[proxy] emit cost-audit logs at warn level

Raise the cost-calculation audit trail (raw response body, parsed token
counts, per-bucket pricing math, final metered cost) from debug to warn so
it is visible on default production log levels while the cost pipeline is
being verified in the field.
This commit is contained in:
Maycon Santos
2026-07-24 05:01:43 +00:00
parent 154084276d
commit 8480429e42
3 changed files with 26 additions and 26 deletions

View File

@@ -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

View File

@@ -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

View File

@@ -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 {