diff --git a/go.mod b/go.mod index 514cf8c63..fa171a5d2 100644 --- a/go.mod +++ b/go.mod @@ -17,7 +17,6 @@ require ( github.com/opencontainers/image-spec v1.1.1 github.com/prometheus/client_model v0.6.2 github.com/prometheus/common v0.67.5 - github.com/sirupsen/logrus v1.9.4 github.com/stretchr/testify v1.11.1 golang.org/x/sync v0.19.0 ) @@ -42,6 +41,7 @@ require ( github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/pkg/errors v0.9.1 // indirect github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 // indirect + github.com/sirupsen/logrus v1.9.4 // indirect github.com/smallnest/ringbuffer v0.0.0-20241116012123-461381446e3d // indirect github.com/yusufpapurcu/wmi v1.2.4 // indirect go.opentelemetry.io/auto/sdk v1.2.1 // indirect diff --git a/main.go b/main.go index 40a374890..e98e1944a 100644 --- a/main.go +++ b/main.go @@ -3,6 +3,7 @@ package main import ( "context" "crypto/tls" + "log/slog" "net" "net/http" "os" @@ -24,13 +25,13 @@ import ( "github.com/docker/model-runner/pkg/inference/models" "github.com/docker/model-runner/pkg/inference/platform" "github.com/docker/model-runner/pkg/inference/scheduling" + "github.com/docker/model-runner/pkg/logging" "github.com/docker/model-runner/pkg/metrics" "github.com/docker/model-runner/pkg/middleware" "github.com/docker/model-runner/pkg/ollama" "github.com/docker/model-runner/pkg/responses" "github.com/docker/model-runner/pkg/routing" modeltls "github.com/docker/model-runner/pkg/tls" - "github.com/sirupsen/logrus" ) const ( @@ -38,7 +39,13 @@ const ( DefaultTLSPort = "12444" ) -var log = logrus.New() +// initLogger creates the application logger based on LOG_LEVEL env var. +func initLogger() *slog.Logger { + level := logging.ParseLevel(os.Getenv("LOG_LEVEL")) + return logging.NewLogger(level) +} + +var log = initLogger() // Log is the logger used by the application, exported for testing purposes. var Log = log @@ -46,6 +53,9 @@ var Log = log // testLog is a test-override logger used by createLlamaCppConfigFromEnv. var testLog = log +// exitFunc is the function called for fatal errors. Overridable in tests. +var exitFunc = os.Exit + func main() { ctx, cancel := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) defer cancel() @@ -57,7 +67,8 @@ func main() { userHomeDir, err := os.UserHomeDir() if err != nil { - log.Fatalf("Failed to get user home directory: %v", err) + log.Error("Failed to get user home directory", "error", err) + os.Exit(1) } modelPath := os.Getenv("MODELS_PATH") @@ -101,27 +112,27 @@ func main() { clientConfig := models.ClientConfig{ StoreRootPath: modelPath, - Logger: log.WithFields(logrus.Fields{"component": "model-manager"}), + Logger: log.With("component", "model-manager"), Transport: baseTransport, } - modelManager := models.NewManager(log.WithFields(logrus.Fields{"component": "model-manager"}), clientConfig) + modelManager := models.NewManager(log.With("component", "model-manager"), clientConfig) modelHandler := models.NewHTTPHandler( log, modelManager, nil, ) - log.Infof("LLAMA_SERVER_PATH: %s", llamaServerPath) + log.Info("LLAMA_SERVER_PATH", "path", llamaServerPath) if vllmServerPath != "" { - log.Infof("VLLM_SERVER_PATH: %s", vllmServerPath) + log.Info("VLLM_SERVER_PATH", "path", vllmServerPath) } if sglangServerPath != "" { - log.Infof("SGLANG_SERVER_PATH: %s", sglangServerPath) + log.Info("SGLANG_SERVER_PATH", "path", sglangServerPath) } if mlxServerPath != "" { - log.Infof("MLX_SERVER_PATH: %s", mlxServerPath) + log.Info("MLX_SERVER_PATH", "path", mlxServerPath) } if vllmMetalServerPath != "" { - log.Infof("VLLM_METAL_SERVER_PATH: %s", vllmMetalServerPath) + log.Info("VLLM_METAL_SERVER_PATH", "path", vllmMetalServerPath) } // Create llama.cpp configuration from environment variables @@ -130,7 +141,7 @@ func main() { llamaCppBackend, err := llamacpp.New( log, modelManager, - log.WithFields(logrus.Fields{"component": llamacpp.Name}), + log.With("component", llamacpp.Name), llamaServerPath, func() string { wd, _ := os.Getwd() @@ -141,46 +152,51 @@ func main() { llamaCppConfig, ) if err != nil { - log.Fatalf("unable to initialize %s backend: %v", llamacpp.Name, err) + log.Error("Unable to initialize backend", "backend", llamacpp.Name, "error", err) + os.Exit(1) } vllmBackend, err := initVLLMBackend(log, modelManager, vllmServerPath) if err != nil { - log.Fatalf("unable to initialize %s backend: %v", vllm.Name, err) + log.Error("Unable to initialize backend", "backend", vllm.Name, "error", err) + os.Exit(1) } mlxBackend, err := mlx.New( log, modelManager, - log.WithFields(logrus.Fields{"component": mlx.Name}), + log.With("component", mlx.Name), nil, mlxServerPath, ) if err != nil { - log.Fatalf("unable to initialize %s backend: %v", mlx.Name, err) + log.Error("Unable to initialize backend", "backend", mlx.Name, "error", err) + os.Exit(1) } sglangBackend, err := sglang.New( log, modelManager, - log.WithFields(logrus.Fields{"component": sglang.Name}), + log.With("component", sglang.Name), nil, sglangServerPath, ) if err != nil { - log.Fatalf("unable to initialize %s backend: %v", sglang.Name, err) + log.Error("Unable to initialize backend", "backend", sglang.Name, "error", err) + os.Exit(1) } diffusersBackend, err := diffusers.New( log, modelManager, - log.WithFields(logrus.Fields{"component": diffusers.Name}), + log.With("component", diffusers.Name), nil, diffusersServerPath, ) if err != nil { - log.Fatalf("unable to initialize diffusers backend: %v", err) + log.Error("Unable to initialize backend", "backend", diffusers.Name, "error", err) + os.Exit(1) } var vllmMetalBackend inference.Backend @@ -188,11 +204,11 @@ func main() { vllmMetalBackend, err = vllmmetal.New( log, modelManager, - log.WithFields(logrus.Fields{"component": vllmmetal.Name}), + log.With("component", vllmmetal.Name), vllmMetalServerPath, ) if err != nil { - log.Warnf("Failed to initialize vllm-metal backend: %v", err) + log.Warn("Failed to initialize vllm-metal backend", "error", err) } } @@ -222,7 +238,7 @@ func main() { http.DefaultClient, metrics.NewTracker( http.DefaultClient, - log.WithField("component", "metrics"), + log.With("component", "metrics"), "", false, ), @@ -278,7 +294,7 @@ func main() { // Add metrics endpoint if enabled if os.Getenv("DISABLE_METRICS") != "1" { metricsHandler := metrics.NewAggregatedMetricsHandler( - log.WithField("component", "metrics"), + log.With("component", "metrics"), schedulerHTTP, ) router.Handle("/metrics", metricsHandler) @@ -302,7 +318,7 @@ func main() { if tcpPort != "" { // Use TCP port addr := ":" + tcpPort - log.Infof("Listening on TCP port %s", tcpPort) + log.Info("Listening on TCP port", "port", tcpPort) server.Addr = addr go func() { serverErrors <- server.ListenAndServe() @@ -311,12 +327,14 @@ func main() { // Use Unix socket if err := os.Remove(sockName); err != nil { if !os.IsNotExist(err) { - log.Fatalf("Failed to remove existing socket: %v", err) + log.Error("Failed to remove existing socket", "error", err) + os.Exit(1) } } ln, err := net.ListenUnix("unix", &net.UnixAddr{Name: sockName, Net: "unix"}) if err != nil { - log.Fatalf("Failed to listen on socket: %v", err) + log.Error("Failed to listen on socket", "error", err) + os.Exit(1) } go func() { serverErrors <- server.Serve(ln) @@ -341,19 +359,22 @@ func main() { var err error certPath, keyPath, err = modeltls.EnsureCertificates("", "") if err != nil { - log.Fatalf("Failed to ensure TLS certificates: %v", err) + log.Error("Failed to ensure TLS certificates", "error", err) + os.Exit(1) } - log.Infof("Using TLS certificate: %s", certPath) - log.Infof("Using TLS key: %s", keyPath) + log.Info("Using TLS certificate", "path", certPath) + log.Info("Using TLS key", "path", keyPath) } else { - log.Fatal("TLS enabled but no certificate provided and auto-cert is disabled") + log.Error("TLS enabled but no certificate provided and auto-cert is disabled") + os.Exit(1) } } // Load TLS configuration tlsConfig, err := modeltls.LoadTLSConfig(certPath, keyPath) if err != nil { - log.Fatalf("Failed to load TLS configuration: %v", err) + log.Error("Failed to load TLS configuration", "error", err) + os.Exit(1) } tlsServer = &http.Server{ @@ -363,7 +384,7 @@ func main() { ReadHeaderTimeout: 10 * time.Second, } - log.Infof("Listening on TLS port %s", tlsPort) + log.Info("Listening on TLS port", "port", tlsPort) go func() { // Use ListenAndServeTLS with empty strings since TLSConfig already has the certs ln, err := tls.Listen("tcp", tlsServer.Addr, tlsConfig) @@ -391,30 +412,30 @@ func main() { select { case err := <-serverErrors: if err != nil { - log.Errorf("Server error: %v", err) + log.Error("Server error", "error", err) } case err := <-tlsServerErrorsChan: if err != nil { - log.Errorf("TLS server error: %v", err) + log.Error("TLS server error", "error", err) } case <-ctx.Done(): - log.Infoln("Shutdown signal received") - log.Infoln("Shutting down the server") + log.Info("Shutdown signal received") + log.Info("Shutting down the server") if err := server.Close(); err != nil { - log.Errorf("Server shutdown error: %v", err) + log.Error("Server shutdown error", "error", err) } if tlsServer != nil { - log.Infoln("Shutting down the TLS server") + log.Info("Shutting down the TLS server") if err := tlsServer.Close(); err != nil { - log.Errorf("TLS server shutdown error: %v", err) + log.Error("TLS server shutdown error", "error", err) } } - log.Infoln("Waiting for the scheduler to stop") + log.Info("Waiting for the scheduler to stop") if err := <-schedulerErrors; err != nil { - log.Errorf("Scheduler error: %v", err) + log.Error("Scheduler error", "error", err) } } - log.Infoln("Docker Model Runner stopped") + log.Info("Docker Model Runner stopped") } // createLlamaCppConfigFromEnv creates a LlamaCppConfig from environment variables @@ -435,12 +456,13 @@ func createLlamaCppConfigFromEnv() config.BackendConfig { for _, arg := range args { for _, disallowed := range disallowedArgs { if arg == disallowed { - testLog.Fatalf("LLAMA_ARGS cannot override the %s argument as it is controlled by the model runner", disallowed) + testLog.Error("LLAMA_ARGS cannot override argument", "arg", disallowed) + exitFunc(1) } } } - testLog.Infof("Using custom arguments: %v", args) + testLog.Info("Using custom arguments", "args", args) return &llamacpp.Config{ Args: args, } diff --git a/main_test.go b/main_test.go index 75f89e584..d2967235b 100644 --- a/main_test.go +++ b/main_test.go @@ -4,7 +4,6 @@ import ( "testing" "github.com/docker/model-runner/pkg/inference/backends/llamacpp" - "github.com/sirupsen/logrus" ) func TestCreateLlamaCppConfigFromEnv(t *testing.T) { @@ -61,17 +60,14 @@ func TestCreateLlamaCppConfigFromEnv(t *testing.T) { t.Setenv("LLAMA_ARGS", tt.llamaArgs) } - // Create a test logger that captures fatal errors - originalLog := testLog - defer func() { testLog = originalLog }() + // Override exitFunc to capture exit calls instead of actually exiting + originalExitFunc := exitFunc + defer func() { exitFunc = originalExitFunc }() - // Create a new logger that will exit with a special exit code - newTestLog := logrus.New() var exitCode int - newTestLog.ExitFunc = func(code int) { + exitFunc = func(code int) { exitCode = code } - testLog = newTestLog config := createLlamaCppConfigFromEnv() diff --git a/pkg/anthropic/handler.go b/pkg/anthropic/handler.go index a03ff57f4..323bec76e 100644 --- a/pkg/anthropic/handler.go +++ b/pkg/anthropic/handler.go @@ -59,7 +59,7 @@ func NewHandler(log logging.Logger, schedulerHTTP *scheduling.HTTPHandler, allow func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { safeMethod := utils.SanitizeForLog(r.Method, -1) safePath := utils.SanitizeForLog(r.URL.Path, -1) - h.log.Infof("Anthropic API request: %s %s", safeMethod, safePath) + h.log.Info("Anthropic API request", "method", safeMethod, "path", safePath) h.httpHandler.ServeHTTP(w, r) } @@ -169,6 +169,6 @@ func (h *Handler) writeAnthropicError(w http.ResponseWriter, statusCode int, err } if err := json.NewEncoder(w).Encode(errResp); err != nil { - h.log.Errorf("Failed to encode error response: %v", err) + h.log.Error("Failed to encode error response", "error", err) } } diff --git a/pkg/anthropic/handler_test.go b/pkg/anthropic/handler_test.go index b2925fabf..39a575142 100644 --- a/pkg/anthropic/handler_test.go +++ b/pkg/anthropic/handler_test.go @@ -1,13 +1,11 @@ package anthropic import ( - "io" + "log/slog" "net/http" "net/http/httptest" "strings" "testing" - - "github.com/sirupsen/logrus" ) func TestWriteAnthropicError(t *testing.T) { @@ -48,9 +46,9 @@ func TestWriteAnthropicError(t *testing.T) { t.Parallel() rec := httptest.NewRecorder() - discard := logrus.New() - discard.SetOutput(io.Discard) - h := &Handler{log: logrus.NewEntry(discard)} + discard := slog.Default() + // discard output is controlled by the slog handler level + h := &Handler{log: discard} h.writeAnthropicError(rec, tt.statusCode, tt.errorType, tt.message) if rec.Code != tt.statusCode { @@ -105,9 +103,9 @@ func TestAPIPrefix(t *testing.T) { func TestProxyToBackend_InvalidJSON(t *testing.T) { t.Parallel() - discard := logrus.New() - discard.SetOutput(io.Discard) - h := &Handler{log: logrus.NewEntry(discard)} + discard := slog.Default() + // discard output is controlled by the slog handler level + h := &Handler{log: discard} rec := httptest.NewRecorder() req := httptest.NewRequest(http.MethodPost, "/anthropic/v1/messages", strings.NewReader(`{invalid json`)) @@ -130,9 +128,9 @@ func TestProxyToBackend_InvalidJSON(t *testing.T) { func TestProxyToBackend_MissingModel(t *testing.T) { t.Parallel() - discard := logrus.New() - discard.SetOutput(io.Discard) - h := &Handler{log: logrus.NewEntry(discard)} + discard := slog.Default() + // discard output is controlled by the slog handler level + h := &Handler{log: discard} rec := httptest.NewRecorder() req := httptest.NewRequest(http.MethodPost, "/anthropic/v1/messages", strings.NewReader(`{"messages": []}`)) @@ -155,9 +153,9 @@ func TestProxyToBackend_MissingModel(t *testing.T) { func TestProxyToBackend_EmptyModel(t *testing.T) { t.Parallel() - discard := logrus.New() - discard.SetOutput(io.Discard) - h := &Handler{log: logrus.NewEntry(discard)} + discard := slog.Default() + // discard output is controlled by the slog handler level + h := &Handler{log: discard} rec := httptest.NewRecorder() req := httptest.NewRequest(http.MethodPost, "/anthropic/v1/messages", strings.NewReader(`{"model": ""}`)) @@ -180,9 +178,9 @@ func TestProxyToBackend_EmptyModel(t *testing.T) { func TestProxyToBackend_RequestTooLarge(t *testing.T) { t.Parallel() - discard := logrus.New() - discard.SetOutput(io.Discard) - h := &Handler{log: logrus.NewEntry(discard)} + discard := slog.Default() + // discard output is controlled by the slog handler level + h := &Handler{log: discard} // Create a request body that exceeds the maxRequestBodySize (10MB) // We'll use a reader that simulates a large body without actually allocating it diff --git a/pkg/distribution/distribution/client.go b/pkg/distribution/distribution/client.go index 15dca4287..04961aae5 100644 --- a/pkg/distribution/distribution/client.go +++ b/pkg/distribution/distribution/client.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" "io" + "log/slog" "os" "path/filepath" "slices" @@ -23,13 +24,12 @@ import ( "github.com/docker/model-runner/pkg/distribution/types" "github.com/docker/model-runner/pkg/inference/platform" "github.com/docker/model-runner/pkg/internal/utils" - "github.com/sirupsen/logrus" ) // Client provides model distribution functionality type Client struct { store *store.LocalStore - log *logrus.Entry + log *slog.Logger registry *registry.Client } @@ -44,7 +44,7 @@ type Option func(*options) // options holds the configuration for a new Client type options struct { storeRootPath string - logger *logrus.Entry + logger *slog.Logger registryClient *registry.Client } @@ -58,7 +58,7 @@ func WithStoreRootPath(path string) Option { } // WithLogger sets the logger -func WithLogger(logger *logrus.Entry) Option { +func WithLogger(logger *slog.Logger) Option { return func(o *options) { if logger != nil { o.logger = logger @@ -77,7 +77,7 @@ func WithRegistryClient(client *registry.Client) Option { func defaultOptions() *options { return &options{ - logger: logrus.NewEntry(logrus.StandardLogger()), + logger: slog.Default(), } } @@ -104,7 +104,7 @@ func NewClient(opts ...Option) (*Client, error) { registryClient = registry.NewClient() } - options.logger.Infoln("Successfully initialized store") + options.logger.Info("Successfully initialized store") c := &Client{ store: s, log: options.logger, @@ -113,7 +113,7 @@ func NewClient(opts ...Option) (*Client, error) { // Migrate any legacy hf.co tags to huggingface.co if err := c.migrateHFTags(); err != nil { - options.logger.Warnf("Failed to migrate HuggingFace tags: %v", err) + options.logger.Warn("Failed to migrate HuggingFace tags", "error", err) } return c, nil @@ -133,7 +133,7 @@ func (c *Client) migrateHFTags() error { return err } if migrated > 0 { - c.log.Infof("Migrated %d HuggingFace tag(s) from hf.co to huggingface.co", migrated) + c.log.Info("Migrated HuggingFace tag(s) from hf.co to huggingface.co", "count", migrated) } return nil } @@ -267,7 +267,7 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter originalReference := reference // Normalize the model reference reference = c.normalizeModelName(reference) - c.log.Infoln("Starting model pull:", utils.SanitizeForLog(reference)) + c.log.Info("starting model pull", "reference", utils.SanitizeForLog(reference)) // Handle bearer token for registry authentication var token string @@ -277,18 +277,18 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter // HuggingFace references always use native pull (download raw files from HF Hub) if isHuggingFaceReference(originalReference) { - c.log.Infoln("Using native HuggingFace pull for:", utils.SanitizeForLog(reference)) + c.log.Info("using native HuggingFace pull", "reference", utils.SanitizeForLog(reference)) // Check if model already exists in local store (reference is already normalized) localModel, err := c.store.Read(reference) if err == nil { - c.log.Infoln("HuggingFace model found in local store:", utils.SanitizeForLog(reference)) + c.log.Info("HuggingFace model found in local store", "reference", utils.SanitizeForLog(reference)) cfg, err := localModel.Config() if err != nil { return fmt.Errorf("getting cached model config: %w", err) } if err := progress.WriteSuccess(progressWriter, fmt.Sprintf("Using cached model: %s", cfg.GetSize()), oci.ModePull); err != nil { - c.log.Warnf("Writing progress: %v", err) + c.log.Warn("Writing progress", "error", err) } return nil } @@ -323,10 +323,10 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter // This prevents race conditions if the tag is updated during the pull remoteDigest, err := remoteModel.Digest() if err != nil { - c.log.Errorln("Failed to get remote image digest:", err) + c.log.Error("failed to get remote image digest", "error", err) return fmt.Errorf("getting remote image digest: %w", err) } - c.log.Infoln("Remote model digest:", remoteDigest.String()) + c.log.Info("remote model digest", "digest", remoteDigest.String()) // Check for incomplete downloads and prepare resume offsets layers, err := remoteModel.Layers() @@ -339,25 +339,25 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter for _, layer := range layers { digest, err := layer.Digest() if err != nil { - c.log.Warnf("Failed to get layer digest: %v", err) + c.log.Warn("Failed to get layer digest", "error", err) continue } // Check if there's an incomplete download for this layer (use DiffID for uncompressed models) diffID, err := layer.DiffID() if err != nil { - c.log.Warnf("Failed to get layer diffID: %v", err) + c.log.Warn("Failed to get layer diffID", "error", err) continue } incompleteSize, err := c.store.GetIncompleteSize(diffID) if err != nil { - c.log.Warnf("Failed to check incomplete size for layer %s: %v", digest, err) + c.log.Warn("Failed to check incomplete size for layer", "digest", digest, "error", err) continue } if incompleteSize > 0 { - c.log.Infof("Found incomplete download for layer %s: %d bytes", digest, incompleteSize) + c.log.Info("Found incomplete download for layer", "digest", digest, "bytes", incompleteSize) resumeOffsets[digest.String()] = incompleteSize } } @@ -366,14 +366,14 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter // and re-fetch using the original reference to ensure compatibility with all registries var rangeSuccess *remote.RangeSuccess if len(resumeOffsets) > 0 { - c.log.Infof("Resuming %d interrupted layer download(s)", len(resumeOffsets)) + c.log.Info("Resuming interrupted layer download(s)", "count", len(resumeOffsets)) // Create a RangeSuccess tracker to record which Range requests succeed rangeSuccess = &remote.RangeSuccess{} ctx = remote.WithResumeOffsets(ctx, resumeOffsets) ctx = remote.WithRangeSuccess(ctx, rangeSuccess) // Re-fetch the model using the original tag reference // The digest has already been validated above, and the resume context will handle layer resumption - c.log.Infof("Re-fetching model with original reference for resume: %s", utils.SanitizeForLog(reference)) + c.log.Info("Re-fetching model with original reference for resume", "model", utils.SanitizeForLog(reference)) remoteModel, err = registryClient.Model(ctx, reference) if err != nil { return fmt.Errorf("reading model from registry with resume context: %w", err) @@ -388,7 +388,7 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter // Check if model exists in local store localModel, err := c.store.Read(remoteDigest.String()) if err == nil { - c.log.Infoln("Model found in local store:", utils.SanitizeForLog(reference)) + c.log.Info("model found in local store", "reference", utils.SanitizeForLog(reference)) cfg, err := localModel.Config() if err != nil { return fmt.Errorf("getting cached model config: %w", err) @@ -396,7 +396,7 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter err = progress.WriteSuccess(progressWriter, fmt.Sprintf("Using cached model: %s", cfg.GetSize()), oci.ModePull) if err != nil { - c.log.Warnf("Writing progress: %v", err) + c.log.Warn("Writing progress", "error", err) } // Ensure model has the correct tag @@ -405,7 +405,7 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter } return nil } else { - c.log.Infoln("Model not found in local store, pulling from remote:", utils.SanitizeForLog(reference)) + c.log.Info("model not found in local store, pulling from remote", "reference", utils.SanitizeForLog(reference)) } // Model doesn't exist in local store or digests don't match, pull from remote @@ -417,13 +417,13 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter } if err = c.store.Write(remoteModel, []string{reference}, progressWriter, writeOpts...); err != nil { if writeErr := progress.WriteError(progressWriter, fmt.Sprintf("Error: %s", err.Error()), oci.ModePull); writeErr != nil { - c.log.Warnf("Failed to write error message: %v", writeErr) + c.log.Warn("Failed to write error message", "error", writeErr) } return fmt.Errorf("writing image to store: %w", err) } if err := progress.WriteSuccess(progressWriter, "Model pulled successfully", oci.ModePull); err != nil { - c.log.Warnf("Failed to write success message: %v", err) + c.log.Warn("Failed to write success message", "error", err) } return nil @@ -431,7 +431,7 @@ func (c *Client) PullModel(ctx context.Context, reference string, progressWriter // LoadModel loads the model from the reader to the store func (c *Client) LoadModel(r io.Reader, progressWriter io.Writer) (string, error) { - c.log.Infoln("Starting model load") + c.log.Info("Starting model load") tr := tarball.NewReader(r) for { @@ -441,30 +441,30 @@ func (c *Client) LoadModel(r io.Reader, progressWriter io.Writer) (string, error } if err != nil { if errors.Is(err, io.ErrUnexpectedEOF) { - c.log.Infof("Model load interrupted (likely cancelled): %s", utils.SanitizeForLog(err.Error())) + c.log.Info("Model load interrupted (likely cancelled)", "error", utils.SanitizeForLog(err.Error())) return "", fmt.Errorf("model load interrupted: %w", err) } return "", fmt.Errorf("reading blob from stream: %w", err) } - c.log.Infoln("Loading blob:", diffID) + c.log.Info("loading blob", "diffID", diffID) if err := c.store.WriteBlob(diffID, tr); err != nil { return "", fmt.Errorf("writing blob: %w", err) } - c.log.Infoln("Loaded blob:", diffID) + c.log.Info("loaded blob", "diffID", diffID) } manifest, digest, err := tr.Manifest() if err != nil { return "", fmt.Errorf("read manifest: %w", err) } - c.log.Infoln("Loading manifest:", digest.String()) + c.log.Info("loading manifest", "digest", digest.String()) if err := c.store.WriteManifest(digest, manifest); err != nil { return "", fmt.Errorf("write manifest: %w", err) } - c.log.Infoln("Loaded model with ID:", digest.String()) + c.log.Info("loaded model", "id", digest.String()) if err := progress.WriteSuccess(progressWriter, "Model loaded successfully", oci.ModePull); err != nil { - c.log.Warnf("Failed to write success message: %v", err) + c.log.Warn("Failed to write success message", "error", err) } return digest.String(), nil @@ -472,10 +472,10 @@ func (c *Client) LoadModel(r io.Reader, progressWriter io.Writer) (string, error // ListModels returns all available models func (c *Client) ListModels() ([]types.Model, error) { - c.log.Infoln("Listing available models") + c.log.Info("Listing available models") modelInfos, err := c.store.List() if err != nil { - c.log.Errorln("Failed to list models:", err) + c.log.Error("failed to list models", "error", err) return nil, fmt.Errorf("listing models: %w", err) } @@ -484,23 +484,23 @@ func (c *Client) ListModels() ([]types.Model, error) { // Read the models model, err := c.store.Read(modelInfo.ID) if err != nil { - c.log.Warnf("Failed to read model with ID %s: %v", modelInfo.ID, err) + c.log.Warn("Failed to read model with ID", "model", modelInfo.ID, "error", err) continue } result = append(result, model) } - c.log.Infoln("Successfully listed models, count:", len(result)) + c.log.Info("successfully listed models", "count", len(result)) return result, nil } // GetModel returns a model by reference func (c *Client) GetModel(reference string) (types.Model, error) { - c.log.Infoln("Getting model by reference:", utils.SanitizeForLog(reference)) + c.log.Info("getting model by reference", "reference", utils.SanitizeForLog(reference)) normalizedRef := c.normalizeModelName(reference) model, err := c.store.Read(normalizedRef) if err != nil { - c.log.Errorln("Failed to get model:", err, "reference:", utils.SanitizeForLog(reference)) + c.log.Error("failed to get model", "error", err, "reference", utils.SanitizeForLog(reference)) return nil, fmt.Errorf("get model '%q': %w", utils.SanitizeForLog(reference), err) } @@ -509,7 +509,7 @@ func (c *Client) GetModel(reference string) (types.Model, error) { // IsModelInStore checks if a model with the given reference is in the local store func (c *Client) IsModelInStore(reference string) (bool, error) { - c.log.Infoln("Checking model by reference:", utils.SanitizeForLog(reference)) + c.log.Info("checking model by reference", "reference", utils.SanitizeForLog(reference)) normalizedRef := c.normalizeModelName(reference) if _, err := c.store.Read(normalizedRef); errors.Is(err, ErrModelNotFound) { return false, nil @@ -546,10 +546,10 @@ func (c *Client) DeleteModel(reference string, force bool) (*DeleteModelResponse resp := DeleteModelResponse{} if isTag { - c.log.Infoln("Untagging model:", reference) + c.log.Info("untagging model", "reference", reference) tags, err := c.store.RemoveTags([]string{normalizedRef}) if err != nil { - c.log.Errorln("Failed to untag model:", err, "tag:", reference) + c.log.Error("failed to untag model", "error", err, "tag", reference) return &DeleteModelResponse{}, fmt.Errorf("untagging model: %w", err) } for _, t := range tags { @@ -568,13 +568,13 @@ func (c *Client) DeleteModel(reference string, force bool) (*DeleteModelResponse ) } - c.log.Infoln("Deleting model:", id) + c.log.Info("deleting model", "id", id) deletedID, tags, err := c.store.Delete(id) if err != nil { - c.log.Errorln("Failed to delete model:", err, "tag:", reference) + c.log.Error("failed to delete model", "error", err, "tag", reference) return &DeleteModelResponse{}, fmt.Errorf("deleting model: %w", err) } - c.log.Infoln("Successfully deleted model:", reference) + c.log.Info("successfully deleted model", "reference", reference) for _, t := range tags { resp = append(resp, DeleteModelAction{Untagged: &t}) } @@ -584,7 +584,7 @@ func (c *Client) DeleteModel(reference string, force bool) (*DeleteModelResponse // Tag adds a tag to a model func (c *Client) Tag(source string, target string) error { - c.log.Infoln("Tagging model, source:", source, "target:", utils.SanitizeForLog(target)) + c.log.Info("tagging model", "source", source, "target", utils.SanitizeForLog(target)) normalizedSource := c.normalizeModelName(source) normalizedTarget := c.normalizeModelName(target) return c.store.AddTags(normalizedSource, []string{normalizedTarget}) @@ -619,18 +619,19 @@ func (c *Client) PushModel(ctx context.Context, tag string, progressWriter io.Wr return fmt.Errorf("reading model: %w", err) } - c.log.Infoln("Pushing model:", utils.SanitizeForLog(tag, -1)) + // Push the model + c.log.Info("pushing model", "tag", utils.SanitizeForLog(tag, -1)) if err := target.Write(ctx, mdl, progressWriter); err != nil { - c.log.Errorln("Failed to push image:", err, "reference:", tag) + c.log.Error("failed to push image", "error", err, "reference", tag) if writeErr := progress.WriteError(progressWriter, fmt.Sprintf("Error: %s", err.Error()), oci.ModePush); writeErr != nil { - c.log.Warnf("Failed to write error message: %v", writeErr) + c.log.Warn("Failed to write error message", "error", writeErr) } return fmt.Errorf("pushing image: %w", err) } - c.log.Infoln("Successfully pushed model:", tag) + c.log.Info("successfully pushed model", "tag", tag) if err := progress.WriteSuccess(progressWriter, "Model pushed successfully", oci.ModePush); err != nil { - c.log.Warnf("Failed to write success message: %v", err) + c.log.Warn("Failed to write success message", "error", err) } return nil @@ -638,7 +639,7 @@ func (c *Client) PushModel(ctx context.Context, tag string, progressWriter io.Wr func (c *Client) pushNativeHuggingFace(ctx context.Context, reference, normalizedRef string, progressWriter io.Writer, token string) error { repo, _, _ := parseHFReference(reference) - c.log.Infof("Pushing native HuggingFace model: repo=%s", utils.SanitizeForLog(repo)) + c.log.Info("Pushing native HuggingFace model", "repo", utils.SanitizeForLog(repo)) if progressWriter != nil { _ = progress.WriteProgress(progressWriter, "Preparing HuggingFace upload...", 0, 0, 0, "", oci.ModePush) @@ -672,7 +673,7 @@ func (c *Client) pushNativeHuggingFace(ctx context.Context, reference, normalize } if err := huggingface.UploadFiles(ctx, hfClient, repo, files, totalSize, progressWriter); err != nil { - c.log.Errorf("HuggingFace push failed: %v", err) + c.log.Error("HuggingFace push failed", "error", err) var authErr *huggingface.AuthError var notFoundErr *huggingface.NotFoundError if errors.As(err, &authErr) { @@ -682,13 +683,13 @@ func (c *Client) pushNativeHuggingFace(ctx context.Context, reference, normalize return registry.ErrModelNotFound } if writeErr := progress.WriteError(progressWriter, fmt.Sprintf("Error: %s", err.Error()), oci.ModePush); writeErr != nil { - c.log.Warnf("Failed to write error message: %v", writeErr) + c.log.Warn("Failed to write error message", "error", writeErr) } return fmt.Errorf("upload model to HuggingFace: %w", err) } if err := progress.WriteSuccess(progressWriter, "Model pushed successfully", oci.ModePush); err != nil { - c.log.Warnf("Failed to write success message: %v", err) + c.log.Warn("Failed to write success message", "error", err) } return nil @@ -698,7 +699,7 @@ func (c *Client) pushNativeHuggingFace(ctx context.Context, reference, normalize // This is used for config-only modifications where the layer data hasn't changed. // The layers must already exist in the store. func (c *Client) WriteLightweightModel(mdl types.ModelArtifact, tags []string) error { - c.log.Infoln("Writing lightweight model variant") + c.log.Info("Writing lightweight model variant") normalizedTags := make([]string, len(tags)) for i, tag := range tags { normalizedTags[i] = c.normalizeModelName(tag) @@ -707,20 +708,20 @@ func (c *Client) WriteLightweightModel(mdl types.ModelArtifact, tags []string) e } func (c *Client) ResetStore() error { - c.log.Infoln("Resetting store") + c.log.Info("Resetting store") if err := c.store.Reset(); err != nil { - c.log.Errorln("Failed to reset store:", err) + c.log.Error("failed to reset store", "error", err) return fmt.Errorf("resetting store: %w", err) } return nil } func (c *Client) ExportModel(reference string, w io.Writer) error { - c.log.Infoln("Exporting model:", utils.SanitizeForLog(reference)) + c.log.Info("exporting model", "reference", utils.SanitizeForLog(reference)) normalizedRef := c.normalizeModelName(reference) mdl, err := c.store.Read(normalizedRef) if err != nil { - c.log.Errorln("Failed to get model for export:", err, "reference:", utils.SanitizeForLog(reference)) + c.log.Error("failed to get model for export", "error", err, "reference", utils.SanitizeForLog(reference)) return fmt.Errorf("get model '%q': %w", utils.SanitizeForLog(reference), err) } @@ -730,11 +731,11 @@ func (c *Client) ExportModel(reference string, w io.Writer) error { } if err := target.Write(context.Background(), mdl, nil); err != nil { - c.log.Errorln("Failed to export model:", err, "reference:", utils.SanitizeForLog(reference)) + c.log.Error("failed to export model", "error", err, "reference", utils.SanitizeForLog(reference)) return fmt.Errorf("export model: %w", err) } - c.log.Infoln("Successfully exported model:", utils.SanitizeForLog(reference)) + c.log.Info("successfully exported model", "reference", utils.SanitizeForLog(reference)) return nil } @@ -743,14 +744,14 @@ type RepackageOptions struct { } func (c *Client) RepackageModel(sourceRef string, targetRef string, opts RepackageOptions) error { - c.log.Infoln("Repackaging model:", utils.SanitizeForLog(sourceRef), "->", utils.SanitizeForLog(targetRef)) + c.log.Info("repackaging model", "source", utils.SanitizeForLog(sourceRef), "target", utils.SanitizeForLog(targetRef)) normalizedSource := c.normalizeModelName(sourceRef) normalizedTarget := c.normalizeModelName(targetRef) mdl, err := c.store.Read(normalizedSource) if err != nil { - c.log.Errorln("Failed to get model for repackaging:", err, "reference:", utils.SanitizeForLog(sourceRef)) + c.log.Error("failed to get model for repackaging", "error", err, "reference", utils.SanitizeForLog(sourceRef)) return fmt.Errorf("get model '%q': %w", utils.SanitizeForLog(sourceRef), err) } @@ -760,11 +761,11 @@ func (c *Client) RepackageModel(sourceRef string, targetRef string, opts Repacka } if err := c.store.WriteLightweight(modifiedModel, []string{normalizedTarget}); err != nil { - c.log.Errorln("Failed to write repackaged model:", err, "target:", utils.SanitizeForLog(targetRef)) + c.log.Error("failed to write repackaged model", "error", err, "target", utils.SanitizeForLog(targetRef)) return fmt.Errorf("write repackaged model: %w", err) } - c.log.Infoln("Successfully repackaged model:", utils.SanitizeForLog(sourceRef), "->", utils.SanitizeForLog(targetRef)) + c.log.Info("successfully repackaged model", "source", utils.SanitizeForLog(sourceRef), "target", utils.SanitizeForLog(targetRef)) return nil } @@ -781,7 +782,7 @@ func GetSupportedFormats() []types.Format { return []types.Format{types.FormatGGUF, types.FormatDiffusers} } -func checkCompat(image types.ModelArtifact, log *logrus.Entry, reference string, progressWriter io.Writer) error { +func checkCompat(image types.ModelArtifact, log *slog.Logger, reference string, progressWriter io.Writer) error { manifest, err := image.Manifest() if err != nil { return err @@ -797,13 +798,12 @@ func checkCompat(image types.ModelArtifact, log *logrus.Entry, reference string, } if config.GetFormat() == "" { - log.Warnf("Model format field is empty for %s, unable to verify format compatibility", - utils.SanitizeForLog(reference)) + log.Warn("Model format field is empty for , unable to verify format compatibility", "model", utils.SanitizeForLog(reference)) } else if !slices.Contains(GetSupportedFormats(), config.GetFormat()) { // Write warning but continue with pull - log.Warnln(warnUnsupportedFormat) + log.Warn(warnUnsupportedFormat) if err := progress.WriteWarning(progressWriter, warnUnsupportedFormat, oci.ModePull); err != nil { - log.Warnf("Failed to write warning message: %v", err) + log.Warn("Failed to write warning message", "error", err) } // Don't return an error - allow the pull to continue } @@ -848,7 +848,7 @@ func parseHFReference(reference string) (repo, revision, tag string) { // This is used when the model is stored as raw files (safetensors) on HuggingFace Hub func (c *Client) pullNativeHuggingFace(ctx context.Context, reference string, progressWriter io.Writer, token string) error { repo, revision, tag := parseHFReference(reference) - c.log.Infof("Pulling native HuggingFace model: repo=%s, revision=%s, tag=%s", utils.SanitizeForLog(repo), utils.SanitizeForLog(revision), utils.SanitizeForLog(tag)) + c.log.Info("Pulling native HuggingFace model", "repo", utils.SanitizeForLog(repo), "revision", utils.SanitizeForLog(revision), "tag", utils.SanitizeForLog(tag)) // Create HuggingFace client hfOpts := []huggingface.ClientOption{ @@ -880,23 +880,23 @@ func (c *Client) pullNativeHuggingFace(ctx context.Context, reference string, pr return registry.ErrModelNotFound } if writeErr := progress.WriteError(progressWriter, fmt.Sprintf("Error: %s", err.Error()), oci.ModePull); writeErr != nil { - c.log.Warnf("Failed to write error message: %v", writeErr) + c.log.Warn("Failed to write error message", "error", writeErr) } return fmt.Errorf("build model from HuggingFace: %w", err) } // Write model to store with normalized tag storageTag := c.normalizeModelName(reference) - c.log.Infof("Writing model to store with tag: %s", utils.SanitizeForLog(storageTag)) + c.log.Info("Writing model to store with tag", "model", utils.SanitizeForLog(storageTag)) if err := c.store.Write(model, []string{storageTag}, progressWriter); err != nil { if writeErr := progress.WriteError(progressWriter, fmt.Sprintf("Error: %s", err.Error()), oci.ModePull); writeErr != nil { - c.log.Warnf("Failed to write error message: %v", writeErr) + c.log.Warn("Failed to write error message", "error", writeErr) } return fmt.Errorf("writing model to store: %w", err) } if err := progress.WriteSuccess(progressWriter, "Model pulled successfully", oci.ModePull); err != nil { - c.log.Warnf("Failed to write success message: %v", err) + c.log.Warn("Failed to write success message", "error", err) } return nil diff --git a/pkg/distribution/distribution/client_test.go b/pkg/distribution/distribution/client_test.go index 31629ff79..ae5754349 100644 --- a/pkg/distribution/distribution/client_test.go +++ b/pkg/distribution/distribution/client_test.go @@ -8,6 +8,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net/http/httptest" "net/url" "os" @@ -24,7 +25,6 @@ import ( mdregistry "github.com/docker/model-runner/pkg/distribution/registry" "github.com/docker/model-runner/pkg/distribution/registry/testregistry" "github.com/docker/model-runner/pkg/inference/platform" - "github.com/sirupsen/logrus" ) var ( @@ -717,7 +717,7 @@ func TestClientDefaultLogger(t *testing.T) { } // Create client with custom logger - customLogger := logrus.NewEntry(logrus.New()) + customLogger := slog.Default() client, err = NewClient( WithStoreRootPath(tempDir), WithLogger(customLogger), diff --git a/pkg/distribution/distribution/normalize_test.go b/pkg/distribution/distribution/normalize_test.go index 26dd55673..4e791eeff 100644 --- a/pkg/distribution/distribution/normalize_test.go +++ b/pkg/distribution/distribution/normalize_test.go @@ -2,13 +2,13 @@ package distribution import ( "io" + "log/slog" "path/filepath" "strings" "testing" "github.com/docker/model-runner/pkg/distribution/builder" "github.com/docker/model-runner/pkg/distribution/tarball" - "github.com/sirupsen/logrus" ) func TestNormalizeModelName(t *testing.T) { @@ -339,7 +339,7 @@ func createTestClient(t *testing.T) (*Client, func()) { // Create client with minimal config client, err := NewClient( WithStoreRootPath(tempDir), - WithLogger(logrus.NewEntry(logrus.StandardLogger())), + WithLogger(slog.Default()), ) if err != nil { t.Fatalf("Failed to create test client: %v", err) diff --git a/pkg/distribution/registry/testregistry/registry.go b/pkg/distribution/registry/testregistry/registry.go index b8555266b..e82aa233e 100644 --- a/pkg/distribution/registry/testregistry/registry.go +++ b/pkg/distribution/registry/testregistry/registry.go @@ -69,7 +69,9 @@ func (r *Registry) handleBlobUpload(w http.ResponseWriter, req *http.Request, pa switch req.Method { case http.MethodPost: // Start upload + r.mu.RLock() uploadID := fmt.Sprintf("upload-%d", len(r.blobs)) + r.mu.RUnlock() location := fmt.Sprintf("/v2/%s/blobs/uploads/%s", repo, uploadID) w.Header().Set("Location", location) w.Header().Set("Docker-Upload-UUID", uploadID) diff --git a/pkg/inference/backends/diffusers/diffusers.go b/pkg/inference/backends/diffusers/diffusers.go index a966c6678..3a991d1eb 100644 --- a/pkg/inference/backends/diffusers/diffusers.go +++ b/pkg/inference/backends/diffusers/diffusers.go @@ -116,14 +116,14 @@ func (d *diffusers) Install(_ context.Context, _ *http.Client) error { // Check if diffusers is installed if err := d.pythonCmd("-c", "import diffusers").Run(); err != nil { d.status = "diffusers package not installed" - d.log.Warnf("diffusers package not found. Install with: uv pip install diffusers torch") + d.log.Warn("diffusers package not found. Install with: uv pip install diffusers torch") return ErrDiffusersNotFound } // Get version output, err := d.pythonCmd("-c", "import diffusers; print(diffusers.__version__)").Output() if err != nil { - d.log.Warnf("could not get diffusers version: %v", err) + d.log.Warn("could not get diffusers version", "error", err) d.status = "running diffusers version: unknown" } else { d.status = fmt.Sprintf("running diffusers version: %s", strings.TrimSpace(string(output))) @@ -156,7 +156,7 @@ func (d *diffusers) Run(ctx context.Context, socket, model string, modelRef stri return fmt.Errorf("%w: model %s", ErrNoDDUFFile, model) } - d.log.Infof("Loading DDUF file from: %s", ddufPath) + d.log.Info("Loading DDUF file from", "path", ddufPath) args, err := d.config.GetArgs(ddufPath, socket, mode, backendConfig) if err != nil { @@ -168,7 +168,7 @@ func (d *diffusers) Run(ctx context.Context, socket, model string, modelRef stri args = append(args, "--served-model-name", modelRef) } - d.log.Infof("Diffusers args: %v", utils.SanitizeForLog(strings.Join(args, " "))) + d.log.Info("Diffusers args", "args", utils.SanitizeForLog(strings.Join(args, " "))) if d.pythonPath == "" { return fmt.Errorf("diffusers: python runtime not configured; did you forget to call Install") @@ -187,7 +187,7 @@ func (d *diffusers) Run(ctx context.Context, socket, model string, modelRef stri SandboxConfig: "", Args: args, Logger: d.log, - ServerLogWriter: d.serverLog.Writer(), + ServerLogWriter: logging.NewWriter(d.serverLog), ErrorTransformer: ExtractPythonError, }) } diff --git a/pkg/inference/backends/llamacpp/download.go b/pkg/inference/backends/llamacpp/download.go index 4db132711..fb1e24b01 100644 --- a/pkg/inference/backends/llamacpp/download.go +++ b/pkg/inference/backends/llamacpp/download.go @@ -56,11 +56,11 @@ func (l *llamaCpp) downloadLatestLlamaCpp(ctx context.Context, log logging.Logge shouldUpdateServer := ShouldUpdateServer ShouldUpdateServerLock.Unlock() if !shouldUpdateServer { - log.Infof("downloadLatestLlamaCpp: update disabled") + log.Info("downloadLatestLlamaCpp: update disabled") return errLlamaCppUpdateDisabled } - log.Infof("downloadLatestLlamaCpp: %s, %s, %s, %s", desiredVersion, desiredVariant, vendoredServerStoragePath, llamaCppPath) + log.Info("downloadLatestLlamaCpp", "version", desiredVersion, "variant", desiredVariant, "storagePath", vendoredServerStoragePath, "llamaCppPath", llamaCppPath) desiredTag := desiredVersion + "-" + desiredVariant url := fmt.Sprintf("https://hub.docker.com/v2/namespaces/%s/repositories/%s/tags/%s", hubNamespace, hubRepo, desiredTag) resp, err := httpClient.Get(url) @@ -89,7 +89,7 @@ func (l *llamaCpp) downloadLatestLlamaCpp(ctx context.Context, log logging.Logge latest = response.Digest } if latest == "" { - log.Warnf("could not fing the %s tag, hub response: %s", desiredTag, body) + log.Warn("could not find the tag", "tag", desiredTag, "response", body) return fmt.Errorf("could not find the %s tag", desiredTag) } @@ -107,18 +107,18 @@ func (l *llamaCpp) downloadLatestLlamaCpp(ctx context.Context, log logging.Logge data, err = os.ReadFile(currentVersionFile) if err != nil { - log.Warnf("failed to read current llama.cpp version: %v", err) - log.Warnf("proceeding to update llama.cpp binary") + log.Warn("failed to read current llama.cpp version", "error", err) + log.Warn("proceeding to update llama.cpp binary") } else if strings.TrimSpace(string(data)) == latest { - log.Infoln("current llama.cpp version is already up to date") + log.Info("current llama.cpp version is already up to date") if _, statErr := os.Stat(llamaCppPath); statErr == nil { l.status = fmt.Sprintf("running llama.cpp %s (%s) version: %s", desiredTag, latest, getLlamaCppVersion(log, llamaCppPath)) return nil } - log.Infoln("llama.cpp binary must be updated, proceeding to update it") + log.Info("llama.cpp binary must be updated, proceeding to update it") } else { - log.Infof("current llama.cpp version is outdated: %s vs %s, proceeding to update it", strings.TrimSpace(string(data)), latest) + log.Info("current llama.cpp version is outdated, proceeding to update", "current", strings.TrimSpace(string(data)), "latest", latest) } image := fmt.Sprintf("registry-1.docker.io/%s/%s@%s", hubNamespace, hubRepo, latest) @@ -163,12 +163,12 @@ func (l *llamaCpp) downloadLatestLlamaCpp(ctx context.Context, log logging.Logge } } - log.Infoln("successfully updated llama.cpp binary") + log.Info("successfully updated llama.cpp binary") l.status = fmt.Sprintf("running llama.cpp %s (%s) version: %s", desiredTag, latest, getLlamaCppVersion(log, llamaCppPath)) - log.Infoln(l.status) + log.Info(l.status) if err := os.WriteFile(currentVersionFile, []byte(latest), 0o644); err != nil { - log.Warnf("failed to save llama.cpp version: %v", err) + log.Warn("failed to save llama.cpp version", "error", err) } return nil @@ -176,7 +176,7 @@ func (l *llamaCpp) downloadLatestLlamaCpp(ctx context.Context, log logging.Logge //nolint:unused // Used in platform-specific files (download_darwin.go, download_windows.go) func extractFromImage(ctx context.Context, log logging.Logger, image, requiredOs, requiredArch, destination string) error { - log.Infof("Extracting image %q to %q", image, destination) + log.Info("Extracting image", "image", image, "destination", destination) tmpDir, err := os.MkdirTemp("", "docker-tar-extract") if err != nil { return err @@ -191,7 +191,7 @@ func extractFromImage(ctx context.Context, log logging.Logger, image, requiredOs func getLlamaCppVersion(log logging.Logger, llamaCpp string) string { output, err := exec.Command(llamaCpp, "--version").CombinedOutput() if err != nil { - log.Warnf("could not get llama.cpp version: %v", err) + log.Warn("could not get llama.cpp version", "error", err) return "unknown" } re := regexp.MustCompile(`version: \d+ \((\w+)\)`) @@ -199,6 +199,6 @@ func getLlamaCppVersion(log logging.Logger, llamaCpp string) string { if len(matches) == 2 { return matches[1] } - log.Warnf("failed to parse llama.cpp version from output:\n%s", strings.TrimSpace(string(output))) + log.Warn("Failed to parse llama.cpp version from output", "output", strings.TrimSpace(string(output))) return "unknown" } diff --git a/pkg/inference/backends/llamacpp/llamacpp.go b/pkg/inference/backends/llamacpp/llamacpp.go index a116480dc..ee4db9f7d 100644 --- a/pkg/inference/backends/llamacpp/llamacpp.go +++ b/pkg/inference/backends/llamacpp/llamacpp.go @@ -117,7 +117,7 @@ func (l *llamaCpp) Install(ctx context.Context, httpClient *http.Client) error { // digest to be equal to the one on Docker Hub. llamaCppPath := filepath.Join(l.updatedServerStoragePath, llamaServerBin) if err := l.ensureLatestLlamaCpp(ctx, l.log, httpClient, llamaCppPath, l.vendoredServerStoragePath); err != nil { - l.log.Infof("failed to ensure latest llama.cpp: %v\n", err) + l.log.Info("Failed to ensure latest llama.cpp", "error", err) if !errors.Is(err, errLlamaCppUpToDate) && !errors.Is(err, errLlamaCppUpdateDisabled) { l.status = fmt.Sprintf("failed to install llama.cpp: %v", err) } @@ -129,7 +129,7 @@ func (l *llamaCpp) Install(ctx context.Context, httpClient *http.Client) error { } l.gpuSupported = l.checkGPUSupport(ctx) - l.log.Infof("installed llama-server with gpuSupport=%t", l.gpuSupported) + l.log.Info("installed llama-server", "gpuSupport", l.gpuSupported) return nil } @@ -180,7 +180,7 @@ func (l *llamaCpp) Run(ctx context.Context, socket, model string, _ string, mode SandboxConfig: sandbox.ConfigurationLlamaCpp, Args: args, Logger: l.log, - ServerLogWriter: l.serverLog.Writer(), + ServerLogWriter: logging.NewWriter(l.serverLog), }) } @@ -351,12 +351,12 @@ func (l *llamaCpp) checkGPUSupport(ctx context.Context) bool { "--list-devices", ) if err != nil { - l.log.Warnf("Failed to start sandboxed llama.cpp process to probe GPU support: %v", err) + l.log.Warn("Failed to start sandboxed llama.cpp process to probe GPU support", "error", err) return false } defer llamaCppSandbox.Close() if err := llamaCppSandbox.Command().Wait(); err != nil { - l.log.Warnf("Failed to determine if llama-server is built with GPU support: %v", err) + l.log.Warn("Failed to determine if llama-server is built with GPU support", "error", err) return false } sc := bufio.NewScanner(strings.NewReader(output.String())) diff --git a/pkg/inference/backends/mlx/mlx.go b/pkg/inference/backends/mlx/mlx.go index 6ba3683ed..012347381 100644 --- a/pkg/inference/backends/mlx/mlx.go +++ b/pkg/inference/backends/mlx/mlx.go @@ -102,7 +102,7 @@ func (m *mlx) Install(ctx context.Context, httpClient *http.Client) error { cmd := exec.CommandContext(ctx, pythonPath, "-c", "import mlx_lm") if runErr := cmd.Run(); runErr != nil { m.status = "mlx-lm package not installed" - m.log.Warnf("mlx-lm package not found. Install with: uv pip install mlx-lm") + m.log.Warn("mlx-lm package not found. Install with: uv pip install mlx-lm") return fmt.Errorf("mlx-lm package not installed: %w", runErr) } @@ -110,7 +110,7 @@ func (m *mlx) Install(ctx context.Context, httpClient *http.Client) error { cmd = exec.CommandContext(ctx, pythonPath, "-c", "import mlx; print(mlx.__version__)") output, outputErr := cmd.Output() if outputErr != nil { - m.log.Warnf("could not get MLX version: %v", outputErr) + m.log.Warn("could not get MLX version", "error", outputErr) m.status = "running MLX version: unknown" } else { m.status = fmt.Sprintf("running MLX version: %s", strings.TrimSpace(string(output))) @@ -142,7 +142,7 @@ func (m *mlx) Run(ctx context.Context, socket, model string, modelRef string, mo SandboxConfig: "", Args: args, Logger: m.log, - ServerLogWriter: m.serverLog.Writer(), + ServerLogWriter: logging.NewWriter(m.serverLog), }) } diff --git a/pkg/inference/backends/runner.go b/pkg/inference/backends/runner.go index 186857340..9cab22c56 100644 --- a/pkg/inference/backends/runner.go +++ b/pkg/inference/backends/runner.go @@ -46,9 +46,8 @@ type RunnerConfig struct { // Logger interface for backend logging type Logger interface { - Infof(format string, args ...interface{}) - Warnf(format string, args ...interface{}) - Warnln(args ...interface{}) + Info(msg string, args ...any) + Warn(msg string, args ...any) } // RunBackend runs a backend process with common error handling and logging. @@ -61,8 +60,8 @@ type Logger interface { func RunBackend(ctx context.Context, config RunnerConfig) error { // Remove old socket file if err := os.RemoveAll(config.Socket); err != nil && !errors.Is(err, fs.ErrNotExist) { - config.Logger.Warnf("failed to remove socket file %s: %v\n", config.Socket, err) - config.Logger.Warnln(config.BackendName + " may not be able to start") + config.Logger.Warn("failed to remove socket file", "socket", config.Socket, "error", err) + config.Logger.Warn(config.BackendName + " may not be able to start") } // Sanitize args for safe logging @@ -70,7 +69,7 @@ func RunBackend(ctx context.Context, config RunnerConfig) error { for i, arg := range config.Args { sanitizedArgs[i] = utils.SanitizeForLog(arg, 0) } - config.Logger.Infof("%s args: %v", config.BackendName, sanitizedArgs) + config.Logger.Info("backend args", "backend", config.BackendName, "args", sanitizedArgs) // Create tail buffer for error output tailBuf := tailbuffer.NewTailBuffer(1024) @@ -107,7 +106,7 @@ func RunBackend(ctx context.Context, config RunnerConfig) error { errOutput := new(strings.Builder) if _, err := io.Copy(errOutput, tailBuf); err != nil { - config.Logger.Warnf("failed to read server output tail: %v", err) + config.Logger.Warn("failed to read server output tail", "error", err) } if errOutput.String() != "" { @@ -124,7 +123,7 @@ func RunBackend(ctx context.Context, config RunnerConfig) error { backendErrors <- backendErr close(backendErrors) if err := os.Remove(config.Socket); err != nil && !errors.Is(err, fs.ErrNotExist) { - config.Logger.Warnf("failed to remove socket file %s on exit: %v\n", config.Socket, err) + config.Logger.Warn("failed to remove socket file on exit", "socket", config.Socket, "error", err) } }() defer func() { diff --git a/pkg/inference/backends/sglang/sglang.go b/pkg/inference/backends/sglang/sglang.go index 802c48802..9e08d5e33 100644 --- a/pkg/inference/backends/sglang/sglang.go +++ b/pkg/inference/backends/sglang/sglang.go @@ -111,14 +111,14 @@ func (s *sglang) Install(_ context.Context, _ *http.Client) error { // Check if sglang is installed if err := s.pythonCmd("-c", "import sglang").Run(); err != nil { s.status = "sglang package not installed" - s.log.Warnf("sglang package not found. Install with: uv pip install sglang") + s.log.Warn("sglang package not found. Install with: uv pip install sglang") return ErrSGLangNotFound } // Get version output, err := s.pythonCmd("-c", "import sglang; print(sglang.__version__)").Output() if err != nil { - s.log.Warnf("could not get sglang version: %v", err) + s.log.Warn("could not get sglang version", "error", err) s.status = "running sglang version: unknown" } else { s.status = fmt.Sprintf("running sglang version: %s", strings.TrimSpace(string(output))) @@ -171,7 +171,7 @@ func (s *sglang) Run(ctx context.Context, socket, model string, modelRef string, SandboxConfig: "", Args: args, Logger: s.log, - ServerLogWriter: s.serverLog.Writer(), + ServerLogWriter: logging.NewWriter(s.serverLog), }) } diff --git a/pkg/inference/backends/vllm/vllm.go b/pkg/inference/backends/vllm/vllm.go index 3ec8bf975..f16adcc27 100644 --- a/pkg/inference/backends/vllm/vllm.go +++ b/pkg/inference/backends/vllm/vllm.go @@ -94,7 +94,7 @@ func (v *vLLM) Install(_ context.Context, _ *http.Client) error { versionPath := filepath.Join(filepath.Dir(vllmDir), "version") versionBytes, err := os.ReadFile(versionPath) if err != nil { - v.log.Warnf("could not get vllm version: %v", err) + v.log.Warn("could not get vllm version", "error", err) v.status = "running vllm version: unknown" } else { v.status = fmt.Sprintf("running vllm version: %s", strings.TrimSpace(string(versionBytes))) @@ -158,7 +158,7 @@ func (v *vLLM) Run(ctx context.Context, socket, model string, modelRef string, m SandboxConfig: "", Args: args, Logger: v.log, - ServerLogWriter: v.serverLog.Writer(), + ServerLogWriter: logging.NewWriter(v.serverLog), }) } diff --git a/pkg/inference/backends/vllmmetal/vllmmetal.go b/pkg/inference/backends/vllmmetal/vllmmetal.go index 81ddec6e7..6d3ffb81c 100644 --- a/pkg/inference/backends/vllmmetal/vllmmetal.go +++ b/pkg/inference/backends/vllmmetal/vllmmetal.go @@ -109,7 +109,7 @@ func (v *vllmMetal) Install(ctx context.Context, httpClient *http.Client) error v.pythonPath = pythonPath return v.verifyInstallation(ctx) } - v.log.Infof("vllm-metal version mismatch: installed %s, want %s", installed, vllmMetalVersion) + v.log.Info("vllm-metal version mismatch", "installed", installed, "want", vllmMetalVersion) } } @@ -120,7 +120,7 @@ func (v *vllmMetal) Install(ctx context.Context, httpClient *http.Client) error // Save version file if err := os.WriteFile(versionFile, []byte(vllmMetalVersion), 0644); err != nil { - v.log.Warnf("failed to write version file: %v", err) + v.log.Warn("failed to write version file", "error", err) } v.pythonPath = pythonPath @@ -130,7 +130,7 @@ func (v *vllmMetal) Install(ctx context.Context, httpClient *http.Client) error // downloadAndExtract downloads the vllm-metal image from Docker Hub and extracts it. // The image contains a self-contained Python installation with all packages pre-installed. func (v *vllmMetal) downloadAndExtract(ctx context.Context, _ *http.Client) error { - v.log.Infof("Downloading vllm-metal %s from Docker Hub...", vllmMetalVersion) + v.log.Info("Downloading vllm-metal from Docker Hub...", "version", vllmMetalVersion) // Create temp directory for download downloadDir, err := os.MkdirTemp("", "vllm-metal-install") @@ -160,7 +160,7 @@ func (v *vllmMetal) downloadAndExtract(ctx context.Context, _ *http.Client) erro return fmt.Errorf("failed to remove existing install dir: %w", err) } - v.log.Infof("Extracting self-contained Python environment...") + v.log.Info("Extracting self-contained Python environment...") // Copy the extracted self-contained Python installation directly to install dir // (the image contains /vllm-metal/ with bin/, lib/, etc.) @@ -175,7 +175,7 @@ func (v *vllmMetal) downloadAndExtract(ctx context.Context, _ *http.Client) erro return fmt.Errorf("failed to make python3 executable: %w", err) } - v.log.Infof("vllm-metal %s installed successfully", vllmMetalVersion) + v.log.Info("vllm-metal installed successfully", "version", vllmMetalVersion) return nil } @@ -266,7 +266,7 @@ func (v *vllmMetal) Run(ctx context.Context, socket, model string, modelRef stri SandboxConfig: "", Args: args, Logger: v.log, - ServerLogWriter: v.serverLog.Writer(), + ServerLogWriter: logging.NewWriter(v.serverLog), }) } diff --git a/pkg/inference/models/handler_test.go b/pkg/inference/models/handler_test.go index d8c0d580e..b7f0c34b2 100644 --- a/pkg/inference/models/handler_test.go +++ b/pkg/inference/models/handler_test.go @@ -2,7 +2,7 @@ package models import ( "encoding/json" - "io" + "log/slog" "net/http" "net/http/httptest" "net/url" @@ -15,7 +15,6 @@ import ( reg "github.com/docker/model-runner/pkg/distribution/registry" "github.com/docker/model-runner/pkg/distribution/registry/testregistry" "github.com/docker/model-runner/pkg/inference" - "github.com/sirupsen/logrus" ) // getProjectRoot returns the absolute path to the project root directory @@ -100,10 +99,10 @@ func TestPullModel(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - log := logrus.NewEntry(logrus.StandardLogger()) - manager := NewManager(log.WithFields(logrus.Fields{"component": "model-manager"}), ClientConfig{ + log := slog.Default() + manager := NewManager(log.With("component", "model-manager"), ClientConfig{ StoreRootPath: tempDir, - Logger: log.WithFields(logrus.Fields{"component": "model-manager"}), + Logger: log.With("component", "model-manager"), PlainHTTP: true, }) handler := NewHTTPHandler(log, manager, nil) @@ -207,10 +206,10 @@ func TestHandleGetModel(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - log := logrus.NewEntry(logrus.StandardLogger()) - manager := NewManager(log.WithFields(logrus.Fields{"component": "model-manager"}), ClientConfig{ + log := slog.Default() + manager := NewManager(log.With("component", "model-manager"), ClientConfig{ StoreRootPath: tempDir, - Logger: log.WithFields(logrus.Fields{"component": "model-manager"}), + Logger: log.With("component", "model-manager"), Transport: http.DefaultTransport, UserAgent: "test-agent", PlainHTTP: true, @@ -297,12 +296,10 @@ func TestCors(t *testing.T) { for _, tt := range tests { t.Run(tt.path, func(t *testing.T) { t.Parallel() - discard := logrus.New() - discard.SetOutput(io.Discard) - log := logrus.NewEntry(discard) - manager := NewManager(log.WithFields(logrus.Fields{"component": "model-manager"}), ClientConfig{ + log := slog.Default() + manager := NewManager(log.With("component", "model-manager"), ClientConfig{ StoreRootPath: tempDir, - Logger: log.WithFields(logrus.Fields{"component": "model-manager"}), + Logger: log.With("component", "model-manager"), }) m := NewHTTPHandler(log, manager, []string{"*"}) req := httptest.NewRequest(http.MethodOptions, "http://model-runner.docker.internal"+tt.path, http.NoBody) diff --git a/pkg/inference/models/http_handler.go b/pkg/inference/models/http_handler.go index 861323445..d8eef0143 100644 --- a/pkg/inference/models/http_handler.go +++ b/pkg/inference/models/http_handler.go @@ -8,6 +8,7 @@ import ( "fmt" "html" "io" + "log/slog" "net/http" "path" "strconv" @@ -20,7 +21,6 @@ import ( "github.com/docker/model-runner/pkg/internal/utils" "github.com/docker/model-runner/pkg/logging" "github.com/docker/model-runner/pkg/middleware" - "github.com/sirupsen/logrus" ) // HTTPHandler manages inference model pulls and storage. @@ -42,7 +42,7 @@ type ClientConfig struct { // StoreRootPath is the root path for the model store. StoreRootPath string // Logger is the logger to use. - Logger *logrus.Entry + Logger *slog.Logger // Transport is the HTTP transport to use. Transport http.RoundTripper // UserAgent is the user agent to use. @@ -110,21 +110,21 @@ func (h *HTTPHandler) handleCreateModel(w http.ResponseWriter, r *http.Request) if err := h.manager.Pull(request.From, request.BearerToken, r, w); err != nil { sanitizedFrom := utils.SanitizeForLog(request.From, -1) if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) { - h.log.Infof("Request canceled/timed out while pulling model %q", sanitizedFrom) + h.log.Info("Request canceled/timed out while pulling model", "model", sanitizedFrom) return } if errors.Is(err, registry.ErrInvalidReference) { - h.log.Warnf("Invalid model reference %q: %v", sanitizedFrom, err) + h.log.Warn("Invalid model reference", "model", sanitizedFrom, "error", err) http.Error(w, "Invalid model reference", http.StatusBadRequest) return } if errors.Is(err, registry.ErrUnauthorized) { - h.log.Warnf("Unauthorized to pull model %q: %v", sanitizedFrom, err) + h.log.Warn("Unauthorized to pull model", "model", sanitizedFrom, "error", err) http.Error(w, "Unauthorized", http.StatusUnauthorized) return } if errors.Is(err, registry.ErrModelNotFound) { - h.log.Warnf("Failed to pull model %q: %v", sanitizedFrom, err) + h.log.Warn("Failed to pull model", "model", sanitizedFrom, "error", err) http.Error(w, "Model not found", http.StatusNotFound) return } @@ -167,7 +167,7 @@ func (h *HTTPHandler) handleExportModel(w http.ResponseWriter, r *http.Request, http.Error(w, err.Error(), http.StatusNotFound) return } - h.log.Warnln("Error while exporting model:", err) + h.log.Warn("error while exporting model", "error", err) http.Error(w, err.Error(), http.StatusInternalServerError) return } @@ -184,7 +184,7 @@ func (h *HTTPHandler) handleGetModels(w http.ResponseWriter, r *http.Request) { // Write the response. w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(apiModels); err != nil { - h.log.Warnln("Error while encoding model listing response:", err) + h.log.Warn("error while encoding model listing response", "error", err) } } @@ -200,7 +200,7 @@ func (h *HTTPHandler) handleGetModelByRef(w http.ResponseWriter, r *http.Request if r.URL.Query().Has("remote") { val, err := strconv.ParseBool(r.URL.Query().Get("remote")) if err != nil { - h.log.Warnln("Error while parsing remote query parameter:", err) + h.log.Warn("error while parsing remote query parameter", "error", err) } else { remote = val } @@ -225,7 +225,7 @@ func (h *HTTPHandler) handleGetModelByRef(w http.ResponseWriter, r *http.Request // Write the response. w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(apiModel); err != nil { - h.log.Warnln("Error while encoding model response:", err) + h.log.Warn("error while encoding model response", "error", err) } } @@ -312,7 +312,7 @@ func (h *HTTPHandler) handleDeleteModel(w http.ResponseWriter, r *http.Request) var force bool if r.URL.Query().Has("force") { if val, err := strconv.ParseBool(r.URL.Query().Get("force")); err != nil { - h.log.Warnln("Error while parsing force query parameter:", err) + h.log.Warn("error while parsing force query parameter", "error", err) } else { force = val } @@ -329,7 +329,7 @@ func (h *HTTPHandler) handleDeleteModel(w http.ResponseWriter, r *http.Request) http.Error(w, err.Error(), http.StatusConflict) return } - h.log.Warnln("Error while deleting model:", err) + h.log.Warn("error while deleting model", "error", err) http.Error(w, err.Error(), http.StatusInternalServerError) return } @@ -359,7 +359,7 @@ func (h *HTTPHandler) handleOpenAIGetModels(w http.ResponseWriter, r *http.Reque // Write the response. w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(models); err != nil { - h.log.Warnln("Error while encoding OpenAI model listing response:", err) + h.log.Warn("error while encoding OpenAI model listing response", "error", err) } } @@ -385,7 +385,7 @@ func (h *HTTPHandler) handleOpenAIGetModel(w http.ResponseWriter, r *http.Reques return } if err := json.NewEncoder(w).Encode(openaiModel); err != nil { - h.log.Warnln("Error while encoding OpenAI model response:", err) + h.log.Warn("error while encoding OpenAI model response", "error", err) } } @@ -445,7 +445,7 @@ func (h *HTTPHandler) handleTagModel(w http.ResponseWriter, r *http.Request, mod "target": target, } if err := json.NewEncoder(w).Encode(response); err != nil { - h.log.Warnln("Error while encoding tag response:", err) + h.log.Warn("error while encoding tag response", "error", err) } } @@ -468,17 +468,17 @@ func (h *HTTPHandler) handlePushModel(w http.ResponseWriter, r *http.Request, mo if err := h.manager.Push(model, req.BearerToken, r, w); err != nil { if errors.Is(err, distribution.ErrInvalidReference) { - h.log.Warnf("Invalid model reference %q: %v", utils.SanitizeForLog(model, -1), err) + h.log.Warn("Invalid model reference", "model", utils.SanitizeForLog(model, -1), "error", err) http.Error(w, "Invalid model reference", http.StatusBadRequest) return } if errors.Is(err, distribution.ErrModelNotFound) { - h.log.Warnf("Failed to push model %q: %v", utils.SanitizeForLog(model, -1), err) + h.log.Warn("Failed to push model", "model", utils.SanitizeForLog(model, -1), "error", err) http.Error(w, "Model not found", http.StatusNotFound) return } if errors.Is(err, registry.ErrUnauthorized) { - h.log.Warnf("Unauthorized to push model %q: %v", utils.SanitizeForLog(model, -1), err) + h.log.Warn("Unauthorized to push model", "model", utils.SanitizeForLog(model, -1), "error", err) http.Error(w, "Unauthorized", http.StatusUnauthorized) return } @@ -513,7 +513,7 @@ func (h *HTTPHandler) handleRepackageModel(w http.ResponseWriter, r *http.Reques http.Error(w, err.Error(), http.StatusNotFound) return } - h.log.Warnf("Failed to repackage model %q: %v", utils.SanitizeForLog(model, -1), err) + h.log.Warn("Failed to repackage model", "model", utils.SanitizeForLog(model, -1), "error", err) http.Error(w, err.Error(), http.StatusInternalServerError) return } @@ -526,7 +526,7 @@ func (h *HTTPHandler) handleRepackageModel(w http.ResponseWriter, r *http.Reques "target": req.Target, } if err := json.NewEncoder(w).Encode(response); err != nil { - h.log.Warnln("Error while encoding repackage response:", err) + h.log.Warn("error while encoding repackage response", "error", err) } } @@ -534,7 +534,7 @@ func (h *HTTPHandler) handleRepackageModel(w http.ResponseWriter, r *http.Reques func (h *HTTPHandler) handlePurge(w http.ResponseWriter, _ *http.Request) { err := h.manager.Purge() if err != nil { - h.log.Warnf("Failed to purge models: %v", err) + h.log.Warn("Failed to purge models", "error", err) http.Error(w, err.Error(), http.StatusInternalServerError) return } diff --git a/pkg/inference/models/manager.go b/pkg/inference/models/manager.go index 75cc2aee7..e0e0408d0 100644 --- a/pkg/inference/models/manager.go +++ b/pkg/inference/models/manager.go @@ -52,7 +52,7 @@ func NewManager(log logging.Logger, c ClientConfig) *Manager { distribution.WithRegistryClient(registryClient), ) if err != nil { - log.Errorf("Failed to create distribution client: %v", err) + log.Error("Failed to create distribution client", "error", err) // Continue without distribution client. The model manager will still // respond to requests, but may return errors if the client is required. } @@ -92,13 +92,13 @@ func (m *Manager) ResolveID(modelRef string) string { sanitizedModelRef := utils.SanitizeForLog(modelRef, -1) model, err := m.GetLocal(sanitizedModelRef) if err != nil { - m.log.Warnf("Failed to resolve model ref %s to ID: %v", sanitizedModelRef, err) + m.log.Warn("Failed to resolve model ref to ID", "model", sanitizedModelRef, "error", err) return sanitizedModelRef } modelID, err := model.ID() if err != nil { - m.log.Warnf("Failed to get model ID for ref %s: %v", sanitizedModelRef, err) + m.log.Warn("Failed to get model ID for ref", "model", sanitizedModelRef, "error", err) return sanitizedModelRef } @@ -172,7 +172,7 @@ func (m *Manager) List() ([]*Model, error) { for _, model := range models { apiModel, err := ToModel(model) if err != nil { - m.log.Warnf("error while converting model, skipping: %v", err) + m.log.Warn("error while converting model, skipping", "error", err) continue } apiModels = append(apiModels, apiModel) @@ -248,12 +248,12 @@ func (m *Manager) Pull(model string, bearerToken string, r *http.Request, w http } // Pull the model using the Docker model distribution client - m.log.Infoln("Pulling model:", utils.SanitizeForLog(model, -1)) + m.log.Info("pulling model", "model", utils.SanitizeForLog(model, -1)) // Use bearer token if provided var err error if bearerToken != "" { - m.log.Infoln("Using provided bearer token for authentication") + m.log.Info("Using provided bearer token for authentication") err = m.distributionClient.PullModel(r.Context(), model, progressWriter, bearerToken) } else { err = m.distributionClient.PullModel(r.Context(), model, progressWriter) @@ -300,7 +300,7 @@ func (m *Manager) Tag(ref, target string) error { for _, mModel := range models { modelID, idErr := mModel.ID() if idErr != nil { - m.log.Warnf("Failed to get model ID: %v", idErr) + m.log.Warn("Failed to get model ID", "error", idErr) continue } @@ -359,7 +359,7 @@ func (m *Manager) Tag(ref, target string) error { // Now tag using the found model reference (the matching tag) if tagErr := m.distributionClient.Tag(foundModelRef, target); tagErr != nil { - m.log.Warnf("Failed to apply tag %q to resolved model %q: %v", utils.SanitizeForLog(target, -1), utils.SanitizeForLog(foundModelRef, -1), tagErr) + m.log.Warn("Failed to apply tag to resolved model", "target", utils.SanitizeForLog(target, -1), "model", utils.SanitizeForLog(foundModelRef, -1), "error", tagErr) return fmt.Errorf("error while tagging model: %w", tagErr) } } else if err != nil { @@ -400,7 +400,7 @@ func (m *Manager) Push(model string, bearerToken string, r *http.Request, w http var err error if bearerToken != "" { - m.log.Infoln("Using provided bearer token for push authentication") + m.log.Info("Using provided bearer token for push authentication") err = m.distributionClient.PushModel(r.Context(), model, progressWriter, bearerToken) } else { err = m.distributionClient.PushModel(r.Context(), model, progressWriter) @@ -417,7 +417,7 @@ func (m *Manager) Purge() error { return fmt.Errorf("model distribution service unavailable") } if err := m.distributionClient.ResetStore(); err != nil { - m.log.Warnf("Failed to purge models: %v", err) + m.log.Warn("Failed to purge models", "error", err) return fmt.Errorf("error while purging models: %w", err) } return nil diff --git a/pkg/inference/scheduling/http_handler.go b/pkg/inference/scheduling/http_handler.go index 90050cac8..a9f3077b9 100644 --- a/pkg/inference/scheduling/http_handler.go +++ b/pkg/inference/scheduling/http_handler.go @@ -448,7 +448,7 @@ func (h *HTTPHandler) Configure(w http.ResponseWriter, r *http.Request) { go func() { preloadBody, err := json.Marshal(OpenAIInferenceRequest{Model: configureRequest.Model}) if err != nil { - h.scheduler.log.Warnf("failed to marshal preload request body: %v", err) + h.scheduler.log.Warn("failed to marshal preload request body", "error", err) return } ctx, cancel := context.WithTimeout(context.Background(), time.Minute) @@ -460,7 +460,7 @@ func (h *HTTPHandler) Configure(w http.ResponseWriter, r *http.Request) { bytes.NewReader(preloadBody), ) if err != nil { - h.scheduler.log.Warnf("failed to create preload request: %v", err) + h.scheduler.log.Warn("failed to create preload request", "error", err) return } preloadReq.Header.Set("User-Agent", r.UserAgent()) @@ -470,7 +470,7 @@ func (h *HTTPHandler) Configure(w http.ResponseWriter, r *http.Request) { recorder := httptest.NewRecorder() h.handleOpenAIInference(recorder, preloadReq) if recorder.Code != http.StatusOK { - h.scheduler.log.Warnf("background model preload failed with status %d: %s", recorder.Code, recorder.Body.String()) + h.scheduler.log.Warn("background model preload failed", "status", recorder.Code, "body", recorder.Body.String()) } }() diff --git a/pkg/inference/scheduling/installer.go b/pkg/inference/scheduling/installer.go index 8703ad031..a41448831 100644 --- a/pkg/inference/scheduling/installer.go +++ b/pkg/inference/scheduling/installer.go @@ -141,7 +141,7 @@ func (i *installer) run(ctx context.Context) { continue } if err := backend.Install(ctx, i.httpClient); err != nil { - i.log.Warnf("Backend installation failed for %s: %v", name, err) + i.log.Warn("Backend installation failed for", "backend", name, "error", err) select { case <-ctx.Done(): status.err = errors.Join(errInstallerShuttingDown, ctx.Err()) diff --git a/pkg/inference/scheduling/loader.go b/pkg/inference/scheduling/loader.go index 6a69b0ba2..d08aaa23e 100644 --- a/pkg/inference/scheduling/loader.go +++ b/pkg/inference/scheduling/loader.go @@ -233,21 +233,17 @@ func (l *loader) evict(idleOnly bool) int { default: } if unused && (!idleOnly || idle || defunct) && (!idleOnly || !neverEvict || defunct) { - l.log.Infof("Evicting %s backend runner with model %s (%s) in %s mode", - r.backend, r.modelID, runnerInfo.modelRef, r.mode, - ) + l.log.Info("Evicting backend runner", "backend", r.backend, "model", r.modelID, "modelRef", runnerInfo.modelRef, "mode", r.mode) l.freeRunnerSlot(runnerInfo.slot, r) evictedCount++ } else if unused { - l.log.Debugf("Runner %s (%s) is unused but not evictable: idleOnly=%v, idle=%v, defunct=%v, neverEvict=%v", - r.modelID, runnerInfo.modelRef, idleOnly, idle, defunct, neverEvict) + l.log.Debug("Runner is unused but not evictable", "modelID", r.modelID, "modelRef", runnerInfo.modelRef, "idleOnly", idleOnly, "idle", idle, "defunct", defunct, "neverEvict", neverEvict) } else { - l.log.Debugf("Runner %s (%s) is in use with %d references, cannot evict", - r.modelID, runnerInfo.modelRef, l.references[runnerInfo.slot]) + l.log.Debug("Runner is in use with references, cannot evict", "modelID", r.modelID, "modelRef", runnerInfo.modelRef, "references", l.references[runnerInfo.slot]) } } if evictedCount > 0 { - l.log.Infof("Evicted %d runner(s)", evictedCount) + l.log.Info("Evicted runner(s)", "count", evictedCount) } return len(l.runners) } @@ -260,16 +256,13 @@ func (l *loader) evictRunner(backend, model string, mode inference.BackendMode) for r, runnerInfo := range l.runners { unused := l.references[runnerInfo.slot] == 0 if unused && (allBackends || r.backend == backend) && r.modelID == model && r.mode == mode { - l.log.Infof("Evicting %s backend runner with model %s (%s) in %s mode", - r.backend, r.modelID, runnerInfo.modelRef, r.mode, - ) + l.log.Info("Evicting backend runner", "backend", r.backend, "model", r.modelID, "modelRef", runnerInfo.modelRef, "mode", r.mode) l.freeRunnerSlot(runnerInfo.slot, r) found = true } } if !found { - l.log.Warnf("No unused runner found for backend=%s, model=%s, mode=%s", - utils.SanitizeForLog(backend), utils.SanitizeForLog(model), utils.SanitizeForLog(string(mode))) + l.log.Warn("No unused runner found", "backend", utils.SanitizeForLog(backend), "model", utils.SanitizeForLog(model), "mode", utils.SanitizeForLog(string(mode))) } return len(l.runners) } @@ -452,7 +445,7 @@ func (l *loader) load(ctx context.Context, backendName, modelID, modelRef string defaultConfig := inference.BackendConfiguration{} if l.modelManager != nil { if bundle, err := l.modelManager.GetBundle(modelID); err != nil { - l.log.Warnf("Failed to get bundle for model %s to determine default context size: %v", modelID, err) + l.log.Warn("Failed to get bundle for model to determine default context size", "model", modelID, "error", err) } else if runtimeConfig := bundle.RuntimeConfig(); runtimeConfig != nil { if ctxSize := runtimeConfig.GetContextSize(); ctxSize != nil { defaultConfig.ContextSize = ctxSize @@ -462,7 +455,7 @@ func (l *loader) load(ctx context.Context, backendName, modelID, modelRef string runnerConfig = &defaultConfig } - l.log.Infof("Loading %s backend runner with model %s in %s mode", backendName, modelID, mode) + l.log.Info("Loading backend runner", "backend", backendName, "model", modelID, "mode", mode) // Acquire the loader lock and defer its release. if !l.lock(ctx) { @@ -492,7 +485,7 @@ func (l *loader) load(ctx context.Context, backendName, modelID, modelRef string if ok { select { case <-l.slots[existing.slot].done: - l.log.Warnf("%s runner for %s is defunct. Waiting for it to be evicted.", backendName, existing.modelRef) + l.log.Warn("Runner is defunct, waiting for eviction", "backend", backendName, "model", existing.modelRef) if l.references[existing.slot] == 0 { l.evictRunner(backendName, modelID, mode) // Continue the loop to retry loading after evicting the defunct runner @@ -509,8 +502,7 @@ func (l *loader) load(ctx context.Context, backendName, modelID, modelRef string // If all slots are full, try evicting unused runners. if len(l.runners) == len(l.slots) { - l.log.Infof("Evicting to make room: %d/%d slots used", - len(l.runners), len(l.slots)) + l.log.Info("Evicting to make room", "runners", len(l.runners), "slots", len(l.slots)) runnerCountAtLoopStart := len(l.runners) remainingRunners := l.evict(false) // Restart the loop if eviction happened @@ -530,8 +522,7 @@ func (l *loader) load(ctx context.Context, backendName, modelID, modelRef string } if slot < 0 { - l.log.Debugf("Cannot load model yet: %d/%d slots used", - len(l.runners), len(l.slots)) + l.log.Debug("Cannot load model yet", "runners", len(l.runners), "slots", len(l.slots)) } // If we've identified a slot, then we're ready to start a runner. @@ -539,9 +530,7 @@ func (l *loader) load(ctx context.Context, backendName, modelID, modelRef string // Create the runner. runner, err := run(l.log, backend, modelID, modelRef, mode, slot, runnerConfig, l.openAIRecorder) if err != nil { - l.log.Warnf("Unable to start %s backend runner with model %s in %s mode: %v", - backendName, modelID, mode, err, - ) + l.log.Warn("Unable to start backend runner", "backend", backendName, "model", modelID, "mode", mode, "error", err) return nil, fmt.Errorf("unable to start runner: %w", err) } @@ -553,9 +542,7 @@ func (l *loader) load(ctx context.Context, backendName, modelID, modelRef string // deduplication of runners and keep slot / memory reservations. if err := runner.wait(ctx); err != nil { runner.terminate() - l.log.Warnf("Initialization for %s backend runner with model %s in %s mode failed: %v", - backendName, modelID, mode, err, - ) + l.log.Warn("Backend runner initialization failed", "backend", backendName, "model", modelID, "mode", mode, "error", err) return nil, fmt.Errorf("error waiting for runner to be ready: %w", err) } @@ -628,7 +615,7 @@ func (l *loader) setRunnerConfig(ctx context.Context, backendName, modelID strin // If the configuration hasn't changed, then just return. if existingConfig, ok := l.runnerConfigs[configKey]; ok && reflect.DeepEqual(runnerConfig, existingConfig) { - l.log.Infof("Configuration for %s runner for modelID %s unchanged", backendName, modelID) + l.log.Info("Runner configuration unchanged", "backend", backendName, "model", modelID) return nil } @@ -651,7 +638,7 @@ func (l *loader) setRunnerConfig(ctx context.Context, backendName, modelID strin return errRunnerAlreadyActive } - l.log.Infof("Configuring %s runner for %s", backendName, modelID) + l.log.Info("Configuring runner", "backend", backendName, "model", modelID) l.runnerConfigs[configKey] = runnerConfig return nil } diff --git a/pkg/inference/scheduling/loader_test.go b/pkg/inference/scheduling/loader_test.go index fe79744bd..9120fba6e 100644 --- a/pkg/inference/scheduling/loader_test.go +++ b/pkg/inference/scheduling/loader_test.go @@ -4,12 +4,12 @@ import ( "context" "errors" "io" + "log/slog" "net/http" "testing" "time" "github.com/docker/model-runner/pkg/inference" - "github.com/sirupsen/logrus" ) // mockBackend is a minimal backend implementation for testing @@ -55,10 +55,8 @@ func (b *fastFailBackend) Run(ctx context.Context, socket, model string, modelRe } // createTestLogger creates a logger for testing -func createTestLogger() *logrus.Entry { - log := logrus.New() - log.SetOutput(io.Discard) - return logrus.NewEntry(log) +func createTestLogger() *slog.Logger { + return slog.Default() } // Test memory size constants @@ -68,7 +66,7 @@ const ( // createDefunctMockRunner creates a mock runner with a closed done channel, // simulating a defunct (crashed/terminated) runner for testing -func createDefunctMockRunner(ctx context.Context, log *logrus.Entry, backend inference.Backend) *runner { +func createDefunctMockRunner(ctx context.Context, log *slog.Logger, backend inference.Backend) *runner { defunctRunnerDone := make(chan struct{}) _, defunctRunnerCancel := context.WithCancel(ctx) @@ -97,7 +95,7 @@ func createDefunctMockRunner(ctx context.Context, log *logrus.Entry, backend inf // createAliveTerminableMockRunner creates a mock runner with an open done channel // (i.e., not defunct) that will close when cancel is invoked, so terminate() returns. -func createAliveTerminableMockRunner(ctx context.Context, log *logrus.Entry, backend inference.Backend) *runner { +func createAliveTerminableMockRunner(ctx context.Context, log *slog.Logger, backend inference.Backend) *runner { runCtx, cancel := context.WithCancel(ctx) done := make(chan struct{}) diff --git a/pkg/inference/scheduling/runner.go b/pkg/inference/scheduling/runner.go index 710a538f8..962aba66a 100644 --- a/pkg/inference/scheduling/runner.go +++ b/pkg/inference/scheduling/runner.go @@ -140,7 +140,7 @@ func run( return nil } proxy.Transport = transport - proxyLog := log.Writer() + proxyLog := logging.NewWriter(log) proxy.ErrorLog = logpkg.New(proxyLog, "", 0) // Create a cancellable context to regulate the runner's backend run loop @@ -192,15 +192,13 @@ func run( if r.openAIRecorder != nil { r.openAIRecorder.SetConfigForModel(modelID, runnerConfig) } else { - r.log.Warnf("OpenAI recorder is nil for model %s", modelID) + r.log.Warn("OpenAI recorder is nil for model", "model", modelID) } // Start the backend run loop. go func() { if err := backend.Run(runCtx, socket, modelID, modelRef, mode, runnerConfig); err != nil { - log.Warnf("Backend %s running model %s exited with error: %v", - backend.Name(), utils.SanitizeForLog(modelRef), err, - ) + log.Warn("Backend running model exited with error", "backend", backend.Name(), "model", utils.SanitizeForLog(modelRef), "error", err) r.err = err } close(runDone) @@ -266,13 +264,13 @@ func (r *runner) terminate() { // Close the proxy's log. if err := r.proxyLog.Close(); err != nil { - r.log.Warnf("Unable to close reverse proxy log writer: %v", err) + r.log.Warn("Unable to close reverse proxy log writer", "error", err) } if r.openAIRecorder != nil { r.openAIRecorder.RemoveModel(r.model) } else { - r.log.Warnf("OpenAI recorder is nil for model %s", r.model) + r.log.Warn("OpenAI recorder is nil for model", "model", r.model) } } diff --git a/pkg/inference/scheduling/scheduler.go b/pkg/inference/scheduling/scheduler.go index dd918478b..cef6b6b9b 100644 --- a/pkg/inference/scheduling/scheduler.go +++ b/pkg/inference/scheduling/scheduler.go @@ -59,7 +59,7 @@ func NewScheduler( tracker *metrics.Tracker, deferredBackends []string, ) *Scheduler { - openAIRecorder := metrics.NewOpenAIRecorder(log.WithField("component", "openai-recorder"), modelManager) + openAIRecorder := metrics.NewOpenAIRecorder(log.With("component", "openai-recorder"), modelManager) // Create the scheduler. s := &Scheduler{ @@ -107,7 +107,7 @@ func (s *Scheduler) Run(ctx context.Context) error { func (s *Scheduler) selectBackendForModel(model types.Model, backend inference.Backend, modelRef string) inference.Backend { config, err := model.Config() if err != nil { - s.log.Warnln("failed to fetch model config:", err) + s.log.Warn("failed to fetch model config", "error", err) return backend } @@ -118,8 +118,8 @@ func (s *Scheduler) selectBackendForModel(model types.Model, backend inference.B if s.installer.isInstalled(vllmmetal.Name) { return vllmMetalBackend } - s.log.Infof("vllm-metal backend is available but not installed. "+ - "To install, run: docker model install-runner --backend %s", vllmmetal.Name) + s.log.Info("vllm-metal backend is available but not installed", + "backend", vllmmetal.Name) return vllmMetalBackend } // Fall back to MLX on macOS @@ -134,9 +134,8 @@ func (s *Scheduler) selectBackendForModel(model types.Model, backend inference.B if sglangBackend, ok := s.backends[sglang.Name]; ok && sglangBackend != nil { return sglangBackend } - s.log.Warnf("Model %s is in safetensors format but no compatible backend is available. "+ - "Backend %s may not support this format and could fail at runtime.", - utils.SanitizeForLog(modelRef), backend.Name()) + s.log.Warn("Model is in safetensors format but no compatible backend is available", + "model", utils.SanitizeForLog(modelRef), "backend", backend.Name()) } return backend @@ -205,7 +204,7 @@ func (s *Scheduler) GetAllActiveRunners() []metrics.ActiveRunner { for _, backend := range runningBackends { mode, ok := inference.ParseBackendMode(backend.Mode) if !ok { - s.log.Warnf("Unknown backend mode %q, defaulting to completion.", backend.Mode) + s.log.Warn("Unknown backend mode, defaulting to completion", "mode", backend.Mode) } // Find the runner slot for this backend/model combination // We iterate through all runners since we don't know the draftModelID @@ -213,7 +212,7 @@ func (s *Scheduler) GetAllActiveRunners() []metrics.ActiveRunner { if key.backend == backend.BackendName && key.modelID == backend.ModelName && key.mode == mode { socket, err := RunnerSocketPath(runnerInfo.slot) if err != nil { - s.log.Warnf("Failed to get socket path for runner %s/%s (%s): %v", backend.BackendName, backend.ModelName, key.modelID, err) + s.log.Warn("Failed to get socket path for runner", "backend", backend.BackendName, "model", backend.ModelName, "modelID", key.modelID, "error", err) continue } @@ -245,7 +244,7 @@ func (s *Scheduler) GetLlamaCppSocket() (string, error) { if backend.BackendName == llamacpp.Name { mode, ok := inference.ParseBackendMode(backend.Mode) if !ok { - s.log.Warnf("Unknown backend mode %q, defaulting to completion.", backend.Mode) + s.log.Warn("Unknown backend mode, defaulting to completion", "mode", backend.Mode) } // Find the runner slot for this backend/model combination // We iterate through all runners since we don't know the draftModelID @@ -335,7 +334,7 @@ func (s *Scheduler) ConfigureRunner(ctx context.Context, backend inference.Backe // Set the runner configuration if err := s.loader.setRunnerConfig(ctx, backend.Name(), modelID, mode, runnerConfig); err != nil { - s.log.Warnf("Failed to configure %s runner for %s (%s): %s", backend.Name(), utils.SanitizeForLog(req.Model, -1), modelID, err) + s.log.Warn("Failed to configure runner", "backend", backend.Name(), "model", utils.SanitizeForLog(req.Model, -1), "modelID", modelID, "error", err) return nil, err } diff --git a/pkg/inference/scheduling/scheduler_test.go b/pkg/inference/scheduling/scheduler_test.go index 0c1d4a71b..58520278d 100644 --- a/pkg/inference/scheduling/scheduler_test.go +++ b/pkg/inference/scheduling/scheduler_test.go @@ -1,12 +1,10 @@ package scheduling import ( - "io" + "log/slog" "net/http" "net/http/httptest" "testing" - - "github.com/sirupsen/logrus" ) func TestCors(t *testing.T) { @@ -30,9 +28,7 @@ func TestCors(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { t.Parallel() - discard := logrus.New() - discard.SetOutput(io.Discard) - log := logrus.NewEntry(discard) + log := slog.Default() s := NewScheduler(log, nil, nil, nil, nil, nil, nil) httpHandler := NewHTTPHandler(s, nil, []string{"*"}) req := httptest.NewRequest(http.MethodOptions, "http://model-runner.docker.internal"+tt.path, http.NoBody) diff --git a/pkg/internal/dockerhub/download.go b/pkg/internal/dockerhub/download.go index 800b1c6bb..d48091d8c 100644 --- a/pkg/internal/dockerhub/download.go +++ b/pkg/internal/dockerhub/download.go @@ -5,7 +5,7 @@ import ( "encoding/base64" "errors" "fmt" - "log" + "log/slog" "os" "path/filepath" "strings" @@ -20,7 +20,6 @@ import ( "github.com/containerd/platforms" "github.com/docker/model-runner/pkg/internal/jsonutil" v1 "github.com/opencontainers/image-spec/specs-go/v1" - "github.com/sirupsen/logrus" ) func PullPlatform(ctx context.Context, image, destination, requiredOs, requiredArch string) error { @@ -52,7 +51,7 @@ func retry(ctx context.Context, attempts int, sleep time.Duration, f func() (*v1 var result *v1.Descriptor for i := 0; i < attempts; i++ { if i > 0 { - log.Printf("retry %d after error: %v\n", i, err) + slog.Info("retrying after error", "attempt", i, "error", err) select { case <-ctx.Done(): return nil, ctx.Err() @@ -100,7 +99,7 @@ func dockerCredentials(host string) (string, string, error) { if hubUsername != "" && hubPassword != "" { return hubUsername, hubPassword, nil } - logrus.WithField("host", host).Debug("checking for registry auth config") + slog.Debug("checking for registry auth config", "host", host) home, err := os.UserHomeDir() if err != nil { return "", "", err @@ -125,10 +124,10 @@ func dockerCredentials(host string) (string, string, error) { } parts := strings.SplitN(string(creds), ":", 2) if len(parts) != 2 { - logrus.Debugf("skipping not user/password auth for registry %s: %s", host, parts[0]) + slog.Debug("skipping non-user/password auth for registry", "host", host, "auth_type", parts[0]) return "", "", nil } - logrus.Debugf("using auth for registry %s: user=%s", host, parts[0]) + slog.Debug("using auth for registry", "host", host, "user", parts[0]) return parts[0], parts[1], nil } } diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go index aacc31bac..399628ec6 100644 --- a/pkg/logging/logging.go +++ b/pkg/logging/logging.go @@ -1,14 +1,78 @@ package logging import ( + "bufio" + "context" "io" - - "github.com/sirupsen/logrus" + "log/slog" + "os" + "strings" ) -// Logger is a bridging interface between logrus and Docker Desktop's internal -// logging types. -type Logger interface { - logrus.FieldLogger - Writer() *io.PipeWriter +// Logger is the application logger type, backed by slog. +type Logger = *slog.Logger + +// ParseLevel parses a log level string into slog.Level. +// Supported values: debug, info, warn, error (case-insensitive). +// Defaults to info if the value is unrecognized. +func ParseLevel(s string) slog.Level { + switch strings.ToLower(strings.TrimSpace(s)) { + case "debug": + return slog.LevelDebug + case "info", "": + return slog.LevelInfo + case "warn", "warning": + return slog.LevelWarn + case "error": + return slog.LevelError + default: + return slog.LevelInfo + } +} + +// NewLogger creates a new slog.Logger with a text handler at the given level. +func NewLogger(level slog.Level) *slog.Logger { + return slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{ + Level: level, + })) +} + +// slogWriter is an io.WriteCloser that forwards each line to a slog.Logger. +type slogWriter struct { + logger *slog.Logger + pr *io.PipeReader + pw *io.PipeWriter + done chan struct{} +} + +// NewWriter returns an io.WriteCloser that logs each line written to it +// using the provided slog.Logger at Info level. +func NewWriter(logger *slog.Logger) io.WriteCloser { + pr, pw := io.Pipe() + sw := &slogWriter{ + logger: logger, + pr: pr, + pw: pw, + done: make(chan struct{}), + } + go sw.scan() + return sw +} + +func (sw *slogWriter) scan() { + defer close(sw.done) + scanner := bufio.NewScanner(sw.pr) + for scanner.Scan() { + sw.logger.Log(context.Background(), slog.LevelInfo, scanner.Text()) + } +} + +func (sw *slogWriter) Write(p []byte) (int, error) { + return sw.pw.Write(p) +} + +func (sw *slogWriter) Close() error { + err := sw.pw.Close() + <-sw.done + return err } diff --git a/pkg/metrics/aggregated_handler.go b/pkg/metrics/aggregated_handler.go index 8f24b1960..442c447c0 100644 --- a/pkg/metrics/aggregated_handler.go +++ b/pkg/metrics/aggregated_handler.go @@ -65,7 +65,7 @@ func (h *AggregatedMetricsHandler) collectAndAggregateMetrics(ctx context.Contex families, err := h.fetchRunnerMetrics(ctx, runner) if err != nil { - h.log.Warnf("Failed to fetch metrics from runner %s/%s: %v", runner.BackendName, runner.ModelName, err) + h.log.Warn("Failed to fetch metrics from runner /", "backend", runner.BackendName, "model", runner.ModelName, "error", err) return } @@ -165,7 +165,7 @@ func (h *AggregatedMetricsHandler) writeAggregatedMetrics(w http.ResponseWriter, encoder := expfmt.NewEncoder(w, expfmt.NewFormat(expfmt.TypeTextPlain)) for _, family := range families { if err := encoder.Encode(family); err != nil { - h.log.Errorf("Failed to encode metric family %s: %v", *family.Name, err) + h.log.Error("Failed to encode metric family", "family", *family.Name, "error", err) continue } } diff --git a/pkg/metrics/metrics.go b/pkg/metrics/metrics.go index f892cd278..05cceda4c 100644 --- a/pkg/metrics/metrics.go +++ b/pkg/metrics/metrics.go @@ -14,7 +14,6 @@ import ( "github.com/docker/model-runner/pkg/distribution/types" "github.com/docker/model-runner/pkg/internal/utils" "github.com/docker/model-runner/pkg/logging" - "github.com/sirupsen/logrus" ) type Tracker struct { @@ -49,13 +48,7 @@ func NewTracker(httpClient *http.Client, log logging.Logger, userAgent string, d userAgent = userAgent + " docker-model-runner" } - if os.Getenv("DEBUG") == "1" { - if logger, ok := log.(*logrus.Logger); ok { - logger.SetLevel(logrus.DebugLevel) - } else if entry, ok := log.(*logrus.Entry); ok { - entry.Logger.SetLevel(logrus.DebugLevel) - } - } + // Debug level is now configured via LOG_LEVEL environment variable return &Tracker{ doNotTrack: os.Getenv("DO_NOT_TRACK") == "1" || doNotTrack, @@ -75,7 +68,7 @@ func (t *Tracker) TrackModel(model types.Model, userAgent, action string) { func (t *Tracker) trackModel(model types.Model, userAgent, action string) { tags := model.Tags() - t.log.Debugln("Tracking model:", tags) + t.log.Debug("tracking model", "tags", tags) if len(tags) == 0 { return } @@ -90,14 +83,14 @@ func (t *Tracker) trackModel(model types.Model, userAgent, action string) { for _, tag := range tags { ref, err := reference.ParseReference(tag, registry.GetDefaultRegistryOptions()...) if err != nil { - t.log.Errorf("Error parsing reference: %v\n", err) + t.log.Error("error parsing reference", "error", err) return } if err = t.headManifest(ref, ua); err != nil { - t.log.Debugf("Manifest does not exist or error occurred: %v\n", err) + t.log.Debug("manifest does not exist or error occurred", "error", err) continue } - t.log.Debugln("Tracked", utils.SanitizeForLog(ref.Name(), -1), utils.SanitizeForLog(ref.Identifier(), -1), "with user agent:", utils.SanitizeForLog(ua, -1)) + t.log.Debug("tracked", "name", utils.SanitizeForLog(ref.Name(), -1), "identifier", utils.SanitizeForLog(ref.Identifier(), -1), "userAgent", utils.SanitizeForLog(ua, -1)) } } diff --git a/pkg/metrics/openai_recorder.go b/pkg/metrics/openai_recorder.go index b1a31dee3..de6c146a4 100644 --- a/pkg/metrics/openai_recorder.go +++ b/pkg/metrics/openai_recorder.go @@ -205,7 +205,7 @@ func (r *OpenAIRecorder) truncateBase64Data(data string) string { func (r *OpenAIRecorder) SetConfigForModel(model string, config *inference.BackendConfiguration) { if config == nil { - r.log.Warnf("SetConfigForModel called with nil config for model %s", model) + r.log.Warn("SetConfigForModel called with nil config for model", "model", model) return } @@ -399,9 +399,9 @@ func (r *OpenAIRecorder) RecordResponse(id, model string, rw http.ResponseWriter return } } - r.log.Errorf("Matching request (id=%s) not found for model %s - %d\n%s", id, modelID, statusCode, response) + r.log.Error("Matching request not found for model", "id", id, "model", modelID, "statusCode", statusCode, "response", response) } else { - r.log.Errorf("Model %s not found in records - %d\n%s", modelID, statusCode, response) + r.log.Error("Model not found in records", "model", modelID, "statusCode", statusCode, "response", response) } } @@ -717,7 +717,7 @@ func (r *OpenAIRecorder) handleStreamingRequests(w http.ResponseWriter, req *htt // Send heartbeat to establish connection. if _, err := fmt.Fprintf(w, "event: connected\ndata: {\"status\": \"connected\"}\n\n"); err != nil { - r.log.Errorf("Failed to write connected event to response: %v", err) + r.log.Error("Failed to write connected event to response", "error", err) } flusher.Flush() @@ -738,17 +738,17 @@ func (r *OpenAIRecorder) handleStreamingRequests(w http.ResponseWriter, req *htt // Send as SSE event. jsonData, err := json.Marshal(modelRecords) if err != nil { - r.log.Errorf("Failed to marshal record for streaming: %v", err) + r.log.Error("Failed to marshal record for streaming", "error", err) errorMsg := fmt.Sprintf(`{"error": "Failed to marshal record: %v"}`, err) if _, writeErr := fmt.Fprintf(w, "event: error\ndata: %s\n\n", errorMsg); writeErr != nil { - r.log.Errorf("Failed to write error event to response: %v", writeErr) + r.log.Error("Failed to write error event to response", "error", writeErr) } flusher.Flush() continue } if _, err := fmt.Fprintf(w, "event: new_request\ndata: %s\n\n", jsonData); err != nil { - r.log.Errorf("Failed to write new_request event to response: %v", err) + r.log.Error("Failed to write new_request event to response", "error", err) } flusher.Flush() @@ -841,14 +841,14 @@ func (r *OpenAIRecorder) sendExistingRecords(w http.ResponseWriter, model string }} jsonData, err := json.Marshal(singleRecord) if err != nil { - r.log.Errorf("Failed to marshal existing record for streaming: %v", err) + r.log.Error("Failed to marshal existing record for streaming", "error", err) errorMsg := fmt.Sprintf(`{"error": "Failed to marshal existing record: %v"}`, err) if _, writeErr := fmt.Fprintf(w, "event: error\ndata: %s\n\n", errorMsg); writeErr != nil { - r.log.Errorf("Failed to write error event to response: %v", writeErr) + r.log.Error("Failed to write error event to response", "error", writeErr) } } else { if _, writeErr := fmt.Fprintf(w, "event: existing_request\ndata: %s\n\n", jsonData); writeErr != nil { - r.log.Errorf("Failed to write existing_request event to response: %v", writeErr) + r.log.Error("Failed to write existing_request event to response", "error", writeErr) } } } @@ -863,8 +863,8 @@ func (r *OpenAIRecorder) RemoveModel(model string) { if _, exists := r.records[modelID]; exists { delete(r.records, modelID) - r.log.Infof("Removed records for model: %s", modelID) + r.log.Info("Removed records for model", "model", modelID) } else { - r.log.Warnf("No records found for model: %s", modelID) + r.log.Warn("No records found for model", "model", modelID) } } diff --git a/pkg/metrics/openai_recorder_test.go b/pkg/metrics/openai_recorder_test.go index e7ff5f8f0..0f8e4f10f 100644 --- a/pkg/metrics/openai_recorder_test.go +++ b/pkg/metrics/openai_recorder_test.go @@ -2,15 +2,15 @@ package metrics import ( "encoding/json" + "log/slog" "testing" "github.com/docker/model-runner/pkg/inference/models" - "github.com/sirupsen/logrus" ) func TestTruncateMediaFields(t *testing.T) { // Create a mock logger and model manager - logger := logrus.New() + logger := slog.Default() modelManager := &models.Manager{} recorder := NewOpenAIRecorder(logger, modelManager) @@ -159,7 +159,7 @@ func TestTruncateMediaFields(t *testing.T) { } func TestTruncateBase64Data(t *testing.T) { - logger := logrus.New() + logger := slog.Default() modelManager := &models.Manager{} recorder := NewOpenAIRecorder(logger, modelManager) diff --git a/pkg/metrics/scheduler_proxy.go b/pkg/metrics/scheduler_proxy.go index ca7183885..df86029b5 100644 --- a/pkg/metrics/scheduler_proxy.go +++ b/pkg/metrics/scheduler_proxy.go @@ -40,7 +40,7 @@ func (h *SchedulerMetricsHandler) ServeHTTP(w http.ResponseWriter, r *http.Reque // Get the socket path for the active llama.cpp runner socket, err := h.scheduler.GetLlamaCppSocket() if err != nil { - h.log.Errorf("Failed to get llama.cpp socket: %v", err) + h.log.Error("Failed to get llama.cpp socket", "error", err) http.Error(w, "Metrics endpoint not available", http.StatusServiceUnavailable) return } @@ -58,7 +58,7 @@ func (h *SchedulerMetricsHandler) ServeHTTP(w http.ResponseWriter, r *http.Reque // Create request to the backend metrics endpoint req, err := http.NewRequestWithContext(r.Context(), http.MethodGet, "http://unix/metrics", http.NoBody) if err != nil { - h.log.Errorf("Failed to create metrics request: %v", err) + h.log.Error("Failed to create metrics request", "error", err) http.Error(w, "Failed to create metrics request", http.StatusInternalServerError) return } @@ -73,7 +73,7 @@ func (h *SchedulerMetricsHandler) ServeHTTP(w http.ResponseWriter, r *http.Reque // Make the request to the backend resp, err := client.Do(req) if err != nil { - h.log.Errorf("Failed to fetch metrics from backend: %v", err) + h.log.Error("Failed to fetch metrics from backend", "error", err) http.Error(w, "Backend metrics unavailable", http.StatusServiceUnavailable) return } @@ -91,9 +91,9 @@ func (h *SchedulerMetricsHandler) ServeHTTP(w http.ResponseWriter, r *http.Reque // Copy response body if _, err := io.Copy(w, resp.Body); err != nil { - h.log.Errorf("Failed to copy metrics response: %v", err) + h.log.Error("Failed to copy metrics response", "error", err) return } - h.log.Debugf("Successfully proxied metrics request") + h.log.Debug("Successfully proxied metrics request") } diff --git a/pkg/ollama/http_handler.go b/pkg/ollama/http_handler.go index 445996f40..45ff4084c 100644 --- a/pkg/ollama/http_handler.go +++ b/pkg/ollama/http_handler.go @@ -62,7 +62,7 @@ func NewHTTPHandler(log logging.Logger, scheduler *scheduling.Scheduler, schedul func (h *HTTPHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { safeMethod := utils.SanitizeForLog(r.Method, -1) safePath := utils.SanitizeForLog(r.URL.Path, -1) - h.log.Infof("Ollama API request: %s %s", safeMethod, safePath) + h.log.Info("Ollama API request", "method", safeMethod, "path", safePath) h.httpHandler.ServeHTTP(w, r) } @@ -145,14 +145,14 @@ func (w *ollamaProgressWriter) Write(p []byte) (n int, err error) { return w.writer.Write(p) } // Unrecognized type, pass through to avoid losing information - w.log.Warnf("Unknown progress message type: %s", msg.Type) + w.log.Warn("Unknown progress message type", "message", msg.Type) return w.writer.Write(p) } // Marshal and write ollama format data, err := json.Marshal(ollamaMsg) if err != nil { - w.log.Warnf("Failed to marshal ollama progress: %v", err) + w.log.Warn("Failed to marshal ollama progress", "error", err) return w.writer.Write(p) } @@ -187,7 +187,7 @@ func (h *HTTPHandler) handleVersion(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - h.log.Errorf("Failed to encode response: %v", err) + h.log.Error("Failed to encode response", "error", err) } } @@ -196,7 +196,7 @@ func (h *HTTPHandler) handleListModels(w http.ResponseWriter, r *http.Request) { // Get models from the model manager modelsList, err := h.modelManager.List() if err != nil { - h.log.Errorf("Failed to list models: %v", err) + h.log.Error("Failed to list models", "error", err) http.Error(w, "Failed to list models", http.StatusInternalServerError) return } @@ -243,7 +243,7 @@ func (h *HTTPHandler) handleListModels(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - h.log.Errorf("Failed to encode response: %v", err) + h.log.Error("Failed to encode response", "error", err) } } @@ -260,7 +260,7 @@ func (h *HTTPHandler) handlePS(w http.ResponseWriter, r *http.Request) { // Get model details to populate additional fields model, err := h.modelManager.GetLocal(backend.ModelName) if err != nil { - h.log.Warnf("Failed to get model details for %s: %v", backend.ModelName, err) + h.log.Warn("Failed to get model details for", "backend", backend.ModelName, "error", err) // Still add the model with basic info models = append(models, PSModel{ Name: backend.ModelName, @@ -303,7 +303,7 @@ func (h *HTTPHandler) handlePS(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - h.log.Errorf("Failed to encode response: %v", err) + h.log.Error("Failed to encode response", "error", err) } } @@ -324,7 +324,7 @@ func (h *HTTPHandler) handleShowModel(w http.ResponseWriter, r *http.Request) { // Get model details model, err := h.modelManager.GetLocal(modelName) if err != nil { - h.log.Errorf("Failed to get model: %v", err) + h.log.Error("Failed to get model", "error", err) http.Error(w, fmt.Sprintf("Model not found: %v", err), http.StatusNotFound) return } @@ -332,7 +332,7 @@ func (h *HTTPHandler) handleShowModel(w http.ResponseWriter, r *http.Request) { // Get config config, err := model.Config() if err != nil { - h.log.Errorf("Failed to get model config: %v", err) + h.log.Error("Failed to get model config", "error", err) http.Error(w, fmt.Sprintf("Failed to get model config: %v", err), http.StatusInternalServerError) return } @@ -350,7 +350,7 @@ func (h *HTTPHandler) handleShowModel(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - h.log.Errorf("Failed to encode response: %v", err) + h.log.Error("Failed to encode response", "error", err) } } @@ -417,7 +417,7 @@ func (h *HTTPHandler) configureModel(ctx context.Context, modelName string, opti if hasContextSize || reasoningBudget != nil || hasKeepAlive { sanitizedModelName := utils.SanitizeForLog(modelName, -1) - h.log.Infof("configureModel: configuring model %s", sanitizedModelName) + h.log.Info("configureModel: configuring model", "model", sanitizedModelName) configureRequest := scheduling.ConfigureRequest{ Model: modelName, } @@ -434,12 +434,12 @@ func (h *HTTPHandler) configureModel(ctx context.Context, modelName string, opti if err == nil { configureRequest.KeepAlive = &ka } else { - h.log.Warnf("configureModel: invalid keep_alive %q: %v", keepAlive, err) + h.log.Warn("configureModel: invalid keep_alive", "model", keepAlive, "error", err) } } _, err := h.scheduler.ConfigureRunner(ctx, nil, configureRequest, userAgent) if err != nil { - h.log.Warnf("configureModel: failed to configure model %s: %v", sanitizedModelName, err) + h.log.Warn("configureModel: failed to configure model", "model", sanitizedModelName, "error", err) } } } @@ -456,7 +456,7 @@ func (h *HTTPHandler) handleGenerate(w http.ResponseWriter, r *http.Request) { var req GenerateRequest if err := json.NewDecoder(r.Body).Decode(&req); err != nil { - h.log.Errorf("handleGenerate: failed to decode request: %v", err) + h.log.Error("handleGenerate: failed to decode request", "error", err) http.Error(w, fmt.Sprintf("Invalid request: %v", err), http.StatusBadRequest) return } @@ -506,7 +506,7 @@ func (h *HTTPHandler) handleGenerate(w http.ResponseWriter, r *http.Request) { func (h *HTTPHandler) unloadModel(ctx context.Context, w http.ResponseWriter, modelName string) { // Sanitize user input before logging to prevent log injection sanitizedModelName := utils.SanitizeForLog(modelName, -1) - h.log.Infof("unloadModel: unloading model %s", sanitizedModelName) + h.log.Info("unloadModel: unloading model", "model", sanitizedModelName) // Create an unload request for the scheduler unloadReq := map[string]interface{}{ @@ -516,19 +516,19 @@ func (h *HTTPHandler) unloadModel(ctx context.Context, w http.ResponseWriter, mo // Marshal the unload request reqBody, err := json.Marshal(unloadReq) if err != nil { - h.log.Errorf("unloadModel: failed to marshal request: %v", err) + h.log.Error("unloadModel: failed to marshal request", "error", err) http.Error(w, fmt.Sprintf("Failed to marshal request: %v", err), http.StatusInternalServerError) return } // Sanitize the user-provided request body before logging to avoid log injection safeReqBody := utils.SanitizeForLog(string(reqBody), -1) - h.log.Infof("unloadModel: sending POST /engines/unload with body: %s", safeReqBody) + h.log.Info("unloadModel: sending POST /engines/unload with body", "model", safeReqBody) // Create a new request to the scheduler newReq, err := http.NewRequestWithContext(ctx, http.MethodPost, "/engines/unload", strings.NewReader(string(reqBody))) if err != nil { - h.log.Errorf("unloadModel: failed to create request: %v", err) + h.log.Error("unloadModel: failed to create request", "error", err) http.Error(w, fmt.Sprintf("Failed to create request: %v", err), http.StatusInternalServerError) return } @@ -544,7 +544,7 @@ func (h *HTTPHandler) unloadModel(ctx context.Context, w http.ResponseWriter, mo // Forward to scheduler HTTP handler h.schedulerHTTP.ServeHTTP(respRecorder, newReq) - h.log.Infof("unloadModel: scheduler response status=%d, body=%s", respRecorder.statusCode, respRecorder.body.String()) + h.log.Info("unloadModel: scheduler response", "status", respRecorder.statusCode, "body", respRecorder.body.String()) // Return the response status w.WriteHeader(respRecorder.statusCode) @@ -574,7 +574,7 @@ func (h *HTTPHandler) handleDelete(w http.ResponseWriter, r *http.Request) { } sanitizedModelName := utils.SanitizeForLog(modelName, -1) - h.log.Infof("handleDelete: deleting model %s", sanitizedModelName) + h.log.Info("handleDelete: deleting model", "model", sanitizedModelName) // First, unload the model from memory unloadReq := map[string]interface{}{ @@ -583,14 +583,14 @@ func (h *HTTPHandler) handleDelete(w http.ResponseWriter, r *http.Request) { reqBody, err := json.Marshal(unloadReq) if err != nil { - h.log.Errorf("handleDelete: failed to marshal unload request: %v", err) + h.log.Error("handleDelete: failed to marshal unload request", "error", err) http.Error(w, fmt.Sprintf("Failed to marshal request: %v", err), http.StatusInternalServerError) return } newReq, err := http.NewRequestWithContext(ctx, http.MethodPost, "/engines/unload", strings.NewReader(string(reqBody))) if err != nil { - h.log.Errorf("handleDelete: failed to create unload request: %v", err) + h.log.Error("handleDelete: failed to create unload request", "error", err) http.Error(w, fmt.Sprintf("Failed to create request: %v", err), http.StatusInternalServerError) return } @@ -603,17 +603,12 @@ func (h *HTTPHandler) handleDelete(w http.ResponseWriter, r *http.Request) { } h.schedulerHTTP.ServeHTTP(respRecorder, newReq) - h.log.Infof("handleDelete: unload response status=%d", respRecorder.statusCode) + h.log.Info("handleDelete: unload response", "status", respRecorder.statusCode) // Check if unload succeeded before deleting from storage if respRecorder.statusCode < 200 || respRecorder.statusCode >= 300 { sanitizedBody := utils.SanitizeForLog(respRecorder.body.String(), -1) - h.log.Errorf( - "handleDelete: unload failed for model %s with status=%d, body=%q", - sanitizedModelName, - respRecorder.statusCode, - sanitizedBody, - ) + h.log.Error("handleDelete: unload failed for model", "model", sanitizedModelName, "status", respRecorder.statusCode, "body", sanitizedBody) http.Error( w, fmt.Sprintf("Failed to unload model: scheduler returned status %d", respRecorder.statusCode), @@ -625,12 +620,12 @@ func (h *HTTPHandler) handleDelete(w http.ResponseWriter, r *http.Request) { // Then delete the model from storage if _, err := h.modelManager.Delete(modelName, false); err != nil { sanitizedErr := utils.SanitizeForLog(err.Error(), -1) - h.log.Errorf("handleDelete: failed to delete model %s: %v", sanitizedModelName, sanitizedErr) + h.log.Error("handleDelete: failed to delete model", "model", sanitizedModelName, "error", sanitizedErr) http.Error(w, fmt.Sprintf("Failed to delete model: %v", sanitizedErr), http.StatusInternalServerError) return } - h.log.Infof("handleDelete: successfully deleted model %s", sanitizedModelName) + h.log.Info("handleDelete: successfully deleted model", "model", sanitizedModelName) // Return success response in Ollama format (empty JSON object) w.Header().Set("Content-Type", "application/json") @@ -664,7 +659,7 @@ func (h *HTTPHandler) handlePull(w http.ResponseWriter, r *http.Request) { // Call the model manager's Pull method with the wrapped writer if err := h.modelManager.Pull(modelName, "", r, ollamaWriter); err != nil { - h.log.Errorf("Failed to pull model: %s", utils.SanitizeForLog(err.Error(), -1)) + h.log.Error("Failed to pull model", "error", utils.SanitizeForLog(err.Error(), -1)) // Send error in Ollama JSON format errorResponse := ollamaPullStatus{ @@ -676,7 +671,7 @@ func (h *HTTPHandler) handlePull(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusInternalServerError) if err := json.NewEncoder(w).Encode(errorResponse); err != nil { - h.log.Errorf("failed to encode response: %v", err) + h.log.Error("failed to encode response", "error", err) } } else { // Headers already sent - write error as JSON line @@ -1053,7 +1048,7 @@ func (s *streamingChatResponseWriter) Write(data []byte) (int, error) { // Parse OpenAI chunk using proper struct var chunk openAIChatStreamChunk if err := json.Unmarshal([]byte(dataStr), &chunk); err != nil { - s.log.Warnf("Failed to parse OpenAI chat stream chunk: %v", err) + s.log.Warn("Failed to parse OpenAI chat stream chunk", "error", err) continue } @@ -1175,7 +1170,7 @@ func (s *streamingGenerateResponseWriter) Write(data []byte) (int, error) { // Parse OpenAI chunk using proper struct var chunk openAIChatStreamChunk if err := json.Unmarshal([]byte(dataStr), &chunk); err != nil { - s.log.Warnf("Failed to parse OpenAI chat stream chunk: %v", err) + s.log.Warn("Failed to parse OpenAI chat stream chunk", "error", err) continue } @@ -1222,7 +1217,7 @@ func (h *HTTPHandler) convertChatResponse(w http.ResponseWriter, respRecorder *r // Convert to Ollama error format (simple string) w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(map[string]string{"error": openAIErr.Error.Message}); err != nil { - h.log.Errorf("failed to encode response: %v", err) + h.log.Error("failed to encode response", "error", err) } } else { // Fallback: return raw error body @@ -1234,7 +1229,7 @@ func (h *HTTPHandler) convertChatResponse(w http.ResponseWriter, respRecorder *r // Parse OpenAI response using proper struct var openAIResp openAIChatResponse if err := json.Unmarshal([]byte(respRecorder.body.String()), &openAIResp); err != nil { - h.log.Errorf("Failed to parse OpenAI response: %v", err) + h.log.Error("Failed to parse OpenAI response", "error", err) http.Error(w, "Failed to parse response", http.StatusInternalServerError) return } @@ -1264,7 +1259,7 @@ func (h *HTTPHandler) convertChatResponse(w http.ResponseWriter, respRecorder *r w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - h.log.Errorf("Failed to encode response: %v", err) + h.log.Error("Failed to encode response", "error", err) } } @@ -1309,7 +1304,7 @@ func (h *HTTPHandler) convertGenerateResponse(w http.ResponseWriter, respRecorde // Convert to Ollama error format (simple string) w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(map[string]string{"error": openAIErr.Error.Message}); err != nil { - h.log.Errorf("failed to encode response: %v", err) + h.log.Error("failed to encode response", "error", err) } } else { // Fallback: return raw error body @@ -1321,7 +1316,7 @@ func (h *HTTPHandler) convertGenerateResponse(w http.ResponseWriter, respRecorde // Parse OpenAI chat response (since we're now using chat completions endpoint) var openAIResp openAIChatResponse if err := json.Unmarshal([]byte(respRecorder.body.String()), &openAIResp); err != nil { - h.log.Errorf("Failed to parse OpenAI chat response: %v", err) + h.log.Error("Failed to parse OpenAI chat response", "error", err) http.Error(w, "Failed to parse response", http.StatusInternalServerError) return } @@ -1345,6 +1340,6 @@ func (h *HTTPHandler) convertGenerateResponse(w http.ResponseWriter, respRecorde w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - h.log.Errorf("Failed to encode response: %v", err) + h.log.Error("Failed to encode response", "error", err) } } diff --git a/pkg/responses/handler.go b/pkg/responses/handler.go index 125efe6c4..298e98735 100644 --- a/pkg/responses/handler.go +++ b/pkg/responses/handler.go @@ -55,7 +55,7 @@ func NewHTTPHandler(log logging.Logger, schedulerHTTP http.Handler, allowedOrigi func (h *HTTPHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { cleanPath := strings.ReplaceAll(r.URL.Path, "\n", "") cleanPath = strings.ReplaceAll(cleanPath, "\r", "") - h.log.Infof("Responses API request: %s %s", r.Method, cleanPath) + h.log.Info("Responses API request", "method", r.Method, "path", cleanPath) h.httpHandler.ServeHTTP(w, r) } @@ -305,7 +305,7 @@ func (h *HTTPHandler) sendJSON(w http.ResponseWriter, statusCode int, data inter w.Header().Set("Content-Type", "application/json") w.WriteHeader(statusCode) if err := json.NewEncoder(w).Encode(data); err != nil { - h.log.Errorf("Failed to encode JSON response: %v", err) + h.log.Error("Failed to encode JSON response", "error", err) } } diff --git a/pkg/responses/handler_test.go b/pkg/responses/handler_test.go index 0968b3ac3..fb71e452b 100644 --- a/pkg/responses/handler_test.go +++ b/pkg/responses/handler_test.go @@ -4,12 +4,11 @@ import ( "bytes" "encoding/json" "io" + "log/slog" "net/http" "net/http/httptest" "strings" "testing" - - "github.com/sirupsen/logrus" ) // mockSchedulerHTTP is a mock scheduler that returns predefined responses. @@ -39,8 +38,7 @@ func (m *mockSchedulerHTTP) ServeHTTP(w http.ResponseWriter, r *http.Request) { } func newTestHandler(mock *mockSchedulerHTTP) *HTTPHandler { - log := logrus.New() - log.SetOutput(io.Discard) + log := slog.New(slog.DiscardHandler) return NewHTTPHandler(log, mock, nil) } diff --git a/vllm_backend.go b/vllm_backend.go index 5697cb77c..404233582 100644 --- a/vllm_backend.go +++ b/vllm_backend.go @@ -3,17 +3,18 @@ package main import ( + "log/slog" + "github.com/docker/model-runner/pkg/inference" "github.com/docker/model-runner/pkg/inference/backends/vllm" "github.com/docker/model-runner/pkg/inference/models" - "github.com/sirupsen/logrus" ) -func initVLLMBackend(log *logrus.Logger, modelManager *models.Manager, customBinaryPath string) (inference.Backend, error) { +func initVLLMBackend(log *slog.Logger, modelManager *models.Manager, customBinaryPath string) (inference.Backend, error) { return vllm.New( log, modelManager, - log.WithFields(logrus.Fields{"component": vllm.Name}), + log.With("component", vllm.Name), nil, customBinaryPath, ) diff --git a/vllm_backend_stub.go b/vllm_backend_stub.go index 64937cc16..86bafd230 100644 --- a/vllm_backend_stub.go +++ b/vllm_backend_stub.go @@ -3,12 +3,13 @@ package main import ( + "log/slog" + "github.com/docker/model-runner/pkg/inference" "github.com/docker/model-runner/pkg/inference/models" - "github.com/sirupsen/logrus" ) -func initVLLMBackend(log *logrus.Logger, modelManager *models.Manager, customBinaryPath string) (inference.Backend, error) { +func initVLLMBackend(log *slog.Logger, modelManager *models.Manager, customBinaryPath string) (inference.Backend, error) { return nil, nil }