132 lines
4.8 KiB
Go
132 lines
4.8 KiB
Go
package obs
|
|
|
|
import (
|
|
"context"
|
|
"fmt"
|
|
"log/slog"
|
|
"os"
|
|
"strings"
|
|
"unicode/utf8"
|
|
)
|
|
|
|
// 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 (a classic wrapper mistake, caught back in 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.
|
|
//
|
|
// The cap is in BYTES, and a Cyrillic answer spends two of them per character, so 4096 was ~2000
|
|
// characters — less than one chunk. That mattered more than log volume: the 25.07 mini-run turned this
|
|
// channel on precisely to read the banknote block, which a model emits at the very END of its answer,
|
|
// and the tail was exactly what the cap removed (the block had to be recovered from the store instead).
|
|
// Raised, and — more importantly — the truncation now keeps BOTH ends (see truncateForLog).
|
|
const llmBodyLogMax = 32768
|
|
|
|
// truncateForLog bounds a logged body while keeping BOTH of its ends. A tail-only cut is the wrong
|
|
// shape for this data: the interesting parts of a model exchange sit at the extremes — the instruction
|
|
// head and, for structured channels like the banknote, the block the model appends LAST. Cutting the
|
|
// middle keeps a cut body diagnosable instead of merely short, and the elision says how much went.
|
|
func truncateForLog(b []byte, maxBytes int) string {
|
|
if len(b) <= maxBytes {
|
|
return string(b)
|
|
}
|
|
// Split the budget between head and tail; the marker names the dropped size so a reader can tell a
|
|
// truncated body from a short one. Cuts land on rune boundaries so the log stays valid UTF-8.
|
|
head := maxBytes / 2
|
|
tail := maxBytes - head
|
|
for head > 0 && !utf8.RuneStart(b[head]) {
|
|
head--
|
|
}
|
|
cut := len(b) - tail
|
|
for cut < len(b) && !utf8.RuneStart(b[cut]) {
|
|
cut++
|
|
}
|
|
return string(b[:head]) + fmt.Sprintf("…(truncated %d bytes)…", cut-head) + string(b[cut:])
|
|
}
|
|
|
|
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
|
|
}
|
|
}
|