feat(addons): log the reason behind a generic denial

core/http/endpoints/addons/apps.go

@@ -156,6 +156,7 @@ func lifecycle(g *gateway.Gateway, db *gorm.DB, action string, opts []Option) ec
 		var body apps.StartRequest
 		if decode(c, &body) != nil || body.OperationID == "" || len(body.OperationID) > 256 || body.Generation == 0 || !appID.MatchString(c.Param("id")) {
 			if !appID.MatchString(c.Param("id")) {
+				logDenial(c, "invalid-addon-id", nil)
 				return failure(c, 403, "Addon request denied")
 			}
 			return failure(c, 400, "An operationId and the listed generation are required")

core/http/endpoints/addons/assets.go

@@ -45,6 +45,7 @@ func GetAsset(g *gateway.Gateway, db *gorm.DB, opts ...Option) echo.HandlerFunc
 		}
 		id, digest, name := c.Param("id"), c.Param("digest"), c.Param("*")
 		if !appID.MatchString(id) || !assetDigest.MatchString(digest) || name == "" || len(name) > maxAssetPath {
+			logDenial(c, "invalid-addon-id-digest-or-path", nil)
 			return failure(c, 403, "Addon request denied")
 		}
 		if g == nil {

core/http/endpoints/addons/gateway.go

@@ -4,10 +4,12 @@ package addons
 import (
 	"encoding/json"
 	"errors"
+	"fmt"
 	"github.com/labstack/echo/v4"
 	"github.com/mudler/LocalAI/core/http/auth"
 	"github.com/mudler/LocalAI/core/services/addons/gateway"
 	"github.com/mudler/LocalAI/pkg/addons/contract"
+	"github.com/mudler/xlog"
 	"gorm.io/gorm"
 	"io"
 	"net/http"
@@ -109,6 +111,55 @@ func denied(c echo.Context, e error) error {
 	}
 	return failure(c, 401, "Named authentication required")
 }
+
+const (
+	ctxAction  = "addon.action"
+	ctxAddonID = "addon.id"
+)
+
+// noteRequest remembers the action and add-on ID of a parsed request, the
+// only request fields a denial log may carry.
+func noteRequest(c echo.Context, r contract.Request) {
+	c.Set(ctxAction, r.Action)
+	c.Set(ctxAddonID, r.AddonID)
+}
+
+// logDenial writes one Warn line for a request refused with the generic
+// message, so an operator can tell which check fired. The client response
+// is not affected. It logs the action and add-on ID of a parsed request (or
+// the route pattern when the request has none), the fixed rule that refused
+// it or the innermost message of err, and the error kind. It never logs the
+// request body, arguments, headers, cookies or credential references.
+func logDenial(c echo.Context, rule string, err error) {
+	action, _ := c.Get(ctxAction).(string)
+	id, _ := c.Get(ctxAddonID).(string)
+	if action == "" {
+		action = c.Path()
+	}
+	if id == "" {
+		id = c.Param("id")
+	}
+	args := []any{"action", action, "addonId", id, "status", http.StatusForbidden}
+	if rule != "" {
+		args = append(args, "rule", rule)
+	}
+	if err != nil {
+		inner := err
+		for u := errors.Unwrap(inner); u != nil; u = errors.Unwrap(inner) {
+			inner = u
+		}
+		kind := fmt.Sprintf("%T", err)
+		switch {
+		case errors.Is(err, gateway.ErrForbidden):
+			kind = "ErrForbidden"
+		case errors.Is(err, gateway.ErrUnavailable):
+			kind = "ErrUnavailable"
+		}
+		args = append(args, "kind", kind, "reason", inner.Error())
+	}
+	xlog.Warn("Addon request denied", args...)
+}
+
 func decode(c echo.Context, v any) error {
 	c.Request().Body = http.MaxBytesReader(c.Response(), c.Request().Body, 2<<20)
 	d := json.NewDecoder(c.Request().Body)
@@ -164,6 +215,7 @@ func resultError(c echo.Context, e error) error {
 			return c.JSON(t.status, AddonErrorResponse{Error: AddonError{Type: t.kind, Code: t.status, Message: t.message}})
 		}
 	}
+	logDenial(c, "", e)
 	return failure(c, 403, "Addon request denied")
 }
 
@@ -191,11 +243,13 @@ func Dispatch(g *gateway.Gateway, db *gorm.DB, opts ...Option) echo.HandlerFunc
 		if decode(c, &r) != nil {
 			return failure(c, 400, "Invalid addon request")
 		}
