diff --git a/server/internal/shared/auth/middleware.go b/server/internal/shared/auth/middleware.go index cc7d90f..1a9869f 100644 --- a/server/internal/shared/auth/middleware.go +++ b/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 +} diff --git a/server/internal/shared/middleware/logger.go b/server/internal/shared/middleware/logger.go index 9418505..6754adf 100644 --- a/server/internal/shared/middleware/logger.go +++ b/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...) diff --git a/server/internal/shared/middleware/logger_test.go b/server/internal/shared/middleware/logger_test.go new file mode 100644 index 0000000..a4c949e --- /dev/null +++ b/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":"`) +} diff --git a/server/internal/tenant/app/knowledge_service.go b/server/internal/tenant/app/knowledge_service.go index ef024e6..b6449fb 100644 --- a/server/internal/tenant/app/knowledge_service.go +++ b/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 ""