diff --git a/CHANGELOG.md b/CHANGELOG.md index 2c4aaa7..69209ab 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,7 @@ Entries before v0.4.0 were reconstructed from git history. - The resolved upstream and where it came from (flag, `LK_UPSTREAM`, or default) are logged at startup. Nothing previously reported the upstream, so a misconfiguration gave no signal at all. - The `/health` 503 body names the upstream it could not reach. +- One access line per request, tagged with the client protocol (`[openai]`, `[gemini]`, `[anthropic]`) and logging method, path, status, and latency. Headers and bodies are never logged, and successful `/health` probes are skipped. Set `LK_LOG=off` to silence it. ### Fixed diff --git a/README.md b/README.md index da07b61..9469f4a 100644 --- a/README.md +++ b/README.md @@ -186,6 +186,19 @@ services: | `LK_MLOCK` | 0 (off) | Lock model in RAM (`1` to enable) | +## Logging + +localaik logs one line per request: method, path, status, and latency. + +``` +localaik [openai] POST /v1/chat/completions 200 412.183ms +localaik [gemini] POST /v1beta/models/gemma:generateContent 200 1.204s +localaik [anthropic] POST /v1/messages 502 Bad Gateway 8.41ms +``` + +Set `LK_LOG=off` to silence per-request logging; the startup lines still print. Only `off` disables it, so `LK_LOG=0` and `LK_LOG=false` leave logging on. Headers and request bodies are never logged, so credentials and prompts stay out of the log. Successful `/health` probes are skipped so the log stays focused on real traffic. + + ## Bring your own model server (`:proxy`) If you already run llama.cpp, vLLM, or anything else that speaks the OpenAI diff --git a/cmd/localaik/main.go b/cmd/localaik/main.go index 3f05754..0833121 100644 --- a/cmd/localaik/main.go +++ b/cmd/localaik/main.go @@ -5,6 +5,7 @@ import ( "log" "net/http" "os" + "strings" "time" "github.com/harshaneel/localaik/internal/pdf" @@ -38,6 +39,12 @@ func upstreamRequiredButUnset(source, requireEnv string) bool { return source == "default" && requireEnv != "" } +// requestLoggingEnabled reports whether per-request logging is on. Only "off" +// disables it; every other value, including "0" and "false", leaves it on. +func requestLoggingEnabled(env string) bool { + return !strings.EqualFold(env, "off") +} + func flagWasSet(name string) bool { set := false flag.Visit(func(f *flag.Flag) { @@ -77,9 +84,14 @@ func main() { log.Fatalf("localaik: %v", err) } + var reqLogger *log.Logger + if requestLoggingEnabled(os.Getenv("LK_LOG")) { + reqLogger = log.Default() + } + httpServer := &http.Server{ Addr: ":" + *port, - Handler: handler, + Handler: server.WithRequestLog(handler, reqLogger), ReadHeaderTimeout: 10 * time.Second, } diff --git a/cmd/localaik/main_test.go b/cmd/localaik/main_test.go index a6cc6c0..b4e1fc8 100644 --- a/cmd/localaik/main_test.go +++ b/cmd/localaik/main_test.go @@ -87,6 +87,26 @@ func TestUpstreamRequiredButUnset(t *testing.T) { } } +func TestRequestLoggingEnabled(t *testing.T) { + tests := []struct { + env string + want bool + }{ + {"", true}, + {"off", false}, + {"OFF", false}, + {"Off", false}, + {"on", true}, + {"0", true}, + {"false", true}, + } + for _, tc := range tests { + if got := requestLoggingEnabled(tc.env); got != tc.want { + t.Errorf("requestLoggingEnabled(%q) = %v, want %v", tc.env, got, tc.want) + } + } +} + // The startup warning must be driven by the same predicate the transport uses; // server.ValidUpstreamAuthHeader owns the table of cases. func TestStartupWarningUsesTheServerPredicate(t *testing.T) { diff --git a/internal/server/logging.go b/internal/server/logging.go new file mode 100644 index 0000000..84e5d85 --- /dev/null +++ b/internal/server/logging.go @@ -0,0 +1,109 @@ +package server + +import ( + "log" + "net/http" + "strconv" + "strings" + "time" +) + +// WithRequestLog wraps next so each request is logged as one access line: +// method, path, status and latency. Headers and bodies are never logged, so no +// credential or prompt content can leak through here. A nil logger disables +// logging and returns next unchanged. +func WithRequestLog(next http.Handler, logger *log.Logger) http.Handler { + if logger == nil { + return next + } + return &requestLogger{next: next, logger: logger} +} + +type requestLogger struct { + next http.Handler + logger *log.Logger +} + +func (l *requestLogger) ServeHTTP(w http.ResponseWriter, r *http.Request) { + start := time.Now() + rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} + + // Deferred so a panicking handler still leaves an access line. + defer func() { + dur := time.Since(start).Round(time.Microsecond) + + // Health probes hit this every few seconds, so log them only when failing. + if r.URL.Path == "/health" && rec.status < http.StatusBadRequest { + return + } + + method, path := sanitizeLogField(r.Method), sanitizeLogField(r.URL.Path) + status := strconv.Itoa(rec.status) + if rec.status >= http.StatusBadRequest { + status += " " + http.StatusText(rec.status) + } + tag := "[" + protocolLabel(r.URL.Path) + "]" + l.logger.Printf("localaik %-11s %s %s %s %s", tag, method, path, status, dur) + }() + + l.next.ServeHTTP(rec, r) +} + +// protocolLabel names the client API a request path belongs to, matching the +// routing in ServeHTTP, so the access line shows which of the three protocols +// was used. +func protocolLabel(path string) string { + switch { + case strings.HasPrefix(path, "/v1beta/"): + return "gemini" + case path == "/v1/messages" || strings.HasPrefix(path, "/v1/messages/"): + return "anthropic" + case strings.HasPrefix(path, "/v1/"): + return "openai" + default: + return "-" + } +} + +// sanitizeLogField quotes a value that carries control characters, so a decoded +// request path cannot forge extra log lines or inject terminal escapes. +func sanitizeLogField(s string) string { + for _, c := range s { + if c < 0x20 || c == 0x7f { + return strconv.Quote(s) + } + } + return s +} + +// statusRecorder captures the response status while preserving http.Flusher, so +// streaming responses still flush through the middleware. +type statusRecorder struct { + http.ResponseWriter + status int + wroteHeader bool +} + +// WriteHeader records only the first status, matching net/http, so the logged +// status is the one the client actually received. +func (s *statusRecorder) WriteHeader(code int) { + if s.wroteHeader { + return + } + s.wroteHeader = true + s.status = code + s.ResponseWriter.WriteHeader(code) +} + +// Write locks in the implicit 200, matching net/http, so a later WriteHeader +// cannot make the log disagree with the status the client received. +func (s *statusRecorder) Write(b []byte) (int, error) { + s.wroteHeader = true + return s.ResponseWriter.Write(b) +} + +func (s *statusRecorder) Flush() { + if f, ok := s.ResponseWriter.(http.Flusher); ok { + f.Flush() + } +} diff --git a/internal/server/logging_test.go b/internal/server/logging_test.go new file mode 100644 index 0000000..4b1c6d6 --- /dev/null +++ b/internal/server/logging_test.go @@ -0,0 +1,245 @@ +package server + +import ( + "bytes" + "io" + "log" + "net/http" + "net/http/httptest" + "strings" + "testing" +) + +func newTestLogger() (*log.Logger, *bytes.Buffer) { + var buf bytes.Buffer + return log.New(&buf, "", 0), &buf +} + +func TestWithRequestLogLogsAccessLine(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil)) + + line := buf.String() + for _, want := range []string{"POST", "/v1/chat/completions", "200"} { + if !strings.Contains(line, want) { + t.Fatalf("access line %q missing %q", line, want) + } + } + if strings.TrimSpace(line) == "" { + t.Fatal("expected an access line") + } +} + +func TestWithRequestLogCapturesErrorStatusAndText(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusBadGateway) + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodPost, "/v1/messages", nil)) + + line := buf.String() + if !strings.Contains(line, "502") || !strings.Contains(line, "Bad Gateway") { + t.Fatalf("error line %q missing status or text", line) + } +} + +func TestWithRequestLogDefaultsToStatusOK(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, _ = io.WriteString(w, "body without an explicit WriteHeader") + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/v1/models", nil)) + + if !strings.Contains(buf.String(), "200") { + t.Fatalf("expected status 200 in %q", buf.String()) + } +} + +// The wrapper must stay an http.Flusher, or SSE streaming through the proxy +// would buffer instead of flushing. +func TestWithRequestLogPreservesFlusher(t *testing.T) { + logger, _ := newTestLogger() + flushed := false + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + f, ok := w.(http.Flusher) + if !ok { + t.Fatal("the wrapped writer is not an http.Flusher; streaming would break") + } + _, _ = io.WriteString(w, "data: chunk\n\n") + f.Flush() + flushed = true + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodPost, "/v1beta/models/m:streamGenerateContent", nil)) + + if !flushed { + t.Fatal("handler never reached the flush path") + } + if !rec.Flushed { + t.Fatal("Flush did not reach the underlying ResponseWriter") + } +} + +func TestProtocolLabel(t *testing.T) { + tests := []struct { + path string + want string + }{ + {"/v1/chat/completions", "openai"}, + {"/v1/completions", "openai"}, + {"/v1/models", "openai"}, + {"/v1/models/gemma", "openai"}, + {"/v1/messages", "anthropic"}, + {"/v1/messages/count_tokens", "anthropic"}, + {"/v1beta/models", "gemini"}, + {"/v1beta/models/gemma:generateContent", "gemini"}, + {"/v1beta/models/gemma:streamGenerateContent", "gemini"}, + {"/health", "-"}, + {"/nope", "-"}, + } + for _, tc := range tests { + if got := protocolLabel(tc.path); got != tc.want { + t.Errorf("protocolLabel(%q) = %q, want %q", tc.path, got, tc.want) + } + } +} + +func TestWithRequestLogTagsTheProtocol(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodPost, "/v1/messages", nil)) + + if !strings.Contains(buf.String(), "[anthropic]") { + t.Fatalf("access line missing the protocol tag: %q", buf.String()) + } +} + +func TestWithRequestLogNilLoggerDisables(t *testing.T) { + called := false + next := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { called = true }) + + h := WithRequestLog(next, nil) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/health", nil)) + + if !called { + t.Fatal("nil logger must still pass the request through to next") + } +} + +func TestWithRequestLogSkipsSuccessfulHealthChecks(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/health", nil)) + + if strings.TrimSpace(buf.String()) != "" { + t.Fatalf("a healthy /health probe should not log, got %q", buf.String()) + } +} + +func TestWithRequestLogLogsFailingHealthChecks(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusServiceUnavailable) + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/health", nil)) + + if !strings.Contains(buf.String(), "503") { + t.Fatalf("a failing /health probe should log, got %q", buf.String()) + } +} + +// A decoded path can contain control characters, which must not reach the log +// verbatim or a caller could forge log lines or inject terminal escapes. +func TestWithRequestLogSanitizesControlCharsInPath(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }), logger) + + req := httptest.NewRequest(http.MethodGet, "/", nil) + req.URL.Path = "/evil\nlocalaik GET /forged 500\x1b[31m" + rec := httptest.NewRecorder() + h.ServeHTTP(rec, req) + + out := buf.String() + if strings.Count(out, "\n") != 1 { + t.Fatalf("expected exactly one newline (the log terminator), got %q", out) + } + if strings.ContainsRune(out, 0x1b) { + t.Fatalf("raw escape byte reached the log: %q", out) + } +} + +// net/http honors only the first WriteHeader, so the log must record that one. +func TestWithRequestLogRecordsFirstStatusOnly(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + w.WriteHeader(http.StatusBadGateway) + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodPost, "/v1/messages", nil)) + + if !strings.Contains(buf.String(), "200") || strings.Contains(buf.String(), "502") { + t.Fatalf("expected the first status 200 to be logged, got %q", buf.String()) + } +} + +// A body write is an implicit 200, so a later WriteHeader must not change the +// logged status away from what the client already received. +func TestWithRequestLogImplicitStatusBeatsLaterWriteHeader(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, _ = io.WriteString(w, "partial body") + w.WriteHeader(http.StatusBadGateway) + }), logger) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest(http.MethodPost, "/v1/messages", nil)) + + if !strings.Contains(buf.String(), "200") || strings.Contains(buf.String(), "502") { + t.Fatalf("expected the implicit 200 to be logged, got %q", buf.String()) + } +} + +// Nothing about the request headers, which can carry credentials, may reach the +// access line. +func TestWithRequestLogNeverLogsHeaders(t *testing.T) { + logger, buf := newTestLogger() + h := WithRequestLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }), logger) + + req := httptest.NewRequest(http.MethodPost, "/v1/messages", nil) + req.Header.Set("Authorization", "Bearer super-secret-token") + req.Header.Set("X-Api-Key", "another-secret") + rec := httptest.NewRecorder() + h.ServeHTTP(rec, req) + + if strings.Contains(buf.String(), "super-secret-token") || strings.Contains(buf.String(), "another-secret") { + t.Fatalf("access line leaked a header credential: %q", buf.String()) + } +}