Skip to content

fix(model): only announce a load at INFO when a load actually happens#11017

Merged
mudler merged 1 commit into
masterfrom
fix/backendloader-log-honesty
Jul 21, 2026
Merged

fix(model): only announce a load at INFO when a load actually happens#11017
mudler merged 1 commit into
masterfrom
fix/backendloader-log-honesty

Conversation

@localai-bot

Copy link
Copy Markdown
Collaborator

The observation

A live distributed LocalAI cluster logged BackendLoader starting for one embedding model roughly 5 times per second, sustained. It looks exactly like a retry storm.

It is not. At the same moment:

  • the model was state=loaded, in_flight=0
  • exactly one backend process existed on the worker node
  • the log lines started 22 seconds after the load had already completed

The traffic was an agent pool issuing ordinary embedding requests against an already-resident model.

Root cause

backendLoader is not only a load path. In distributed mode Load() deliberately bypasses the local cache and calls backendLoader on every inference request, so SmartRouter can re-pick a replica per request:

// pkg/model/initializers.go, Load()
if distributed {
    client, err := ml.backendLoader(opts...)   // every request, by design

That call lands in loadModel's distributed branch, which routes to the existing replica and spawns nothing. But backendLoader's very first statement was an unconditional xlog.Info("BackendLoader starting", ...), so the load banner fired at request rate for a model that was never being loaded.

(In local mode Load() early-returns on CheckIsLoaded before reaching backendLoader, so the local path was never the source of these lines. The distributed per-request call is the real and intended behaviour — the routing is correct, only the logging was dishonest.)

The adjacent effective runtime tuning banner, documented as "Logged once per load", had the same problem for the same reason: it was once per call, not once per load.

The fix

Emit both banners at INFO only when the model is not already resident; keep the per-call trace at DEBUG for anyone following the routing path.

isResident is a plain store lookup — no health probe, no eviction — so it is safe on the per-request hot path, unlike checkIsLoaded, which probes over gRPC and can evict.

An operator reading INFO logs can now tell a genuine cold model load from routine traffic against a resident model.

Why it matters

This log cost real debugging time: it caused an engineer to diagnose a non-existent retry storm during an unrelated production investigation. Same class of defect as #10985, which fixed io.Copy errors being labelled failed to write file when they were read failures — a log line that sends the reader after the wrong thing.

Tests

pkg/model/initializers_load_logging_test.go (Ginkgo/Gomega, internal package). Written first and confirmed red on behaviour:

[FAIL] backendLoader load logging when the model is already resident [It] does not announce a load at info level
[FAIL] backendLoader load logging when the model is already resident [It] does not repeat the effective runtime tuning banner at info level
Ran 140 of 140 Specs -- 138 Passed | 2 Failed

Logs are captured through a slog handler pinned at LevelInfo, so a wrong-severity emission fails the spec rather than passing silently. A third spec pins that a genuine cold load still announces at INFO, so the warm-path suppression cannot silence real loads.

Verification

command exit
go build ./core/... ./pkg/... 0
go test ./pkg/model/ 0 (140 specs)
make lint 0 (0 issues)

Repo grepped (including tests/e2e/) for anything pinning the log text: only a prose comment in core/services/nodes/router.go mentions BackendLoader logs, no assertions.

Scope is limited to load-related logging.

backendLoader logged "BackendLoader starting" at INFO as its very first
statement, unconditionally. That reads as "a model is being loaded", but
backendLoader is not only a load path: in distributed mode Load()
deliberately bypasses the local cache and calls backendLoader on every
inference request so SmartRouter can re-pick a replica per request. The
model is already resident, no process is spawned, and nothing is loaded,
yet the banner fires at request rate.

On a live cluster this produced ~5 "BackendLoader starting" lines per
second for a single embedding model, sustained, starting 22 seconds
after the load had already completed. The model was state=loaded with
in_flight=0 and exactly one backend process on the worker. It looked
exactly like a retry storm and cost real debugging time during an
unrelated production investigation. The adjacent "effective runtime
tuning" banner, documented as "logged once per load", had the same
problem for the same reason.

Emit both banners at INFO only when the model is not already resident,
and keep the per-call trace at DEBUG for anyone following the routing
path. isResident is a plain store lookup with no health probe and no
eviction, so it is safe on the per-request hot path (unlike
checkIsLoaded, which probes and can evict).

Same class of defect as #10985: a log line that sends the reader after
the wrong thing.

Signed-off-by: Ettore Di Giacinto <mudler@localai.io>
Assisted-by: Claude Code:claude-opus-4-8[1m] [Read] [Edit] [Bash]
@mudler
mudler merged commit 54d5c18 into master Jul 21, 2026
21 of 22 checks passed
@mudler
mudler deleted the fix/backendloader-log-honesty branch July 21, 2026 13:33
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants