feat(observability): enrich request logs with auth and knowledge context

- Collect per-request auth diagnostics (header presence, scheme, token
  fingerprint, failure stage/reason, subject, expiry) in the auth
  middleware and expose them through RequestLogContextFromGin so the
  shared logger middleware can emit them.
- Add route, query, user-agent, and referer fields to the request log.
- Log knowledge resolve outcome per stage (no_search_points,
  no_candidate_text, no_active_candidates, rerank_failed_fallback,
  resolved) with candidate/selected snippet previews and precise facts.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

server/internal/shared/auth/middleware.go

@@ -1,24 +1,75 @@
 package auth
 
 import (
+	"errors"
 	"strings"
+	"time"
 
 	"github.com/gin-gonic/gin"
+	"github.com/golang-jwt/jwt/v5"
 
 	"github.com/geo-platform/tenant-api/internal/shared/response"
 )
 
+const authRequestLogContextKey = "auth_request_log_context"
+
+type RequestLogContext struct {
+	HeaderPresent    bool
+	Scheme           string
+	TokenFingerprint string
+	FailureStage     string
+	FailureReason    string
+	ParseError       string
+	TokenSubject     string
+	TokenExpiresAt   string
+}
+
 func Middleware(jwtMgr *Manager, sessions *SessionStore) gin.HandlerFunc {
 	return func(c *gin.Context) {
-		raw, err := bearerToken(c.GetHeader("Authorization"))
+		header := c.GetHeader("Authorization")
+		updateRequestLogContext(c, func(meta *RequestLogContext) {
+			meta.HeaderPresent = strings.TrimSpace(header) != ""
+			meta.Scheme = authorizationScheme(header)
+		})
+
+		raw, err := bearerToken(header)
 		if err != nil {
+			updateRequestLogContext(c, func(meta *RequestLogContext) {
+				meta.FailureStage = "read_bearer_token"
+				meta.FailureReason = bearerHeaderFailureReason(header)
+			})
 			response.Error(c, response.ErrUnauthorized(40101, "missing_bearer_token", "Authorization header is required"))
 			c.Abort()
 			return
 		}
+		updateRequestLogContext(c, func(meta *RequestLogContext) {
+			meta.TokenFingerprint = tokenFingerprint(raw)
+		})
 
 		claims, err := jwtMgr.Parse(raw)
-		if err != nil || claims.Subject != "access" {
+		if err != nil {
+			updateRequestLogContext(c, func(meta *RequestLogContext) {
+				meta.FailureStage = "parse_access_token"
+				meta.FailureReason = accessTokenFailureReason(err)
+				meta.ParseError = err.Error()
+			})
+			response.Error(c, response.ErrUnauthorized(40102, "invalid_access_token", "token is invalid or expired"))
+			c.Abort()
+			return
+		}
+
+		updateRequestLogContext(c, func(meta *RequestLogContext) {
+			meta.TokenSubject = strings.TrimSpace(claims.Subject)
+			if claims.ExpiresAt != nil {
+				meta.TokenExpiresAt = claims.ExpiresAt.Time.UTC().Format(time.RFC3339)
+			}
+		})
+
+		if claims.Subject != "access" {
+			updateRequestLogContext(c, func(meta *RequestLogContext) {
+				meta.FailureStage = "validate_access_subject"
+				meta.FailureReason = "wrong_subject"
+			})
 			response.Error(c, response.ErrUnauthorized(40102, "invalid_access_token", "token is invalid or expired"))
 			c.Abort()
 			return
@@ -26,6 +77,10 @@ func Middleware(jwtMgr *Manager, sessions *SessionStore) gin.HandlerFunc {
 
 		revoked, _ := sessions.IsBlacklisted(c.Request.Context(), claims.ID)
 		if revoked {
+			updateRequestLogContext(c, func(meta *RequestLogContext) {
+				meta.FailureStage = "check_blacklist"
+				meta.FailureReason = "blacklisted"
+			})
 			response.Error(c, response.ErrUnauthorized(40103, "token_revoked", "token has been logged out"))
 			c.Abort()
 			return
@@ -48,3 +103,99 @@ func bearerToken(header string) (string, error) {
 	}
 	return parts[1], nil
 }
+
+func RequestLogContextFromGin(c *gin.Context) (RequestLogContext, bool) {
+	if c == nil {
+		return RequestLogContext{}, false
+	}
+
+	value, ok := c.Get(authRequestLogContextKey)
+	if !ok || value == nil {
+		return RequestLogContext{}, false
+	}
+
+	meta, ok := value.(*RequestLogContext)
+	if !ok || meta == nil {
+		return RequestLogContext{}, false
+	}
+
+	return *meta, true
+}
+
+func updateRequestLogContext(c *gin.Context, apply func(*RequestLogContext)) {
+	if c == nil || apply == nil {
+		return
+	}
+
+	value, ok := c.Get(authRequestLogContextKey)
+	if ok {
+		if meta, ok := value.(*RequestLogContext); ok && meta != nil {
+			apply(meta)
+			return
+		}
+	}
+
+	meta := &RequestLogContext{}
+	apply(meta)
+	c.Set(authRequestLogContextKey, meta)
+}
+
+func authorizationScheme(header string) string {
+	parts := strings.Fields(strings.TrimSpace(header))
+	if len(parts) == 0 {
+		return ""
+	}
+	return parts[0]
+}
+
+func bearerHeaderFailureReason(header string) string {
+	trimmed := strings.TrimSpace(header)
+	if trimmed == "" {
+		return "missing_authorization_header"
+	}
+
+	parts := strings.Fields(trimmed)
+	if len(parts) == 0 {
+		return "missing_authorization_header"
+	}
+	if !strings.EqualFold(parts[0], "bearer") {
+		return "invalid_authorization_scheme"
+	}
+	if len(parts) == 1 {
+		return "missing_token_after_bearer"
+	}
+	return "malformed_authorization_header"
+}
+
+func accessTokenFailureReason(err error) string {
+	switch {
+	case err == nil:
+		return ""
+	case errors.Is(err, jwt.ErrTokenExpired):
+		return "expired"
+	case errors.Is(err, jwt.ErrTokenNotValidYet):
+		return "not_valid_yet"
+	case errors.Is(err, jwt.ErrTokenMalformed):
+		return "malformed"
+	case errors.Is(err, jwt.ErrTokenSignatureInvalid):
+		return "bad_signature"
+	case errors.Is(err, jwt.ErrTokenUnverifiable):
+		return "unverifiable"
+	case errors.Is(err, jwt.ErrTokenInvalidClaims):
+		return "invalid_claims"
+	default:
+		return "parse_failed"
+	}
+}
+
+func tokenFingerprint(raw string) string {
+	if strings.TrimSpace(raw) == "" {
+		return ""
+	}
+
+	hashed := HashToken(raw)
+	if len(hashed) > 16 {
+		return hashed[:16]
+	}
+	return hashed
+}

server/internal/shared/middleware/logger.go

@@ -6,6 +6,7 @@ import (
 	"github.com/gin-gonic/gin"
 	"go.uber.org/zap"
 
+	"github.com/geo-platform/tenant-api/internal/shared/auth"
 	"github.com/geo-platform/tenant-api/internal/shared/response"
 )
 
@@ -22,6 +23,18 @@ func Logger(logger *zap.Logger) gin.HandlerFunc {
 			zap.String("request_id", RequestIDFromGin(c)),
 			zap.String("client_ip", c.ClientIP()),
 		}
+		if route := c.FullPath(); route != "" {
+			fields = append(fields, zap.String("route", route))
+		}
+		if rawQuery := c.Request.URL.RawQuery; rawQuery != "" {
+			fields = append(fields, zap.String("query", rawQuery))
+		}
+		if userAgent := c.Request.UserAgent(); userAgent != "" {
+			fields = append(fields, zap.String("user_agent", userAgent))
+		}
+		if referer := c.Request.Referer(); referer != "" {
+			fields = append(fields, zap.String("referer", referer))
+		}
 
 		if appErr, ok := response.AppErrorFromGin(c); ok {
 			fields = append(fields,
@@ -38,6 +51,31 @@ func Logger(logger *zap.Logger) gin.HandlerFunc {
 			fields = append(fields, zap.String("error", c.Errors.String()))
 		}
 
+		if authCtx, ok := auth.RequestLogContextFromGin(c); ok {
+			fields = append(fields, zap.Bool("auth_header_present", authCtx.HeaderPresent))
+			if authCtx.Scheme != "" {
+				fields = append(fields, zap.String("auth_scheme", authCtx.Scheme))
+			}
+			if authCtx.TokenFingerprint != "" {
+				fields = append(fields, zap.String("auth_token_fingerprint", authCtx.TokenFingerprint))
+			}
+			if authCtx.FailureStage != "" {
+				fields = append(fields, zap.String("auth_failure_stage", authCtx.FailureStage))
+			}
+			if authCtx.FailureReason != "" {
+				fields = append(fields, zap.String("auth_failure_reason", authCtx.FailureReason))
+			}
+			if authCtx.ParseError != "" {
+				fields = append(fields, zap.String("auth_parse_error", authCtx.ParseError))
+			}
+			if authCtx.TokenSubject != "" {
+				fields = append(fields, zap.String("auth_token_subject", authCtx.TokenSubject))
+			}
+			if authCtx.TokenExpiresAt != "" {
+				fields = append(fields, zap.String("auth_token_expires_at", authCtx.TokenExpiresAt))
+			}
+		}
+
 		switch status := c.Writer.Status(); {
 		case status >= 500:
 			logger.Error("request", fields...)

server/internal/shared/middleware/logger_test.go

@@ -0,0 +1,74 @@
+package middleware
+
+import (
+	"bytes"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+	"time"
+
+	"github.com/alicebob/miniredis/v2"
+	"github.com/gin-gonic/gin"
+	goredis "github.com/redis/go-redis/v9"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	sharedauth "github.com/geo-platform/tenant-api/internal/shared/auth"
+)
+
+func TestLoggerIncludesDetailedAuthFailureContext(t *testing.T) {
+	t.Parallel()
+
+	gin.SetMode(gin.TestMode)
+
+	var logBuffer bytes.Buffer
+	encoderConfig := zap.NewProductionEncoderConfig()
+	encoderConfig.TimeKey = ""
+	logger := zap.New(zapcore.NewCore(
+		zapcore.NewJSONEncoder(encoderConfig),
+		zapcore.AddSync(&logBuffer),
+		zapcore.DebugLevel,
+	))
+
+	mr := miniredis.RunT(t)
+	rdb := goredis.NewClient(&goredis.Options{Addr: mr.Addr()})
+	mgr := sharedauth.NewManager("logger-test-secret", -1*time.Minute, 7*24*time.Hour)
+	sessions := sharedauth.NewSessionStore(rdb)
+
+	pair, err := mgr.Issue(7, 42, "editor")
+	require.NoError(t, err)
+
+	router := gin.New()
+	router.Use(RequestID())
+	router.Use(Logger(logger))
+	router.Use(sharedauth.Middleware(mgr, sessions))
+	router.GET("/test", func(c *gin.Context) {
+		c.Status(http.StatusOK)
+	})
+
+	req := httptest.NewRequest(http.MethodGet, "/test?tab=cards", nil)
+	req.Header.Set("Authorization", "Bearer "+pair.AccessToken)
+	req.Header.Set("User-Agent", "geo-rankly-test/1.0")
+	resp := httptest.NewRecorder()
+
+	router.ServeHTTP(resp, req)
+
+	require.Equal(t, http.StatusUnauthorized, resp.Code)
+
+	logLine := logBuffer.String()
+	t.Log(logLine)
+
+	require.Contains(t, logLine, `"msg":"request"`)
+	require.Contains(t, logLine, `"status":401`)
+	require.Contains(t, logLine, `"route":"/test"`)
+	require.Contains(t, logLine, `"query":"tab=cards"`)
+	require.Contains(t, logLine, `"user_agent":"geo-rankly-test/1.0"`)
+	require.Contains(t, logLine, `"app_message":"invalid_access_token"`)
+	require.Contains(t, logLine, `"auth_header_present":true`)
+	require.Contains(t, logLine, `"auth_scheme":"Bearer"`)
+	require.Contains(t, logLine, `"auth_failure_stage":"parse_access_token"`)
+	require.Contains(t, logLine, `"auth_failure_reason":"expired"`)
+	require.Contains(t, logLine, `"auth_parse_error":"token has invalid claims: token is expired"`)
+	require.Contains(t, logLine, `"auth_token_fingerprint":"`)
+}

server/internal/tenant/app/knowledge_service.go

@@ -790,6 +790,7 @@ func (s *KnowledgeService) ResolveContext(
 		return nil, response.ErrServiceUnavailable(50354, "qdrant_search_failed", err.Error())
 	}
 	if len(searchPoints) == 0 {
+		s.logKnowledgeResolve(baseContext, tenantID, query, "no_search_points", nil, nil)
 		return baseContext, nil
 	}
 
@@ -812,6 +813,7 @@ func (s *KnowledgeService) ResolveContext(
 		documents = append(documents, text)
 	}
 	if len(candidates) == 0 {
+		s.logKnowledgeResolve(baseContext, tenantID, query, "no_candidate_text", nil, nil)
 		return baseContext, nil
 	}
 
@@ -820,6 +822,7 @@ func (s *KnowledgeService) ResolveContext(
 		return nil, err
 	}
 	if len(candidates) == 0 {
+		s.logKnowledgeResolve(baseContext, tenantID, query, "no_active_candidates", nil, nil)
 		return baseContext, nil
 	}
 
@@ -834,6 +837,7 @@ func (s *KnowledgeService) ResolveContext(
 		selected = s.enrichKnowledgePromptSnippets(ctx, tenantID, selected)
 		baseContext.Snippets = selected
 		baseContext.PreciseFacts = s.collectKnowledgeContextPreciseFacts(ctx, tenantID, groupIDs, selected)
+		s.logKnowledgeResolve(baseContext, tenantID, query, "rerank_failed_fallback", candidates, selected)
 		return baseContext, nil
 	}
 
@@ -853,9 +857,97 @@ func (s *KnowledgeService) ResolveContext(
 	selected = s.enrichKnowledgePromptSnippets(ctx, tenantID, selected)
 	baseContext.Snippets = selected
 	baseContext.PreciseFacts = s.collectKnowledgeContextPreciseFacts(ctx, tenantID, groupIDs, selected)
+	s.logKnowledgeResolve(baseContext, tenantID, query, "resolved", candidates, selected)
 	return baseContext, nil
 }
 
+func (s *KnowledgeService) logKnowledgeResolve(
+	knowledgeCtx *KnowledgeContext,
+	tenantID int64,
+	query string,
+	stage string,
+	candidates []KnowledgeSnippet,
+	selected []KnowledgeSnippet,
+) {
+	if s == nil || s.logger == nil || knowledgeCtx == nil {
+		return
+	}
+
+	s.logger.Info("knowledge resolve result",
+		zap.String("stage", strings.TrimSpace(stage)),
+		zap.Int64("tenant_id", tenantID),
+		zap.Int64s("group_ids", knowledgeCtx.GroupIDs),
+		zap.Strings("group_names", knowledgeCtx.GroupNames),
+		zap.String("query", knowledgeLogPreview(query, 600)),
+		zap.Int("candidate_count", len(candidates)),
+		zap.Int("selected_count", len(selected)),
+		zap.Int("precise_fact_count", len(knowledgeCtx.PreciseFacts)),
+		zap.Any("candidates", summarizeKnowledgeSnippetsForLog(candidates)),
+		zap.Any("selected_snippets", summarizeKnowledgeSnippetsForLog(selected)),
+		zap.Strings("precise_facts", summarizeKnowledgeFactsForLog(knowledgeCtx.PreciseFacts)),
+	)
+}
+
+func summarizeKnowledgeSnippetsForLog(snippets []KnowledgeSnippet) []map[string]any {
+	if len(snippets) == 0 {
+		return []map[string]any{}
+	}
+
+	summary := make([]map[string]any, 0, len(snippets))
+	for _, snippet := range snippets {
+		entry := map[string]any{
+			"point_id":   snippet.PointID,
+			"group_id":   snippet.GroupID,
+			"group_name": strings.TrimSpace(snippet.GroupName),
+			"item_id":    snippet.KnowledgeItemID,
+			"item_name":  strings.TrimSpace(snippet.ItemName),
+			"score":      snippet.Score,
+			"text":       knowledgeLogPreview(snippet.Text, 240),
+		}
+		if sourceType := strings.TrimSpace(snippet.SourceType); sourceType != "" {
+			entry["source_type"] = sourceType
+		}
+		if sourceURI := strings.TrimSpace(derefKnowledgeString(snippet.SourceURI)); sourceURI != "" {
+			entry["source_uri"] = sourceURI
+		}
+		if len(snippet.PreciseFacts) > 0 {
+			entry["precise_facts"] = summarizeKnowledgeFactsForLog(snippet.PreciseFacts)
+		}
+		summary = append(summary, entry)
+	}
+	return summary
+}
+
+func summarizeKnowledgeFactsForLog(facts []string) []string {
+	if len(facts) == 0 {
+		return []string{}
+	}
+
+	limit := len(facts)
+	if limit > 12 {
+		limit = 12
+	}
+
+	summary := make([]string, 0, limit)
+	for _, fact := range facts[:limit] {
+		summary = append(summary, knowledgeLogPreview(fact, 240))
+	}
+	return summary
+}
+
+func knowledgeLogPreview(value string, maxRunes int) string {
+	text := strings.TrimSpace(value)
+	if text == "" {
+		return ""
+	}
+
+	runes := []rune(text)
+	if maxRunes <= 0 || len(runes) <= maxRunes {
+		return text
+	}
+	return strings.TrimSpace(string(runes[:maxRunes])) + "..."
+}
+
 func (s *KnowledgeService) RenderPromptSection(ctx *KnowledgeContext) string {
 	if ctx == nil || (len(ctx.Snippets) == 0 && len(ctx.PreciseFacts) == 0) {
 		return ""