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

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.


Assisted-by: Claude Code:claude-opus-4-8[1m] [Read] [Edit] [Bash]

Signed-off-by: Ettore Di Giacinto <mudler@localai.io>
Co-authored-by: Ettore Di Giacinto <mudler@localai.io>

pkg/model/initializers.go

@@ -219,15 +219,29 @@ func parallelSlotsFromOptions(opts []string) string {
 func (ml *ModelLoader) backendLoader(opts ...Option) (client grpc.Backend, err error) {
 	o := NewOptions(opts...)
 
-	xlog.Info("BackendLoader starting", "modelID", o.modelID, "backend", o.backendString, "model", o.model)
+	// backendLoader is not a synonym for "a model is being loaded": in
+	// distributed mode Load() deliberately bypasses the local cache and calls
+	// it on every inference request so SmartRouter re-picks a replica per
+	// request. Announcing a load unconditionally therefore made ordinary
+	// traffic against a resident model look like a retry storm in the INFO
+	// log. Reserve INFO for a genuine cold load; keep the per-call trace at
+	// DEBUG for anyone actually following the routing path.
+	coldLoad := !ml.isResident(o.modelID)
+
+	if coldLoad {
+		xlog.Info("BackendLoader starting", "modelID", o.modelID, "backend", o.backendString, "model", o.model)
+	} else {
+		xlog.Debug("BackendLoader invoked for an already-resident model", "modelID", o.modelID, "backend", o.backendString, "model", o.model)
+	}
 
 	// Surface the effective performance-relevant runtime options at load (some of
 	// these are auto-tuned for the detected hardware). Logged once per load so an
 	// admin can see what will actually run and pin or override any value in the
 	// model YAML — or set LOCALAI_DISABLE_HARDWARE_DEFAULTS=true to turn the
 	// hardware auto-tuning off entirely. Gated on an LLM-ish load (context set) so
-	// TTS/audio/other backends stay quiet.
-	if opt := o.gRPCOptions; opt != nil && opt.ContextSize > 0 {
+	// TTS/audio/other backends stay quiet, and on a cold load so it stays "once
+	// per load" rather than once per request.
+	if opt := o.gRPCOptions; coldLoad && opt != nil && opt.ContextSize > 0 {
 		xlog.Info("effective runtime tuning (override in the model YAML; LOCALAI_DISABLE_HARDWARE_DEFAULTS=true disables hardware auto-tuning)",
 			"modelID", o.modelID,
 			"context", opt.ContextSize,

pkg/model/initializers_load_logging_test.go

@@ -0,0 +1,102 @@
+package model
+
+import (
+	"bytes"
+	"log/slog"
+
+	pb "github.com/mudler/LocalAI/pkg/grpc/proto"
+	"github.com/mudler/LocalAI/pkg/system"
+	"github.com/mudler/xlog"
+
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+)
+
+// backendLoader is not a synonym for "a model is being loaded". 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, so
+// the function runs at request rate against an already-resident model. Emitting
+// the load banner unconditionally made ordinary embedding traffic (~5 req/s)
+// look like a retry storm in the INFO log and sent an engineer chasing a
+// non-existent hot loop during an unrelated production investigation. INFO must
+// mark a genuine cold load only; the per-call trace belongs at DEBUG.
+var _ = Describe("backendLoader load logging", func() {
+	var (
+		ml       *ModelLoader
+		captured *bytes.Buffer
+	)
+
+	BeforeEach(func() {
+		systemState, err := system.GetSystemState(system.WithModelPath(GinkgoT().TempDir()))
+		Expect(err).ToNot(HaveOccurred())
+		ml = NewModelLoader(systemState)
+
+		// Capture at info level so a debug-level emission is filtered out: the
+		// assertions then fail on severity, not merely on wording.
+		captured = &bytes.Buffer{}
+		handler := slog.NewTextHandler(captured, &slog.HandlerOptions{Level: slog.LevelInfo})
+		xlog.SetLogger(xlog.NewLoggerWithHandler(handler, xlog.LogLevelInfo))
+	})
+
+	AfterEach(func() {
+		// xlog exposes no getter for the package logger, so restore the same
+		// default the suite entrypoint installs rather than the prior value.
+		xlog.SetLogger(xlog.NewLogger(xlog.LogLevel("info"), "text"))
+	})
+
+	Context("when the model is already resident", func() {
+		BeforeEach(func() {
+			resident := NewModel("resident-model", "127.0.0.1:65535", nil)
+			// Skip the gRPC health probe so the resident model survives the
+			// lookup without a live backend behind the address.
+			resident.MarkHealthy()
+			ml.mu.Lock()
+			ml.store.Set("resident-model", resident)
+			ml.mu.Unlock()
+		})
+
+		It("does not announce a load at info level", func() {
+			_, err := ml.backendLoader(
+				WithModelID("resident-model"),
+				WithModel("resident-model"),
+				WithBackendString("llama-cpp"),
+				WithLoadGRPCLoadModelOpts(&pb.ModelOptions{ContextSize: 4096}),
+			)
+			Expect(err).ToNot(HaveOccurred())
+
+			Expect(captured.String()).ToNot(ContainSubstring("BackendLoader starting"),
+				"a request served by an already-resident model must not look like a cold load")
+		})
+
+		It("does not repeat the effective runtime tuning banner at info level", func() {
+			_, err := ml.backendLoader(
+				WithModelID("resident-model"),
+				WithModel("resident-model"),
+				WithBackendString("llama-cpp"),
+				WithLoadGRPCLoadModelOpts(&pb.ModelOptions{ContextSize: 4096}),
+			)
+			Expect(err).ToNot(HaveOccurred())
+
+			Expect(captured.String()).ToNot(ContainSubstring("effective runtime tuning"),
+				"the tuning banner documents what a load will run with, so it belongs to a load")
+		})
+	})
+
+	Context("when the model is not resident", func() {
+		It("still announces the cold load at info level", func() {
+			// The load itself fails (no such backend is installed); what is
+			// pinned here is that the banner is emitted before that, so
+			// suppressing the warm case does not silence real loads.
+			_, err := ml.backendLoader(
+				WithModelID("cold-model"),
+				WithModel("cold-model"),
+				WithBackendString("definitely-not-an-installed-backend"),
+				WithLoadGRPCLoadModelOpts(&pb.ModelOptions{ContextSize: 4096}),
+			)
+			Expect(err).To(HaveOccurred())
+
+			Expect(captured.String()).To(ContainSubstring("BackendLoader starting"))
+			Expect(captured.String()).To(ContainSubstring("effective runtime tuning"))
+		})
+	})
+})

pkg/model/loader.go

@@ -601,6 +601,20 @@ func (ml *ModelLoader) shutdownModel(ctx context.Context, modelName string, forc
 	return ml.deleteProcess(ctx, modelName, force)
 }
 
+// isResident reports whether the model store already holds an entry for
+// modelID. Unlike checkIsLoaded it never probes the backend and never evicts,
+// so it is safe to call on a per-request hot path: it answers "have we been
+// here before?", which is exactly what the load logging needs to distinguish a
+// cold load from routine traffic against a resident model.
+func (ml *ModelLoader) isResident(modelID string) bool {
+	ml.mu.Lock()
+	store := ml.store
+	ml.mu.Unlock()
+
+	_, ok := store.Get(modelID)
+	return ok
+}
+
 func (ml *ModelLoader) CheckIsLoaded(s string) *Model {
 	release := ml.operations.acquire(s, false)
 	defer release()