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..a8c725798 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,49 @@ 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 := 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 +} 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 (