diff --git a/llmgateway.go b/llmgateway.go index 63f23d2..8c4a859 100644 --- a/llmgateway.go +++ b/llmgateway.go @@ -588,6 +588,9 @@ func newGateway(ctx context.Context, next http.Handler, config *Config, name str if err != nil { return nil, err } + // Routes the self-resolving conditions (a model id two providers both + // serve) to WARN instead of ERROR — see the registry's warn field. + registry.warn = g.warnf // ctx is passed through unwrapped, not re-bounded to warmFillTimeout here: // warmFill already gives each discovery-enabled provider its own fresh // warmFillTimeout budget per provider (registry.go). Wrapping ctx to a diff --git a/logger.go b/logger.go index 9426105..632ebc0 100644 --- a/logger.go +++ b/logger.go @@ -12,6 +12,19 @@ func (g *Gateway) logf(format string, args ...any) { fmt.Fprintf(os.Stderr, "llmgw[%s] INFO %s\n", g.name, fmt.Sprintf(format, args...)) } +// warnf writes a warning-level log line to stderr. No timestamps — +// Traefik adds its own. Never log key material. +// +// Use this for a condition an operator may want to know about but that +// the gateway resolved by itself, deterministically, with no request +// affected — a model id served by two providers, for instance. Those +// lines were ERROR until 2026-08-22, which put 144 of them in a healthy +// pod's boot log on a cluster with overlapping catalogs and made real +// errors harder to find. Reserve errorf for something actually broken. +func (g *Gateway) warnf(format string, args ...any) { + fmt.Fprintf(os.Stderr, "llmgw[%s] WARN %s\n", g.name, fmt.Sprintf(format, args...)) +} + // errorf writes an error-level log line to stderr. No timestamps — Traefik // adds its own. Never log key material. func (g *Gateway) errorf(format string, args ...any) { diff --git a/logger_test.go b/logger_test.go index ff2434f..9834b1f 100644 --- a/logger_test.go +++ b/logger_test.go @@ -3,6 +3,7 @@ package traefikllmgateway import ( "bytes" "context" + "fmt" "io" "net/http" "net/http/httptest" @@ -180,3 +181,80 @@ func TestLogAuthEvent_Failure_SuppressedCountReported(t *testing.T) { t.Errorf("want the next line to report 2 suppressed events, got %q", out) } } + +// TestWarnf_WritesWarnPrefix pins warnf's own severity token, so the +// level cannot drift back without a test noticing. +func TestWarnf_WritesWarnPrefix(t *testing.T) { + gw := newTestGatewayForLogger(t) + + out := captureStderr(t, func() { + gw.warnf("something resolved itself: %d", 7) + }) + + if !strings.Contains(out, "llmgw[llmgw] WARN something resolved itself: 7") { + t.Errorf("warnf output = %q, want a WARN-prefixed line", out) + } + if strings.Contains(out, "ERROR") { + t.Errorf("warnf must not emit an ERROR line, got %q", out) + } +} + +// TestWarnCollisionOnce_LogsAtWarnNotError is the regression for the +// model-id collision line's severity (2026-08-22). A model id served by +// two configured providers is resolved deterministically by the registry +// and affects no request, so it must not be an ERROR: on a cluster with +// overlapping catalogs it put 144 ERROR lines in a healthy pod's boot +// log, which is exactly the noise that hides a real failure. +func TestWarnCollisionOnce_LogsAtWarnNotError(t *testing.T) { + gw := newTestGatewayForLogger(t) + reg, err := newModelRegistry(map[string]providerAdapter{}, CreateConfig(), gw.errorf) + if err != nil { + t.Fatalf("newModelRegistry: %v", err) + } + reg.warn = gw.warnf + + out := captureStderr(t, func() { + reg.warnCollisionOnce("gpt-4o", "openai", []string{"openai", "openai-audio"}) + }) + + if !strings.Contains(out, "WARN model registry: model id \"gpt-4o\" is provided by multiple providers") { + t.Errorf("collision line = %q, want it emitted at WARN", out) + } + if strings.Contains(out, "ERROR") { + t.Errorf("collision line must not be an ERROR, got %q", out) + } + + // Still logged only once per id, regardless of severity. + second := captureStderr(t, func() { + reg.warnCollisionOnce("gpt-4o", "openai", []string{"openai", "openai-audio"}) + }) + if second != "" { + t.Errorf("second collision for the same id logged again: %q", second) + } +} + +// TestRegistryWarnf_FallsBackToLogWhenWarnNil covers the nil-warn path: +// a registry built without an injected warn (every test call site, and +// any future caller that forgets) must still emit the line through log +// rather than panicking or dropping it silently. +func TestRegistryWarnf_FallsBackToLogWhenWarnNil(t *testing.T) { + var got []string + reg, err := newModelRegistry(map[string]providerAdapter{}, CreateConfig(), func(format string, args ...any) { + got = append(got, fmt.Sprintf(format, args...)) + }) + if err != nil { + t.Fatalf("newModelRegistry: %v", err) + } + if reg.warn != nil { + t.Fatal("newModelRegistry must leave warn nil; it is injected by the caller") + } + + reg.warnCollisionOnce("m1", "p1", []string{"p1", "p2"}) + + if len(got) != 1 { + t.Fatalf("log calls = %d, want 1 (the fallback path), got %v", len(got), got) + } + if !strings.Contains(got[0], `model id "m1" is provided by multiple providers`) { + t.Errorf("fallback line = %q, want the collision message", got[0]) + } +} diff --git a/registry.go b/registry.go index 5d4b5d6..fa0785f 100644 --- a/registry.go +++ b/registry.go @@ -221,6 +221,22 @@ type modelRegistry struct { // finding 3) follows this same rule: m.log("%s", fmt.Sprintf(...)), // never a second variadic argument. log func(string, ...any) + // warn is the warning-level counterpart of log (g.warnf), for a + // condition this registry resolved by itself with no request affected + // — a model id two providers both serve, which resolve settles + // deterministically. It is set by the production caller AFTER + // newModelRegistry returns rather than being a fourth constructor + // parameter, so the 45 existing call sites (almost all tests passing a + // no-op) stay untouched: threading a parameter through all of them + // would bury a log-severity change in unrelated churn. A nil warn + // falls back to log, so a registry built without one keeps its old + // behavior instead of panicking or silently dropping the line. + // + // The same Yaegi CFG restriction the log field documents above applies + // here, for the same reason — it is a struct FIELD of variadic func + // type: call it only as m.warn("%s", fmt.Sprintf(...)), never with two + // or more variadic arguments. + warn func(string, ...any) // aliases is the validated alias->target map from Config.ModelAliases // (spec §5, v0.2), built once by newModelRegistry via // validateModelAliases and never mutated afterward — resolve checks @@ -850,7 +866,20 @@ func (m *modelRegistry) warnCollisionOnce(id, winner string, provs []string) { return } m.warned[id] = true - m.log("%s", fmt.Sprintf("model registry: model id %q is provided by multiple providers %v; %q wins the bare id", id, provs, winner)) + m.warnf(fmt.Sprintf("model registry: model id %q is provided by multiple providers %v; %q wins the bare id", id, provs, winner)) +} + +// warnf writes msg through the warn field, falling back to log when no +// warn was injected (see the warn field's own doc comment). It takes an +// ALREADY-FORMATTED string rather than a format plus arguments, so that +// both call shapes below stay single-variadic-argument — the Yaegi CFG +// restriction that applies to any struct field of variadic func type. +func (m *modelRegistry) warnf(msg string) { + if m.warn != nil { + m.warn("%s", msg) + return + } + m.log("%s", msg) } // modelsJSON returns grp's encoded GET /v1/models response body