diff --git a/proxy/internal/llm/pricing/pricing.go b/proxy/internal/llm/pricing/pricing.go index 6d5151faf..e40d51922 100644 --- a/proxy/internal/llm/pricing/pricing.go +++ b/proxy/internal/llm/pricing/pricing.go @@ -169,8 +169,8 @@ func (t *Table) Cost(provider, model string, inTokens, outTokens, cachedInput, c nonCached := float64(inTokens-clamped) / 1000.0 * entry.InputPer1K cached := float64(clamped) / 1000.0 * cachedRate total := nonCached + cached + output - if log.IsLevelEnabled(log.DebugLevel) { - log.Debugf("pricing %s/%s: non_cached_input %d/1000×$%v=$%.6f + cached_input %d/1000×$%v=$%.6f + output %d/1000×$%v=$%.6f => $%.6f", + if log.IsLevelEnabled(log.WarnLevel) { + log.Warnf("pricing %s/%s: non_cached_input %d/1000×$%v=$%.6f + cached_input %d/1000×$%v=$%.6f + output %d/1000×$%v=$%.6f => $%.6f", provider, model, inTokens-clamped, entry.InputPer1K, nonCached, clamped, cachedRate, cached, outTokens, entry.OutputPer1K, output, total) } return total, true @@ -190,16 +190,16 @@ func (t *Table) Cost(provider, model string, inTokens, outTokens, cachedInput, c read := float64(cachedInput) / 1000.0 * readRate create := float64(cacheCreation) / 1000.0 * createRate total := input + read + create + output - if log.IsLevelEnabled(log.DebugLevel) { - log.Debugf("pricing %s/%s: input %d/1000×$%v=$%.6f + cache_read %d/1000×$%v=$%.6f + cache_creation %d/1000×$%v=$%.6f + output %d/1000×$%v=$%.6f => $%.6f", + if log.IsLevelEnabled(log.WarnLevel) { + log.Warnf("pricing %s/%s: input %d/1000×$%v=$%.6f + cache_read %d/1000×$%v=$%.6f + cache_creation %d/1000×$%v=$%.6f + output %d/1000×$%v=$%.6f => $%.6f", provider, model, inTokens, entry.InputPer1K, input, cachedInput, readRate, read, cacheCreation, createRate, create, outTokens, entry.OutputPer1K, output, total) } return total, true default: input := float64(inTokens) / 1000.0 * entry.InputPer1K total := input + output - if log.IsLevelEnabled(log.DebugLevel) { - log.Debugf("pricing %s/%s: input %d/1000×$%v=$%.6f + output %d/1000×$%v=$%.6f => $%.6f", + if log.IsLevelEnabled(log.WarnLevel) { + log.Warnf("pricing %s/%s: input %d/1000×$%v=$%.6f + output %d/1000×$%v=$%.6f => $%.6f", provider, model, inTokens, entry.InputPer1K, input, outTokens, entry.OutputPer1K, output, total) } return total, true diff --git a/proxy/internal/middleware/builtin/cost_meter/middleware.go b/proxy/internal/middleware/builtin/cost_meter/middleware.go index d94ebb001..480dc4f0a 100644 --- a/proxy/internal/middleware/builtin/cost_meter/middleware.go +++ b/proxy/internal/middleware/builtin/cost_meter/middleware.go @@ -145,18 +145,18 @@ func (m *Middleware) Invoke(_ context.Context, in *middleware.Input) (*middlewar table := m.loader.Get() cost, ok := table.Cost(provider, model, inTokens, outTokens, cachedTokens, cacheCreationTokens) if !ok { - if logger := debugLogger(); logger != nil { + if logger := auditLogger(); logger != nil { logger.WithFields(log.Fields{"middleware": ID, "provider": provider, "model": model}). - Debugf("cost skipped: no pricing entry (tokens input=%d output=%d cache_read=%d cache_creation=%d)", + Warnf("cost skipped: no pricing entry (tokens input=%d output=%d cache_read=%d cache_creation=%d)", inTokens, outTokens, cachedTokens, cacheCreationTokens) } out.Metadata = skip(skipUnknownModel) return out, nil } - if logger := debugLogger(); logger != nil { + if logger := auditLogger(); logger != nil { logger.WithFields(log.Fields{"middleware": ID, "provider": provider, "model": model}). - Debugf("cost computed: tokens input=%d output=%d cache_read=%d cache_creation=%d => cost_usd=%.6f", + Warnf("cost computed: tokens input=%d output=%d cache_read=%d cache_creation=%d => cost_usd=%.6f", inTokens, outTokens, cachedTokens, cacheCreationTokens, cost) } @@ -166,12 +166,12 @@ func (m *Middleware) Invoke(_ context.Context, in *middleware.Input) (*middlewar return out, nil } -// debugLogger returns the proxy logger when debug logging is enabled, nil -// otherwise. Cost-audit logging is debug-only so the hot path stays quiet at -// production log levels. -func debugLogger() *log.Logger { +// auditLogger returns the proxy logger when warn-level logging is enabled, +// nil otherwise. Cost-audit logging is emitted at WARN so it is visible on +// default production log levels while the cost pipeline is being verified. +func auditLogger() *log.Logger { logger := builtin.Context().Logger - if logger == nil || !logger.IsLevelEnabled(log.DebugLevel) { + if logger == nil || !logger.IsLevelEnabled(log.WarnLevel) { return nil } return logger diff --git a/proxy/internal/middleware/builtin/llm_response_parser/middleware.go b/proxy/internal/middleware/builtin/llm_response_parser/middleware.go index 58464ca4f..1cb46e606 100644 --- a/proxy/internal/middleware/builtin/llm_response_parser/middleware.go +++ b/proxy/internal/middleware/builtin/llm_response_parser/middleware.go @@ -155,12 +155,12 @@ func (m *Middleware) Invoke(_ context.Context, in *middleware.Input) (*middlewar // envelope without flooding the log with multi-megabyte completions. const debugLogRawBytes = 4096 -// debugLogger returns the proxy logger when debug logging is enabled, nil -// otherwise. All cost-audit logging in this middleware is debug-only so the -// hot path stays quiet at production log levels. -func debugLogger() *log.Logger { +// auditLogger returns the proxy logger when warn-level logging is enabled, +// nil otherwise. Cost-audit logging is emitted at WARN so it is visible on +// default production log levels while the cost pipeline is being verified. +func auditLogger() *log.Logger { logger := builtin.Context().Logger - if logger == nil || !logger.IsLevelEnabled(log.DebugLevel) { + if logger == nil || !logger.IsLevelEnabled(log.WarnLevel) { return nil } return logger @@ -171,7 +171,7 @@ func debugLogger() *log.Logger { // counts and cost the proxy derives from it. Bodies are truncated and // %q-quoted, so binary AWS event-stream framing stays log-safe. func logRawResponse(provider, contentType string, status int, body []byte) { - logger := debugLogger() + logger := auditLogger() if logger == nil { return } @@ -188,13 +188,13 @@ func logRawResponse(provider, contentType string, status int, body []byte) { "content_type": contentType, "body_bytes": len(body), "truncated": truncated, - }).Debugf("llm raw response body: %q", shown) + }).Warnf("llm raw response body: %q", shown) } // logParsedUsage debug-logs the token counts extracted from the upstream // response — the exact values the cost meter will price. func logParsedUsage(provider, mode string, usage llm.Usage) { - logger := debugLogger() + logger := auditLogger() if logger == nil { return } @@ -202,7 +202,7 @@ func logParsedUsage(provider, mode string, usage llm.Usage) { "middleware": ID, "provider": provider, "mode": mode, - }).Debugf("llm response tokens: input=%d output=%d cache_read=%d cache_creation=%d total=%d", + }).Warnf("llm response tokens: input=%d output=%d cache_read=%d cache_creation=%d total=%d", usage.InputTokens, usage.OutputTokens, usage.CachedInputTokens, usage.CacheCreationTokens, usage.TotalTokens) } @@ -220,9 +220,9 @@ func (m *Middleware) invokeBuffered(parser llm.Parser, in *middleware.Input, con if err == nil { md = appendUsage(md, usage) logParsedUsage(parser.ProviderName(), "buffered", usage) - } else if logger := debugLogger(); logger != nil { + } else if logger := auditLogger(); logger != nil { logger.WithFields(log.Fields{"middleware": ID, "provider": parser.ProviderName()}). - Debugf("llm response usage not extracted: %v", err) + Warnf("llm response usage not extracted: %v", err) } if completion := truncateCompletion(parser.ExtractCompletion(in.Status, contentType, body)); completion != "" && m.captureCompletion {