From b129694ffe06bcfc6db527c16c4f14a7ae3e948c Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Tue, 3 Nov 2026 14:32:53 +0000 Subject: [PATCH] feat(http): add an opt-in client address to the access log Operators could not tell which client sends requests that are refused with 401. Add --log-client (LOCALAI_LOG_CLIENT, off by default). When set, the HTTP request log line also carries duration, remote, user_agent and, when present, request_id. The address is the TCP peer. It is never read from X-Forwarded-For, X-Real-Ip or Forwarded, because LocalAI has no trusted-proxy setting and any client can forge those headers. Behind a reverse proxy the value is the proxy address. Authorization headers, cookies, query strings and bodies are never logged. User agent and request id are cut to a fixed length and have control characters replaced. Assisted-by: Claude:claude-sonnet-5-5 go gofmt --- core/cli/run.go | 2 + core/config/application_config.go | 8 ++ core/http/access_log.go | 117 +++++++++++++++++++++++ core/http/access_log_internal_test.go | 118 ++++++++++++++++++++++++ core/http/app.go | 40 +------- docs/content/reference/cli-reference.md | 1 + 6 files changed, 247 insertions(+), 39 deletions(-) create mode 100644 core/http/access_log.go create mode 100644 core/http/access_log_internal_test.go diff --git a/core/cli/run.go b/core/cli/run.go index a41e672284..830c169642 100644 --- a/core/cli/run.go +++ b/core/cli/run.go @@ -50,6 +50,7 @@ type RunCMD struct { AddonsOwnerAddress string `name:"addons-owner-address" env:"LOCALAI_ADDONS_OWNER_ADDRESS" help:"Address of the add-on owner carrier, as https://host:port with no path. Use a stable service name, never a pod address. Required for the owner and frontend roles" group:"addons"` AddonsOwnerListen string `name:"addons-owner-listen" env:"LOCALAI_ADDONS_OWNER_LISTEN" help:"Owner role only: the address the carrier listens on. Empty listens on all interfaces, on the port of --addons-owner-address" group:"addons"` AddonsCarrierDir string `name:"addons-carrier-dir" env:"LOCALAI_ADDONS_CARRIER_DIR" type:"path" help:"Directory with the carrier key set made by 'local-ai util addons-carrier-keys'. Required for the owner and frontend roles" group:"addons"` + LogClient bool `name:"log-client" env:"LOCALAI_LOG_CLIENT" default:"false" help:"Add the duration, client address, user agent and request id to the HTTP access log. Off by default. The address is the TCP peer, never read from X-Forwarded-For. Turn it on with --log-client" group:"logging"` AutoUpgradeAddons bool `name:"auto-upgrade-addons" env:"LOCALAI_AUTO_UPGRADE_ADDONS" default:"false" help:"Upgrade installed add-ons on their own when a newer version appears in their library. Off by default; upgrades then stay manual" group:"addons"` AddonsOfficialLibrary bool `name:"addons-official-library" env:"LOCALAI_ADDONS_OFFICIAL_LIBRARY" default:"true" help:"Register the official add-on library on the first start, when the add-on owner has no sources.json yet. A library the admin removes later stays removed. Turn it off with --addons-official-library=false" group:"addons"` AddonsBackendLibrary bool `name:"addons-backend-library" env:"LOCALAI_ADDONS_BACKEND_LIBRARY" default:"true" help:"Register the backend library on the first start, when the add-on owner has no sources.json yet. A build from master reads it as the backend source; a tagged build reads the backend gallery until the release cutover. Turn it off to read the backend gallery only" group:"addons"` @@ -394,6 +395,7 @@ func (r *RunCMD) Run(ctx *cliContext.Context) (result error) { config.WithYAMLConfigPreload(r.PreloadModelsConfig), config.WithSystemState(systemState), config.WithContextSize(r.ContextSize), + config.WithLogClient(r.LogClient), config.WithDebug(ctx.Debug || (ctx.LogLevel != nil && *ctx.LogLevel == "debug")), config.WithGeneratedContentDir(r.GeneratedContentPath), config.WithUploadDir(r.UploadPath), diff --git a/core/config/application_config.go b/core/config/application_config.go index 2d01e6b9e4..e92f48d0ee 100644 --- a/core/config/application_config.go +++ b/core/config/application_config.go @@ -142,6 +142,7 @@ type ApplicationConfig struct { F16 bool Debug bool + LogClient bool EnableTracing bool MaxConcurrentBackendRequests int TracingMaxItems int @@ -1071,6 +1072,13 @@ func WithDebug(debug bool) AppOption { } } +// WithLogClient adds the peer address and user agent to the HTTP access log. +func WithLogClient(on bool) AppOption { + return func(o *ApplicationConfig) { + o.LogClient = on + } +} + func WithTracingMaxItems(items int) AppOption { return func(o *ApplicationConfig) { o.TracingMaxItems = items diff --git a/core/http/access_log.go b/core/http/access_log.go new file mode 100644 index 0000000000..ec314446e7 --- /dev/null +++ b/core/http/access_log.go @@ -0,0 +1,117 @@ +package http + +import ( + "errors" + "net" + "net/http" + "strings" + "time" + "unicode" + + "github.com/labstack/echo/v4" + "github.com/mudler/LocalAI/pkg/diagnostics" + "github.com/mudler/xlog" +) + +// maxLoggedUserAgent caps the user agent in the access log so a client +// cannot flood the log with one header. +const maxLoggedUserAgent = 80 + +// maxLoggedRequestID caps the request id for the same reason. +const maxLoggedRequestID = 64 + +// accessLog logs one line per request. When logClient is true the line also +// carries the peer address and the user agent, so an unauthorized caller can +// be identified. +func accessLog(logClient bool) echo.MiddlewareFunc { + return func(next echo.HandlerFunc) echo.HandlerFunc { + return func(c echo.Context) error { + start := time.Now() + req := c.Request() + res := c.Response() + err := next(c) + + // Echo's central HTTPErrorHandler runs *after* this middleware + // returns, so res.Status still reads the default 200 here when a + // handler returned an error without writing a response. Mirror + // echo.DefaultHTTPErrorHandler's status derivation so the access + // log reflects the status the client actually receives — without + // this, every silent handler error logs as 200. + status := res.Status + if err != nil && !res.Committed { + status = http.StatusInternalServerError + var he *echo.HTTPError + if errors.As(err, &he) { + status = he.Code + } + } + + // Fix for #7989: Reduce log verbosity of Web UI polling, resources API, and health checks + // These paths are logged at DEBUG level (hidden by default) instead of INFO. + isQuietPath := false + for _, path := range quietPaths { + if req.URL.Path == path { + isQuietPath = true + break + } + } + + // URL.Path never holds the query string, so keys passed as + // ?api_key=... stay out of the log. + attrs := []any{"method", req.Method, "path", req.URL.Path, "status", status} + if logClient { + attrs = append(attrs, "duration", time.Since(start).String(), "remote", peerAddr(req), "user_agent", sanitizeLogValue(req.UserAgent(), maxLoggedUserAgent)) + if id := requestID(req, res); id != "" { + attrs = append(attrs, "request_id", id) + } + } + + if isQuietPath && status == 200 { + xlog.Debug("HTTP request", attrs...) + } else { + xlog.Info("HTTP request", attrs...) + } + return err + } + } +} + +// peerAddr returns the TCP peer address without the port. It does not use +// echo's Context.RealIP: with no IPExtractor configured, RealIP trusts the +// X-Forwarded-For and X-Real-Ip headers, which any client can forge. LocalAI +// has no trusted-proxy setting, so the peer address is the only safe value. +func peerAddr(req *http.Request) string { + host, _, err := net.SplitHostPort(req.RemoteAddr) + if err != nil { + return req.RemoteAddr + } + return host +} + +// requestID returns the diagnostic id the server set on the response, or the +// X-Request-Id the caller sent, or an empty string. +func requestID(req *http.Request, res *echo.Response) string { + id := res.Header().Get(diagnostics.HeaderDiagnosticID) + if id == "" { + id = req.Header.Get(echo.HeaderXRequestID) + } + return sanitizeLogValue(id, maxLoggedRequestID) +} + +// sanitizeLogValue replaces control characters with a space and truncates +// the value to max characters. +func sanitizeLogValue(ua string, max int) string { + var b strings.Builder + n := 0 + for _, r := range ua { + if n == max { + break + } + if unicode.IsControl(r) { + r = ' ' + } + b.WriteRune(r) + n++ + } + return b.String() +} diff --git a/core/http/access_log_internal_test.go b/core/http/access_log_internal_test.go new file mode 100644 index 0000000000..3b9e1157ef --- /dev/null +++ b/core/http/access_log_internal_test.go @@ -0,0 +1,118 @@ +package http + +import ( + "bytes" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + + "github.com/labstack/echo/v4" + "github.com/mudler/xlog" + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" +) + +var _ = Describe("HTTP access log", func() { + var logs *bytes.Buffer + + BeforeEach(func() { + logs = new(bytes.Buffer) + xlog.SetLogger(xlog.NewLoggerWithHandler(slog.NewJSONHandler(logs, nil), xlog.LogLevelDebug)) + DeferCleanup(func() { xlog.SetLogger(xlog.NewLogger(xlog.LogLevelInfo, "text")) }) + }) + + // serve sends one request through the access log and returns the log line. + serve := func(logClient bool, mutate func(*http.Request)) string { + logs.Reset() + e := echo.New() + e.Use(accessLog(logClient)) + e.POST("/chat/completions", func(c echo.Context) error { + return echo.NewHTTPError(http.StatusUnauthorized, "no key") + }) + req := httptest.NewRequest(http.MethodPost, "/chat/completions", nil) + req.RemoteAddr = "192.0.2.10:54321" + if mutate != nil { + mutate(req) + } + e.ServeHTTP(httptest.NewRecorder(), req) + return logs.String() + } + + It("logs the peer address and the user agent", func() { + line := serve(true, func(r *http.Request) { r.Header.Set("User-Agent", "curl/8.5.0") }) + Expect(line).To(ContainSubstring(`"remote":"192.0.2.10"`)) + Expect(line).To(ContainSubstring(`"user_agent":"curl/8.5.0"`)) + Expect(line).To(ContainSubstring(`"status":401`)) + Expect(line).To(ContainSubstring(`"path":"/chat/completions"`)) + }) + + It("ignores a forged X-Forwarded-For and X-Real-Ip", func() { + line := serve(true, func(r *http.Request) { + r.Header.Set("X-Forwarded-For", "203.0.113.99") + r.Header.Set("X-Real-Ip", "203.0.113.98") + }) + Expect(line).To(ContainSubstring(`"remote":"192.0.2.10"`)) + Expect(line).NotTo(ContainSubstring("203.0.113")) + }) + + It("truncates the user agent to 80 characters", func() { + line := serve(true, func(r *http.Request) { r.Header.Set("User-Agent", strings.Repeat("a", 500)) }) + Expect(line).To(ContainSubstring(`"user_agent":"` + strings.Repeat("a", 80) + `"`)) + }) + + It("replaces control characters in the user agent", func() { + Expect(sanitizeLogValue("evil\r\nINFO fake\tline\x00", 80)).To(Equal("evil INFO fake line ")) + Expect(sanitizeLogValue(strings.Repeat("é", 100), 80)).To(HaveLen(160)) + }) + + It("adds neither field when the option is off", func() { + line := serve(false, func(r *http.Request) { r.Header.Set("User-Agent", "curl/8.5.0") }) + Expect(line).NotTo(ContainSubstring("remote")) + Expect(line).NotTo(ContainSubstring("user_agent")) + Expect(line).To(ContainSubstring(`"status":401`)) + }) + + It("never logs credentials, query strings or cookies", func() { + line := serve(true, func(r *http.Request) { + r.URL.RawQuery = "api_key=sk-query-secret" + r.Header.Set("Authorization", "Bearer sk-header-secret") + r.Header.Set("Cookie", "session=cookie-secret") + }) + Expect(line).NotTo(ContainSubstring("sk-header-secret")) + Expect(line).NotTo(ContainSubstring("Bearer")) + Expect(line).NotTo(ContainSubstring("sk-query-secret")) + Expect(line).NotTo(ContainSubstring("cookie-secret")) + Expect(line).To(ContainSubstring(`"path":"/chat/completions"`)) + }) + + It("logs the duration and the request id when one is present", func() { + line := serve(true, func(r *http.Request) { r.Header.Set("X-Request-Id", "req-42\nforged") }) + Expect(line).To(ContainSubstring(`"duration":`)) + Expect(line).To(ContainSubstring(`"request_id":"req-42 forged"`)) + Expect(serve(true, nil)).NotTo(ContainSubstring("request_id")) + }) + + It("falls back to the raw address when it has no port", func() { + line := serve(true, func(r *http.Request) { r.RemoteAddr = "@" }) + Expect(line).To(ContainSubstring(`"remote":"@"`)) + }) +}) + +var _ = DescribeTable("peerAddr", + func(remote string, headers map[string]string, want string) { + req := httptest.NewRequest(http.MethodGet, "/", nil) + req.RemoteAddr = remote + for k, v := range headers { + req.Header.Set(k, v) + } + Expect(peerAddr(req)).To(Equal(want)) + }, + Entry("ipv4 with port", "192.0.2.10:1234", nil, "192.0.2.10"), + Entry("ipv6 with port", "[2001:db8::1]:1234", nil, "2001:db8::1"), + Entry("no port", "192.0.2.10", nil, "192.0.2.10"), + Entry("spoofed X-Forwarded-For", "192.0.2.10:1234", map[string]string{"X-Forwarded-For": "203.0.113.7"}, "192.0.2.10"), + Entry("spoofed X-Forwarded-For chain", "192.0.2.10:1234", map[string]string{"X-Forwarded-For": "203.0.113.7, 198.51.100.1"}, "192.0.2.10"), + Entry("spoofed X-Real-Ip", "192.0.2.10:1234", map[string]string{"X-Real-Ip": "203.0.113.7"}, "192.0.2.10"), + Entry("spoofed Forwarded", "192.0.2.10:1234", map[string]string{"Forwarded": "for=203.0.113.7"}, "192.0.2.10"), +) diff --git a/core/http/app.go b/core/http/app.go index 2b2a6ad93a..5745fec31c 100644 --- a/core/http/app.go +++ b/core/http/app.go @@ -338,45 +338,7 @@ func API(application *application.Application) (*echo.Echo, error) { } // Custom logger middleware using xlog - e.Use(func(next echo.HandlerFunc) echo.HandlerFunc { - return func(c echo.Context) error { - req := c.Request() - res := c.Response() - err := next(c) - - // Echo's central HTTPErrorHandler runs *after* this middleware - // returns, so res.Status still reads the default 200 here when a - // handler returned an error without writing a response. Mirror - // echo.DefaultHTTPErrorHandler's status derivation so the access - // log reflects the status the client actually receives — without - // this, every silent handler error logs as 200. - status := res.Status - if err != nil && !res.Committed { - status = http.StatusInternalServerError - var he *echo.HTTPError - if errors.As(err, &he) { - status = he.Code - } - } - - // Fix for #7989: Reduce log verbosity of Web UI polling, resources API, and health checks - // These paths are logged at DEBUG level (hidden by default) instead of INFO. - isQuietPath := false - for _, path := range quietPaths { - if req.URL.Path == path { - isQuietPath = true - break - } - } - - if isQuietPath && status == 200 { - xlog.Debug("HTTP request", "method", req.Method, "path", req.URL.Path, "status", status) - } else { - xlog.Info("HTTP request", "method", req.Method, "path", req.URL.Path, "status", status) - } - return err - } - }) + e.Use(accessLog(application.ApplicationConfig().LogClient)) // Recover middleware if !application.ApplicationConfig().Debug { diff --git a/docs/content/reference/cli-reference.md b/docs/content/reference/cli-reference.md index 9839b05219..37f01ff105 100644 --- a/docs/content/reference/cli-reference.md +++ b/docs/content/reference/cli-reference.md @@ -20,6 +20,7 @@ model, see [Model Configuration]({{% relref "advanced/model-configuration" %}}). |-----------|---------|-------------|----------------------| | `-h, --help` | | Show context-sensitive help | | | `--log-level` | `info` | Set the level of logs to output [error,warn,info,debug,trace] | `$LOCALAI_LOG_LEVEL` | +| `--log-client` | `false` | `local-ai run` only. Add `duration`, `remote` (the TCP peer address), `user_agent` (control characters replaced, cut to 80 characters), and `request_id` (when the request has one) to the `HTTP request` log line, so you can tell who sent a request that was refused. The address never comes from `X-Forwarded-For` or `X-Real-Ip`, so behind a reverse proxy it is the proxy address. Authorization headers, cookies, query strings and bodies are never logged. | `$LOCALAI_LOG_CLIENT` | | `--credentials-file` | | YAML file with credentials for private registries, galleries and download hosts. See [Private Registries and Galleries]({{% relref "advanced/private-sources" %}}) | `$LOCALAI_CREDENTIALS_FILE` | | `--debug` | `false` | **DEPRECATED** - Use `--log-level=debug` instead. Enable debug logging | `$LOCALAI_DEBUG`, `$DEBUG` |