+		noteRequest(c, r)
 		// Recovery and update mutations have their own routes, which accept
 		// only the administrator's own browser session. The generic dispatch
 		// also takes API keys, so it must not carry them.
 		if (gateway.RecoveryAction(r.Action) && r.Action != gateway.ActionRecoveryStatus) ||
 			(gateway.UpdateAction(r.Action) && r.Action != gateway.ActionUpdateStatus) {
+			logDenial(c, "recovery-and-update-actions-use-their-own-routes", nil)
 			return failure(c, 403, "Addon request denied")
 		}
 		if r.Action != "read" {

core/http/endpoints/addons/installrefusal_test.go

@@ -12,10 +12,12 @@ import (
 	"crypto/sha256"
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"os"
 	"path/filepath"
+	"strings"
 
 	"github.com/labstack/echo/v4"
 	"github.com/mudler/LocalAI/core/config"
@@ -25,6 +27,7 @@ import (
 	"github.com/mudler/LocalAI/core/services/addons/gateway"
 	"github.com/mudler/LocalAI/core/services/addons/packages"
 	"github.com/mudler/LocalAI/pkg/addons/contract"
+	"github.com/mudler/xlog"
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
 )
@@ -128,6 +131,40 @@ var _ = Describe("install refusal in the dispatch response", func() {
 		Expect(message(body)).To(Equal(generic))
 	})
 
+	It("logs the reason behind a generic denial and leaves the response unchanged", func() {
+		_, app, token, _, _ := setup()
+		logs := &strings.Builder{}
+		xlog.SetLogger(xlog.NewLoggerWithHandler(slog.NewTextHandler(logs, &slog.HandlerOptions{Level: slog.LevelWarn}), xlog.LogLevelWarn))
+		DeferCleanup(func() { xlog.SetLogger(xlog.NewLogger(xlog.LogLevel("info"), "text")) })
+
+		code, body := install(app, token, "corrupt")
+		Expect(code).To(Equal(http.StatusForbidden))
+		Expect(body).To(MatchJSON(`{"error":{"type":"addon_error","message":"` + generic + `","code":403}}`))
+		line := logs.String()
+		Expect(strings.Count(line, "\n")).To(Equal(1), line)
+		Expect(line).To(ContainSubstring("action=install"))
+		Expect(line).To(ContainSubstring("addonId=corrupt"))
+		Expect(line).To(ContainSubstring("reason="))
+		Expect(line).To(ContainSubstring("kind="))
+		// Neither the credential nor the arguments reach the log.
+		Expect(line).NotTo(ContainSubstring(token))
+		Expect(line).NotTo(ContainSubstring("Bearer"))
+		Expect(line).NotTo(ContainSubstring("sourceId"))
+		Expect(line).NotTo(ContainSubstring("op-corrupt"))
+
+		logs.Reset()
+		r := httptest.NewRequest(http.MethodPost, "/api/addons/dispatch", bytes.NewBufferString(`{"addonId":"x","operationId":"o","action":"update-upgrade","arguments":{}}`))
+		r.Header.Set("Content-Type", "application/json")
+		r.Header.Set("Authorization", "Bearer "+token)
+		w := httptest.NewRecorder()
+		app.ServeHTTP(w, r)
+		Expect(w.Code).To(Equal(http.StatusForbidden))
+		Expect(w.Body.String()).To(MatchJSON(`{"error":{"type":"addon_error","message":"` + generic + `","code":403}}`))
+		Expect(logs.String()).To(ContainSubstring("action=update-upgrade"))
+		Expect(logs.String()).To(ContainSubstring("rule=recovery-and-update-actions-use-their-own-routes"))
+		Expect(logs.String()).NotTo(ContainSubstring(token))
+	})
+
 	It("returns the same text through a forwarding frontend", func() {
 		m, _, token, _, mount := setup()
 		certs, roots := certificates()

core/http/endpoints/addons/recovery.go

@@ -121,6 +121,7 @@ func recoveryRoute(g *gateway.Gateway, db *gorm.DB, opts []Option, action string
 		}
 		id := c.Param("id")
 		if !appID.MatchString(id) {
+			logDenial(c, "invalid-addon-id", nil)
 			return failure(c, 403, "Addon request denied")
 		}
 		var req any

core/http/endpoints/addons/updates.go

@@ -94,6 +94,7 @@ func GetUpdate(g *gateway.Gateway, db *gorm.DB, opts ...Option) echo.HandlerFunc
 		}
 		id := c.Param("id")
 		if !appID.MatchString(id) {
+			logDenial(c, "invalid-addon-id", nil)
 			return failure(c, 403, "Addon request denied")
 		}
 		if g == nil {
@@ -126,6 +127,7 @@ func updateMutation(g *gateway.Gateway, db *gorm.DB, opts []Option, action strin
 		}
 		id := c.Param("id")
 		if !appID.MatchString(id) {
+			logDenial(c, "invalid-addon-id", nil)
 			return failure(c, 403, "Addon request denied")
 		}
 		req := body()