LocalAI/pkg/model/initializers_load_logging_test.go

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"))
		})
	})
})