From 0346c3ed39050236d48bfd77bfc62b2458f8eb83 Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Sat, 22 Aug 2026 16:04:51 +0100 Subject: [PATCH] fix(registry): log model-id collisions at WARN, not ERROR MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A model id served by two configured providers is resolved deterministically by the registry, the winner is named in the message, and no request is affected. Logging it at ERROR put 144 ERROR lines in a healthy pod's boot log on a cluster with overlapping openai, openai-audio, copilot and macstudio catalogs, which is exactly the noise that hides a real failure. Adds Gateway.warnf beside logf and errorf, and a warn field on modelRegistry carrying it. The field is set by the production caller after newModelRegistry returns rather than added as a fourth constructor parameter: 45 call sites pass a logger today, almost all of them tests passing a no-op, and threading a parameter through all of them would bury a one-line severity change in unrelated churn. A nil warn falls back to log, so a registry built without one keeps its current behaviour instead of panicking or dropping the line. registry.warnf takes an already-formatted string so both call shapes stay single-variadic-argument. Yaegi v0.16.1's CFG builder panics on a call to a struct FIELD of variadic func type with two or more variadic arguments, which is the restriction the log field beside it already documents. Verified under the real interpreter, not only compiled: yaegi-check drives a genuine two-provider collision and now prints WARN. The severity test fails if the call site reverts to log, so the level cannot drift back unnoticed. Only this message moves. Genuine failures — discovery errors, metadata capture panics, encoding failures — stay at ERROR. --- llmgateway.go | 3 ++ logger.go | 13 +++++++++ logger_test.go | 78 ++++++++++++++++++++++++++++++++++++++++++++++++++ registry.go | 31 +++++++++++++++++++- 4 files changed, 124 insertions(+), 1 deletion(-) 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