115 lines
4.3 KiB
Go
115 lines
4.3 KiB
Go
package main
|
|
|
|
import (
|
|
"context"
|
|
"log/slog"
|
|
"os"
|
|
"strings"
|
|
)
|
|
|
|
// newLogger builds the process logger from the environment: LOG_LEVEL
|
|
// (debug|info|warn|error, default info) and LOG_FORMAT (text|json, default
|
|
// text). It writes to stderr with UTC timestamps (matching the previous
|
|
// log.LUTC behaviour). Built from getenv directly — not Config — so it exists
|
|
// before LoadConfig (the generate-registration path logs before config loads).
|
|
func newLogger() *slog.Logger {
|
|
opts := &slog.HandlerOptions{
|
|
Level: parseLogLevel(getenv("LOG_LEVEL", "info")),
|
|
ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr {
|
|
if a.Key == slog.TimeKey && a.Value.Kind() == slog.KindTime {
|
|
a.Value = slog.TimeValue(a.Value.Time().UTC())
|
|
}
|
|
return a
|
|
},
|
|
}
|
|
var h slog.Handler
|
|
if strings.EqualFold(strings.TrimSpace(getenv("LOG_FORMAT", "text")), "json") {
|
|
h = slog.NewJSONHandler(os.Stderr, opts)
|
|
} else {
|
|
h = slog.NewTextHandler(os.Stderr, opts)
|
|
}
|
|
// Wrap so every record logged with a *Context method carries the request trace_id.
|
|
return slog.New(contextHandler{h})
|
|
}
|
|
|
|
// contextHandler wraps a slog.Handler so a record logged with one of the *Context methods
|
|
// (InfoContext/DebugContext/WarnContext/ErrorContext) automatically gets the request's
|
|
// trace_id attached — the userver-style trail, set once at the top of a request and
|
|
// carried through to the model call. Records logged without a traced context (startup,
|
|
// the appservice transaction handler) simply carry no trace_id. The field is named
|
|
// trace_id (the OTel convention) so it maps cleanly into OpenSearch and a future OTel
|
|
// exporter.
|
|
type contextHandler struct{ slog.Handler }
|
|
|
|
func (h contextHandler) Handle(ctx context.Context, r slog.Record) error {
|
|
if id := traceFromContext(ctx); id != "" {
|
|
r.AddAttrs(slog.String("trace_id", id))
|
|
}
|
|
return h.Handler.Handle(ctx, r)
|
|
}
|
|
|
|
// WithAttrs/WithGroup must re-wrap, or the embedded handler's versions would return a
|
|
// bare handler and silently drop the trace_id injection for any child logger.
|
|
func (h contextHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
|
|
return contextHandler{h.Handler.WithAttrs(attrs)}
|
|
}
|
|
|
|
func (h contextHandler) WithGroup(name string) slog.Handler {
|
|
return contextHandler{h.Handler.WithGroup(name)}
|
|
}
|
|
|
|
// logLLMExchange logs the raw request/response bodies of one model call at DEBUG, but
|
|
// ONLY for senders on the LOG_BODIES_USERS allowlist (the per-request `verbose` flag
|
|
// stamped into ctx at admission). Everyone else gets routing + metadata logs only, so
|
|
// message content never enters the logs unless an operator opts a specific user in AND
|
|
// runs at LOG_LEVEL=debug (DebugContext is suppressed otherwise). Only the request and
|
|
// response BODIES are logged — never the URL or any header — so the API key cannot leak
|
|
// whether it rides in the Authorization header (xAI / Gemini-compat) or the URL query
|
|
// string (Gemini native grounding). Bodies are truncated to llmBodyLogMax bytes, and the
|
|
// auto-injected trace_id ties the exchange to the rest of the request's lines.
|
|
func logLLMExchange(ctx context.Context, log *slog.Logger, provider string, reqBody []byte, status int, respBody []byte) {
|
|
if log == nil {
|
|
return
|
|
}
|
|
ri, ok := reqInfoFromContext(ctx)
|
|
if !ok || !ri.verbose {
|
|
return
|
|
}
|
|
log.DebugContext(ctx, "llm exchange",
|
|
"provider", provider,
|
|
"sender", ri.sender,
|
|
"status", status,
|
|
"request", truncateForLog(reqBody, llmBodyLogMax),
|
|
"response", truncateForLog(respBody, llmBodyLogMax),
|
|
)
|
|
}
|
|
|
|
// llmBodyLogMax caps each logged model body. A fixed constant, not an env knob — the cap
|
|
// only bounds log volume on an opt-in debug path and never needs per-deploy tuning. ~4 KB
|
|
// keeps a typical prompt/answer readable while staying bounded.
|
|
const llmBodyLogMax = 4096
|
|
|
|
// truncateForLog renders a body for a log line, capped at maxBytes (≤0 → a 2000-byte
|
|
// default) with an ellipsis marker so a truncated payload is visibly truncated.
|
|
func truncateForLog(b []byte, maxBytes int) string {
|
|
if maxBytes <= 0 {
|
|
maxBytes = 2000
|
|
}
|
|
if len(b) > maxBytes {
|
|
return string(b[:maxBytes]) + "…(truncated)"
|
|
}
|
|
return string(b)
|
|
}
|
|
|
|
func parseLogLevel(s string) slog.Level {
|
|
switch strings.ToLower(strings.TrimSpace(s)) {
|
|
case "debug":
|
|
return slog.LevelDebug
|
|
case "warn", "warning":
|
|
return slog.LevelWarn
|
|
case "error":
|
|
return slog.LevelError
|
|
default:
|
|
return slog.LevelInfo
|
|
}
|
|
}
|