From a1da825265cdd5edb041e1b9b09ebe777b8ef1f1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ignacio=20L=C3=B3pez=20Luna?= Date: Thu, 2 Apr 2026 13:55:00 +0200 Subject: [PATCH 1/2] feat: enable /logs API endpoint in standalone (Docker CE) mode When MODEL_RUNNER_LOG_DIR is not set, auto-create a default log directory (/tmp/model-runner-logs) and set up tee logging so that all output goes to both stderr (for docker logs) and bracket- timestamped log files (for the /logs API endpoint). Changes: - Add BracketWriter to pkg/logging that prefixes each line with [timestamp] in the format expected by MergeLogs - Auto-create log directory and open service + engine log files - Use io.MultiWriter to tee slog output to stderr and log files - Configure ServerLogFactory for engine backend logs - Always enable /logs endpoint when a log directory is available - Fix comments that incorrectly stated Docker Desktop uses MODEL_RUNNER_LOG_DIR (it uses its own log infrastructure) --- main.go | 66 ++++++++++++++- pkg/envconfig/envconfig.go | 5 +- pkg/logging/bracket_writer_test.go | 127 +++++++++++++++++++++++++++++ pkg/logging/logging.go | 48 +++++++++++ pkg/logging/testmain_test.go | 12 +++ pkg/logs/merge.go | 2 +- 6 files changed, 254 insertions(+), 6 deletions(-) create mode 100644 pkg/logging/bracket_writer_test.go create mode 100644 pkg/logging/testmain_test.go diff --git a/main.go b/main.go index f54dc88f7..b7c213668 100644 --- a/main.go +++ b/main.go @@ -5,6 +5,7 @@ import ( "crypto/tls" "encoding/json" "fmt" + "io" "log/slog" "net" "net/http" @@ -93,6 +94,54 @@ func main() { log.Info("VLLM_METAL_SERVER_PATH", "path", vllmMetalServerPath) } + // Determine log directory. When MODEL_RUNNER_LOG_DIR is set, + // use it. Otherwise auto-create a default directory so that the + // /logs API endpoint is available in all deployment modes. + logDir := envconfig.LogDir() + if logDir == "" { + logDir = filepath.Join(os.TempDir(), "model-runner-logs") + if mkdirErr := os.MkdirAll(logDir, 0o755); mkdirErr != nil { + log.Warn("failed to create default log directory, /logs endpoint will be disabled", + "dir", logDir, "error", mkdirErr) + logDir = "" + } + } + + // When a log directory is available, set up file-backed logging + // using tee writers (stderr + bracket-timestamped files) so that + // both `docker logs` and the /logs API work. + var engineLogFile *os.File + if logDir != "" { + serviceLogFile, openErr := os.OpenFile( + filepath.Join(logDir, dmrlogs.ServiceLogName), + os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o644, + ) + if openErr != nil { + log.Warn("failed to open service log file, /logs endpoint will be disabled", "error", openErr) + logDir = "" + } else { + defer serviceLogFile.Close() + bracketW := logging.NewBracketWriter(serviceLogFile) + log = slog.New(slog.NewTextHandler( + io.MultiWriter(os.Stderr, bracketW), + &slog.HandlerOptions{Level: envconfig.LogLevel()}, + )) + } + + if logDir != "" { + var openErr error + engineLogFile, openErr = os.OpenFile( + filepath.Join(logDir, dmrlogs.EngineLogName), + os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o644, + ) + if openErr != nil { + log.Warn("failed to open engine log file", "error", openErr) + } else { + defer engineLogFile.Close() + } + } + } + // Create llama.cpp configuration from environment variables llamaCppConfig, err := createLlamaCppConfigFromEnv() if err != nil { @@ -117,7 +166,17 @@ func main() { }, Backends: append( routing.DefaultBackendDefs(routing.BackendsConfig{ - Log: log, + Log: log, + ServerLogFactory: func(_ string) logging.Logger { + if engineLogFile == nil { + return log + } + bracketW := logging.NewBracketWriter(engineLogFile) + return slog.New(slog.NewTextHandler( + io.MultiWriter(os.Stderr, bracketW), + &slog.HandlerOptions{Level: envconfig.LogLevel()}, + )) + }, LlamaCppVendoredPath: llamaServerPath, LlamaCppUpdatedPath: updatedServerPath, LlamaCppConfig: llamaCppConfig, @@ -166,8 +225,9 @@ func main() { } }) - // Logs endpoint (Docker Desktop mode only). - if logDir := envconfig.LogDir(); logDir != "" { + // Logs endpoint — available in both Docker Desktop and + // standalone (Docker CE) modes when a log directory exists. + if logDir != "" { r.HandleFunc( "GET /logs", dmrlogs.NewHTTPHandler(logDir), diff --git a/pkg/envconfig/envconfig.go b/pkg/envconfig/envconfig.go index aaf4ed4a6..8be6bbd4d 100644 --- a/pkg/envconfig/envconfig.go +++ b/pkg/envconfig/envconfig.go @@ -160,8 +160,9 @@ func VLLMMetalServerPath() string { } // LogDir returns the directory containing DMR log files. -// Configured via MODEL_RUNNER_LOG_DIR; set by Docker Desktop when -// it manages DMR. When empty, the /logs API endpoint is disabled. +// Configured via MODEL_RUNNER_LOG_DIR. When empty, the server +// auto-creates a default log directory so that the /logs API +// endpoint is available in all deployment modes. func LogDir() string { return Var("MODEL_RUNNER_LOG_DIR") } diff --git a/pkg/logging/bracket_writer_test.go b/pkg/logging/bracket_writer_test.go new file mode 100644 index 000000000..a37ce4fd7 --- /dev/null +++ b/pkg/logging/bracket_writer_test.go @@ -0,0 +1,127 @@ +package logging + +import ( + "bytes" + "regexp" + "strings" + "testing" +) + +// timestampRe matches the bracket-timestamp prefix produced by BracketWriter. +var timestampRe = regexp.MustCompile( + `^\[(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z)\] (.*)$`, +) + +func TestBracketWriter_SingleLine(t *testing.T) { + var buf bytes.Buffer + bw := NewBracketWriter(&buf) + + n, err := bw.Write([]byte("hello world\n")) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if n != len("hello world\n") { + t.Fatalf("expected n=%d, got %d", len("hello world\n"), n) + } + + output := buf.String() + matches := timestampRe.FindStringSubmatch(strings.TrimRight(output, "\n")) + if len(matches) != 3 { + t.Fatalf("output did not match expected format: %q", output) + } + if matches[2] != "hello world" { + t.Errorf("expected message %q, got %q", "hello world", matches[2]) + } +} + +func TestBracketWriter_MultipleLines(t *testing.T) { + var buf bytes.Buffer + bw := NewBracketWriter(&buf) + + input := "line one\nline two\nline three\n" + n, err := bw.Write([]byte(input)) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if n != len(input) { + t.Fatalf("expected n=%d, got %d", len(input), n) + } + + lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n") + if len(lines) != 3 { + t.Fatalf("expected 3 lines, got %d: %v", len(lines), lines) + } + + expected := []string{"line one", "line two", "line three"} + for i, line := range lines { + matches := timestampRe.FindStringSubmatch(line) + if len(matches) != 3 { + t.Errorf("line %d did not match format: %q", i, line) + continue + } + if matches[2] != expected[i] { + t.Errorf("line %d: expected %q, got %q", i, expected[i], matches[2]) + } + } +} + +func TestBracketWriter_PartialWrites(t *testing.T) { + var buf bytes.Buffer + bw := NewBracketWriter(&buf) + + // Write partial line (no newline yet). + _, err := bw.Write([]byte("partial")) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if buf.Len() != 0 { + t.Fatalf("expected no output for partial line, got %q", buf.String()) + } + + // Complete the line. + _, err = bw.Write([]byte(" line\n")) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + + matches := timestampRe.FindStringSubmatch(strings.TrimRight(buf.String(), "\n")) + if len(matches) != 3 { + t.Fatalf("output did not match format: %q", buf.String()) + } + if matches[2] != "partial line" { + t.Errorf("expected %q, got %q", "partial line", matches[2]) + } +} + +func TestBracketWriter_EmptyLine(t *testing.T) { + var buf bytes.Buffer + bw := NewBracketWriter(&buf) + + _, err := bw.Write([]byte("\n")) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + + output := strings.TrimRight(buf.String(), "\n") + matches := timestampRe.FindStringSubmatch(output) + if len(matches) != 3 { + t.Fatalf("output did not match format: %q", buf.String()) + } + if matches[2] != "" { + t.Errorf("expected empty message, got %q", matches[2]) + } +} + +func TestBracketWriter_NoTrailingNewline(t *testing.T) { + var buf bytes.Buffer + bw := NewBracketWriter(&buf) + + // Write without trailing newline — should buffer without output. + _, err := bw.Write([]byte("no newline")) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if buf.Len() != 0 { + t.Fatalf("expected no output without newline, got %q", buf.String()) + } +} diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go index 399628ec6..8f0805395 100644 --- a/pkg/logging/logging.go +++ b/pkg/logging/logging.go @@ -2,11 +2,15 @@ package logging import ( "bufio" + "bytes" "context" + "fmt" "io" "log/slog" "os" "strings" + "sync" + "time" ) // Logger is the application logger type, backed by slog. @@ -76,3 +80,47 @@ func (sw *slogWriter) Close() error { <-sw.done return err } + +// BracketWriter wraps an io.Writer and prefixes each complete line +// with a [timestamp] in the format expected by the logs.MergeLogs +// function. Partial writes are buffered until a newline is received. +// +// This is used to write log files in the same format that Docker +// Desktop produces, so the /logs API endpoint can serve and +// merge-sort them correctly. +type BracketWriter struct { + w io.Writer + mu sync.Mutex + buf []byte +} + +// NewBracketWriter creates a new BracketWriter that wraps w. +func NewBracketWriter(w io.Writer) *BracketWriter { + return &BracketWriter{w: w} +} + +// Write implements io.Writer. It buffers partial input and writes +// each complete line to the underlying writer with a [timestamp] +// prefix. +func (bw *BracketWriter) Write(p []byte) (int, error) { + bw.mu.Lock() + defer bw.mu.Unlock() + + n := len(p) + bw.buf = append(bw.buf, p...) + + for { + idx := bytes.IndexByte(bw.buf, '\n') + if idx < 0 { + break + } + line := string(bw.buf[:idx]) + bw.buf = append(bw.buf[:0], bw.buf[idx+1:]...) + + ts := time.Now().UTC().Format("2006-01-02T15:04:05.000000000Z") + if _, err := fmt.Fprintf(bw.w, "[%s] %s\n", ts, line); err != nil { + return n, err + } + } + return n, nil +} diff --git a/pkg/logging/testmain_test.go b/pkg/logging/testmain_test.go new file mode 100644 index 000000000..24648b655 --- /dev/null +++ b/pkg/logging/testmain_test.go @@ -0,0 +1,12 @@ +package logging + +import ( + "testing" + + "go.uber.org/goleak" +) + +// TestMain runs goleak after the test suite to detect goroutine leaks. +func TestMain(m *testing.M) { + goleak.VerifyTestMain(m) +} diff --git a/pkg/logs/merge.go b/pkg/logs/merge.go index 3963a7541..fd4f54d2c 100644 --- a/pkg/logs/merge.go +++ b/pkg/logs/merge.go @@ -1,6 +1,6 @@ // Package logs provides shared log file reading, merging, and // following utilities for the Docker Model Runner service log and -// engine log files created by Docker Desktop. +// engine log files. package logs import ( From 0bc7b22af1024ff9fc03279c9d774fd7e286ce21 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ignacio=20L=C3=B3pez=20Luna?= Date: Thu, 2 Apr 2026 14:10:53 +0200 Subject: [PATCH 2/2] fix: prevent data loss in BracketWriter on write errors Move buffer advancement after the successful write to the underlying writer. Previously, the line was removed from the buffer before the write, so a failed write (e.g., full disk) would lose the log entry. Also avoids an unnecessary string allocation by passing the byte slice directly to fmt.Fprintf. --- pkg/logging/logging.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go index 8f0805395..a8c725798 100644 --- a/pkg/logging/logging.go +++ b/pkg/logging/logging.go @@ -114,13 +114,15 @@ func (bw *BracketWriter) Write(p []byte) (int, error) { if idx < 0 { break } - line := string(bw.buf[:idx]) - bw.buf = append(bw.buf[:0], bw.buf[idx+1:]...) + line := bw.buf[:idx] ts := time.Now().UTC().Format("2006-01-02T15:04:05.000000000Z") if _, err := fmt.Fprintf(bw.w, "[%s] %s\n", ts, line); err != nil { return n, err } + // Advance the buffer only after a successful write to + // avoid losing the line on transient I/O errors. + bw.buf = append(bw.buf[:0], bw.buf[idx+1:]...) } return n, nil }