textmachine/backend/internal/obs/logging.go

109 lines
3.5 KiB
Go

package obs
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). Writes to stderr with UTC timestamps.
func NewLogger() *slog.Logger {
opts := &slog.HandlerOptions{
Level: parseLogLevel(os.Getenv("LOG_LEVEL")),
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(os.Getenv("LOG_FORMAT")), "json") {
h = slog.NewJSONHandler(os.Stderr, opts)
} else {
h = slog.NewTextHandler(os.Stderr, opts)
}
return slog.New(contextHandler{h})
}
// contextHandler wraps a slog.Handler so a record logged with one of the
// *Context methods automatically gets the call's trace_id AND the translation
// axis (book/chapter/chunk/stage/role) attached — the userver-style trail, set
// once at the top of a unit of work and carried through to the model call.
// Records logged without a traced context simply carry none of these.
type contextHandler struct{ slog.Handler }
func (h contextHandler) Handle(ctx context.Context, r slog.Record) error {
if ri, ok := ReqInfoFromContext(ctx); ok {
if ri.TraceID != "" {
r.AddAttrs(slog.String("trace_id", ri.TraceID))
}
if ri.Book != "" {
r.AddAttrs(slog.String("book", ri.Book), slog.Int("chapter", ri.Chapter), slog.Int("chunk", ri.Chunk))
}
if ri.Stage != "" {
r.AddAttrs(slog.String("stage", ri.Stage), slog.String("role", ri.Role))
}
}
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 (типовая ошибка обёрток, поймана ещё в vojo).
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 when the call's context opted in (ReqInfo.LogBodies) —
// message content never enters the logs unless an operator explicitly enables
// it AND runs at LOG_LEVEL=debug. Only the BODIES are logged — never the URL
// or any header — so the API key cannot leak. Bodies are truncated.
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.LogBodies {
return
}
log.DebugContext(ctx, "llm exchange",
"provider", provider,
"status", status,
"request", truncateForLog(reqBody, llmBodyLogMax),
"response", truncateForLog(respBody, llmBodyLogMax),
)
}
// llmBodyLogMax caps each logged model body: keeps a typical prompt/answer
// readable while staying bounded. A constant, not a knob — it only bounds log
// volume on an opt-in debug path.
const llmBodyLogMax = 4096
func truncateForLog(b []byte, maxBytes int) string {
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
}
}