From 569a4e9ce7a60f2d2c5e3a9c45de2a967fb39ff2 Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Wed, 8 Apr 2026 22:44:59 +0800 Subject: [PATCH 01/12] fix(audit): populate missing actor and request metadata in audit logs - Resolve ActorUsername via DB lookup for 11 audit entries in token exchange, refresh, and management paths where sessionless API context left the field empty - Add RequestContextMiddleware to propagate UserAgent, RequestPath, and RequestMethod through request context for all downstream audit logging - Enrich buildAuditLog with context fallback for request metadata fields - Drain logChan on shutdown to prevent silent audit event loss - Add Prometheus counter for audit events dropped due to buffer overflow - Consolidate duplicate GetUserByID call in ExchangeAuthorizationCode - Remove dead IPMiddleware wrapper and update stale references Co-Authored-By: Claude Opus 4.6 (1M context) --- internal/bootstrap/router.go | 2 +- internal/handlers/auth.go | 2 +- internal/handlers/oauth_handler.go | 2 +- internal/middleware/auth.go | 2 +- internal/middleware/context.go | 17 +++-- internal/services/audit.go | 34 +++++++++- internal/services/audit_test.go | 98 +++++++++++++++++++++++++++ internal/services/token.go | 10 +++ internal/services/token_exchange.go | 90 +++++++++++++----------- internal/services/token_management.go | 68 +++++++++++-------- internal/services/token_refresh.go | 33 +++++---- internal/util/context.go | 38 +++++++++++ internal/util/context_test.go | 29 ++++++++ 13 files changed, 332 insertions(+), 93 deletions(-) diff --git a/internal/bootstrap/router.go b/internal/bootstrap/router.go index 9de6de51..0c0a3064 100644 --- a/internal/bootstrap/router.go +++ b/internal/bootstrap/router.go @@ -44,7 +44,7 @@ func setupRouter( // Setup middleware r.Use(metrics.HTTPMetricsMiddleware(prometheusMetrics)) r.Use(gin.Logger(), gin.Recovery()) - r.Use(middleware.IPMiddleware()) + r.Use(middleware.RequestContextMiddleware()) r.Use(middleware.SecurityHeaders(strings.HasPrefix(cfg.BaseURL, "https://"))) // Setup session middleware diff --git a/internal/handlers/auth.go b/internal/handlers/auth.go index cb98b6f5..e0316344 100644 --- a/internal/handlers/auth.go +++ b/internal/handlers/auth.go @@ -170,7 +170,7 @@ func (h *AuthHandler) Login(c *gin.Context, // Set session fingerprint if enabled if h.cfg.SessionFingerprint { - clientIP := c.GetString(middleware.ContextKeyClientIP) // Set by IPMiddleware + clientIP := c.GetString(middleware.ContextKeyClientIP) // Set by RequestContextMiddleware userAgent := c.Request.UserAgent() fingerprint := middleware.GenerateFingerprint( clientIP, diff --git a/internal/handlers/oauth_handler.go b/internal/handlers/oauth_handler.go index bc3aef4c..9ff9d8bf 100644 --- a/internal/handlers/oauth_handler.go +++ b/internal/handlers/oauth_handler.go @@ -230,7 +230,7 @@ func (h *OAuthHandler) OAuthCallback(c *gin.Context) { // Set session fingerprint if enabled if h.sessionFingerprintEnabled { - clientIP := c.GetString(middleware.ContextKeyClientIP) // Set by IPMiddleware + clientIP := c.GetString(middleware.ContextKeyClientIP) // Set by RequestContextMiddleware userAgent := c.Request.UserAgent() fingerprint := middleware.GenerateFingerprint( clientIP, diff --git a/internal/middleware/auth.go b/internal/middleware/auth.go index 42f7946c..5383387f 100644 --- a/internal/middleware/auth.go +++ b/internal/middleware/auth.go @@ -146,7 +146,7 @@ func SessionFingerprintMiddleware(enabled, includeIP bool) gin.HandlerFunc { if storedFingerprint != nil { // Get current fingerprint - clientIP := c.GetString(ContextKeyClientIP) // Set by IPMiddleware + clientIP := c.GetString(ContextKeyClientIP) // Set by RequestContextMiddleware userAgent := c.Request.UserAgent() currentFingerprint := GenerateFingerprint(clientIP, userAgent, includeIP) diff --git a/internal/middleware/context.go b/internal/middleware/context.go index 9d63b17d..3d1a0f97 100644 --- a/internal/middleware/context.go +++ b/internal/middleware/context.go @@ -8,15 +8,24 @@ import ( // ContextKeyClientIP is the gin context key for the client IP address. const ContextKeyClientIP = "client_ip" -// IPMiddleware extracts client IP and stores it in the context -func IPMiddleware() gin.HandlerFunc { +// RequestContextMiddleware extracts client IP and HTTP request metadata +// (User-Agent, path, method) and stores them in the request context for +// downstream services (e.g. audit logging). +func RequestContextMiddleware() gin.HandlerFunc { return func(c *gin.Context) { clientIP := c.ClientIP() // Gin's ClientIP() handles X-Forwarded-For and other headers c.Set(ContextKeyClientIP, clientIP) - // Also store in request context for services layer - c.Request = c.Request.WithContext(util.SetIPContext(c.Request.Context(), clientIP)) + // Store IP and request metadata in request context for services layer + ctx := util.SetIPContext(c.Request.Context(), clientIP) + ctx = util.SetRequestMetadataContext( + ctx, + c.Request.UserAgent(), + c.Request.URL.Path, + c.Request.Method, + ) + c.Request = c.Request.WithContext(ctx) c.Next() } diff --git a/internal/services/audit.go b/internal/services/audit.go index 68d73e20..74f3a713 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -14,6 +14,8 @@ import ( "github.com/go-authgate/authgate/internal/util" "github.com/google/uuid" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promauto" ) // Compile-time interface check. @@ -35,6 +37,9 @@ type AuditService struct { // Graceful shutdown wg sync.WaitGroup shutdownCh chan struct{} + + // Prometheus counter for dropped events + eventsDropped prometheus.Counter } // NewAuditService creates a new audit service @@ -49,6 +54,12 @@ func NewAuditService(s core.Store, bufferSize int) *AuditService { logChan: make(chan *models.AuditLog, bufferSize), batchBuffer: make([]*models.AuditLog, 0, 100), shutdownCh: make(chan struct{}), + eventsDropped: promauto.NewCounter(prometheus.CounterOpts{ + Namespace: "authgate", + Subsystem: "audit", + Name: "events_dropped_total", + Help: "Total number of audit log events dropped due to a full buffer.", + }), } service.batchTicker = time.NewTicker(1 * time.Second) @@ -73,9 +84,16 @@ func (s *AuditService) worker() { s.flushBatch() case <-s.shutdownCh: - // Flush remaining logs before shutdown - s.flushBatch() - return + // Drain remaining events from logChan before shutdown + for { + select { + case entry := <-s.logChan: + s.addToBatch(entry) + default: + s.flushBatch() + return + } + } } } } @@ -132,6 +150,15 @@ func (s *AuditService) buildAuditLog( if entry.ActorUserID == "" { entry.ActorUserID = models.GetUserIDFromContext(ctx) } + if entry.UserAgent == "" { + entry.UserAgent = util.GetUserAgentFromContext(ctx) + } + if entry.RequestPath == "" { + entry.RequestPath = util.GetRequestPathFromContext(ctx) + } + if entry.RequestMethod == "" { + entry.RequestMethod = util.GetRequestMethodFromContext(ctx) + } entry.Details = maskSensitiveDetails(entry.Details) now := time.Now() @@ -164,6 +191,7 @@ func (s *AuditService) Log(ctx context.Context, entry core.AuditLogEntry) { case s.logChan <- auditLog: default: log.Printf("WARNING: Audit log buffer full, dropping event: %s", entry.Action) + s.eventsDropped.Inc() } } diff --git a/internal/services/audit_test.go b/internal/services/audit_test.go index a8bc5a8e..f5174e6e 100644 --- a/internal/services/audit_test.go +++ b/internal/services/audit_test.go @@ -1,10 +1,14 @@ package services import ( + "context" "testing" + "github.com/go-authgate/authgate/internal/core" "github.com/go-authgate/authgate/internal/models" + "github.com/go-authgate/authgate/internal/util" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func TestMaskSensitiveDetails_FullRedaction(t *testing.T) { @@ -70,3 +74,97 @@ func TestMaskSensitiveDetails_PlainField(t *testing.T) { func TestMaskSensitiveDetails_Nil(t *testing.T) { assert.Nil(t, maskSensitiveDetails(nil)) } + +func TestBuildAuditLog_EnrichesRequestMetadataFromContext(t *testing.T) { + svc := &AuditService{} + + ctx := context.Background() + ctx = util.SetIPContext(ctx, "10.0.0.1") + ctx = util.SetRequestMetadataContext(ctx, "Mozilla/5.0", "/oauth/token", "POST") + + entry := core.AuditLogEntry{ + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + Action: "test", + Success: true, + } + + result := svc.buildAuditLog(ctx, entry) + + assert.Equal(t, "10.0.0.1", result.ActorIP) + assert.Equal(t, "Mozilla/5.0", result.UserAgent) + assert.Equal(t, "/oauth/token", result.RequestPath) + assert.Equal(t, "POST", result.RequestMethod) +} + +func TestBuildAuditLog_DoesNotOverrideExplicitValues(t *testing.T) { + svc := &AuditService{} + + ctx := context.Background() + ctx = util.SetIPContext(ctx, "10.0.0.1") + ctx = util.SetRequestMetadataContext(ctx, "Mozilla/5.0", "/oauth/token", "POST") + + entry := core.AuditLogEntry{ + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + ActorIP: "192.168.1.1", + UserAgent: "custom-agent", + RequestPath: "/custom/path", + RequestMethod: "GET", + Action: "test", + Success: true, + } + + result := svc.buildAuditLog(ctx, entry) + + // Explicit values should be preserved, not overwritten by context + assert.Equal(t, "192.168.1.1", result.ActorIP) + assert.Equal(t, "custom-agent", result.UserAgent) + assert.Equal(t, "/custom/path", result.RequestPath) + assert.Equal(t, "GET", result.RequestMethod) +} + +func TestBuildAuditLog_EnrichesUserFromContext(t *testing.T) { + svc := &AuditService{} + + user := &models.User{ + ID: "user-123", + Username: "testuser", + } + ctx := models.SetUserContext(context.Background(), user) + + entry := core.AuditLogEntry{ + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + Action: "test", + Success: true, + } + + result := svc.buildAuditLog(ctx, entry) + + assert.Equal(t, "user-123", result.ActorUserID) + assert.Equal(t, "testuser", result.ActorUsername) +} + +func TestShutdown_DrainsLogChan(t *testing.T) { + // Build the service manually so we can use a real store and avoid nil panics. + s := setupTestStore(t) + svc := NewAuditService(s, 100) + + // Directly enqueue entries into logChan (bypass Log to avoid buildAuditLog) + for i := range 5 { + svc.logChan <- &models.AuditLog{ + ID: "drain-test-" + string(rune('0'+i)), + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + Action: "drain-test", + } + } + + // Shutdown should drain all entries without losing them + err := svc.Shutdown(context.Background()) + require.NoError(t, err) + + // logChan should be empty after shutdown + assert.Empty(t, svc.logChan) +} diff --git a/internal/services/token.go b/internal/services/token.go index 0866c9f3..472c9c0c 100644 --- a/internal/services/token.go +++ b/internal/services/token.go @@ -79,6 +79,16 @@ func NewTokenService( } } +// resolveUsername looks up the username for a given userID. +// Returns empty string on error (best-effort for audit logging). +func (s *TokenService) resolveUsername(userID string) string { + user, err := s.store.GetUserByID(userID) + if err != nil { + return "" + } + return user.Username +} + // getAccessTokenByHash looks up a token, using cache if available. // On cache backend errors (e.g. Redis unavailable), falls back to direct DB lookup // so that valid tokens are not rejected due to cache infrastructure issues. diff --git a/internal/services/token_exchange.go b/internal/services/token_exchange.go index 89180553..c1bcb3ec 100644 --- a/internal/services/token_exchange.go +++ b/internal/services/token_exchange.go @@ -78,13 +78,16 @@ func (s *TokenService) ExchangeDeviceCode( _ = s.store.DeleteDeviceCodeByID(dc.ID) // Log token issuance + actorUsername := s.resolveUsername(accessToken.UserID) + s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventAccessTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: accessToken.UserID, - ResourceType: models.ResourceToken, - ResourceID: accessToken.ID, - Action: "Access token issued via device code exchange", + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: accessToken.UserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: accessToken.ID, + Action: "Access token issued via device code exchange", Details: models.AuditDetails{ "client_id": accessToken.ClientID, "scopes": accessToken.Scopes, @@ -95,12 +98,13 @@ func (s *TokenService) ExchangeDeviceCode( }) s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventRefreshTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: refreshToken.UserID, - ResourceType: models.ResourceToken, - ResourceID: refreshToken.ID, - Action: "Refresh token issued via device code exchange", + EventType: models.EventRefreshTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: refreshToken.UserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: refreshToken.ID, + Action: "Refresh token issued via device code exchange", Details: models.AuditDetails{ "client_id": refreshToken.ClientID, "scopes": refreshToken.Scopes, @@ -137,6 +141,13 @@ func (s *TokenService) ExchangeAuthorizationCode( return nil, nil, "", err } + // Fetch user once for both audit logging (username) and ID token profile claims. + actorUser, actorUserErr := s.store.GetUserByID(authCode.UserID) + actorUsername := "" + if actorUserErr == nil { + actorUsername = actorUser.Username + } + // Generate OIDC ID Token when openid scope was granted (OIDC Core 1.0 §3.1.3.3). // ID tokens are not stored in the database; they are short-lived and non-revocable. // ID token generation is only supported when the provider implements IDTokenProvider. @@ -153,36 +164,37 @@ func (s *TokenService) ExchangeAuthorizationCode( AtHash: token.ComputeAtHash(accessToken.RawToken), } - // Fetch user profile for scope-gated claims - if user, err := s.store.GetUserByID(authCode.UserID); err == nil { + // Populate scope-gated claims from the user fetched above + if actorUserErr == nil { if scopeSet["profile"] { - params.Name = user.FullName - params.PreferredUsername = user.Username - params.Picture = user.AvatarURL - updatedAt := user.UpdatedAt + params.Name = actorUser.FullName + params.PreferredUsername = actorUser.Username + params.Picture = actorUser.AvatarURL + updatedAt := actorUser.UpdatedAt params.UpdatedAt = &updatedAt } if scopeSet["email"] { - params.Email = user.Email + params.Email = actorUser.Email params.EmailVerified = false // AuthGate does not verify email addresses } } else if scopeSet["profile"] || scopeSet["email"] { log.Printf( "[Token] ID token: failed to fetch user profile for user_id=%s, profile/email claims will be omitted: %v", authCode.UserID, - err, + actorUserErr, ) } if generated, err := idp.GenerateIDToken(params); err == nil { idToken = generated s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventIDTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: authCode.UserID, - ResourceType: models.ResourceToken, - ResourceID: accessToken.ID, - Action: "ID token issued via authorization code exchange", + EventType: models.EventIDTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: authCode.UserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: accessToken.ID, + Action: "ID token issued via authorization code exchange", Details: models.AuditDetails{ "client_id": authCode.ClientID, "scopes": authCode.Scopes, @@ -204,12 +216,13 @@ func (s *TokenService) ExchangeAuthorizationCode( // Audit s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventAccessTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: accessToken.UserID, - ResourceType: models.ResourceToken, - ResourceID: accessToken.ID, - Action: "Access token issued via authorization code exchange", + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: accessToken.UserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: accessToken.ID, + Action: "Access token issued via authorization code exchange", Details: models.AuditDetails{ "client_id": accessToken.ClientID, "scopes": accessToken.Scopes, @@ -219,12 +232,13 @@ func (s *TokenService) ExchangeAuthorizationCode( Success: true, }) s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventRefreshTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: refreshToken.UserID, - ResourceType: models.ResourceToken, - ResourceID: refreshToken.ID, - Action: "Refresh token issued via authorization code exchange", + EventType: models.EventRefreshTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: refreshToken.UserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: refreshToken.ID, + Action: "Refresh token issued via authorization code exchange", Details: models.AuditDetails{ "client_id": refreshToken.ClientID, "scopes": refreshToken.Scopes, diff --git a/internal/services/token_management.go b/internal/services/token_management.go index 811cf17f..f49f1ccb 100644 --- a/internal/services/token_management.go +++ b/internal/services/token_management.go @@ -40,19 +40,22 @@ func (s *TokenService) RevokeTokenByID(ctx context.Context, tokenID, actorUserID return err } + actorUsername := s.resolveUsername(actorUserID) + err = s.store.RevokeToken(tokenID) if err != nil { // Log revocation failure s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventTokenRevoked, - Severity: models.SeverityError, - ActorUserID: actorUserID, - ResourceType: models.ResourceToken, - ResourceID: tokenID, - Action: "Token revocation failed", - Details: models.AuditDetails{"token_category": tok.TokenCategory}, - Success: false, - ErrorMessage: err.Error(), + EventType: models.EventTokenRevoked, + Severity: models.SeverityError, + ActorUserID: actorUserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: tokenID, + Action: "Token revocation failed", + Details: models.AuditDetails{"token_category": tok.TokenCategory}, + Success: false, + ErrorMessage: err.Error(), }) return err } @@ -64,12 +67,13 @@ func (s *TokenService) RevokeTokenByID(ctx context.Context, tokenID, actorUserID // Log token revocation s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventTokenRevoked, - Severity: models.SeverityInfo, - ActorUserID: actorUserID, - ResourceType: models.ResourceToken, - ResourceID: tokenID, - Action: "Token revoked", + EventType: models.EventTokenRevoked, + Severity: models.SeverityInfo, + ActorUserID: actorUserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: tokenID, + Action: "Token revoked", Details: models.AuditDetails{ "token_category": tok.TokenCategory, "client_id": tok.ClientID, @@ -131,19 +135,22 @@ func (s *TokenService) updateTokenStatusWithAudit( } } + actorUsername := s.resolveUsername(actorUserID) + err = s.store.UpdateTokenStatus(tokenID, newStatus) if err != nil { // Log failure s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: eventType, - Severity: models.SeverityError, - ActorUserID: actorUserID, - ResourceType: models.ResourceToken, - ResourceID: tokenID, - Action: actionFailed, - Details: models.AuditDetails{"token_category": tok.TokenCategory}, - Success: false, - ErrorMessage: err.Error(), + EventType: eventType, + Severity: models.SeverityError, + ActorUserID: actorUserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: tokenID, + Action: actionFailed, + Details: models.AuditDetails{"token_category": tok.TokenCategory}, + Success: false, + ErrorMessage: err.Error(), }) return err } @@ -152,12 +159,13 @@ func (s *TokenService) updateTokenStatusWithAudit( // Log success s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: eventType, - Severity: models.SeverityInfo, - ActorUserID: actorUserID, - ResourceType: models.ResourceToken, - ResourceID: tokenID, - Action: actionSuccess, + EventType: eventType, + Severity: models.SeverityInfo, + ActorUserID: actorUserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: tokenID, + Action: actionSuccess, Details: models.AuditDetails{ "token_category": tok.TokenCategory, "client_id": tok.ClientID, diff --git a/internal/services/token_refresh.go b/internal/services/token_refresh.go index 42c5fa96..3adbc083 100644 --- a/internal/services/token_refresh.go +++ b/internal/services/token_refresh.go @@ -53,13 +53,16 @@ func (s *TokenService) revokeTokenFamilyWithAudit( } // Audit log — CRITICAL severity because this indicates potential token theft + actorUsername := s.resolveUsername(reusedToken.UserID) + _ = s.auditService.LogSync(ctx, core.AuditLogEntry{ - EventType: models.EventSuspiciousActivity, - Severity: models.SeverityCritical, - ActorUserID: reusedToken.UserID, - ResourceType: models.ResourceToken, - ResourceID: reusedToken.ID, - Action: "Refresh token reuse detected — token family revoked", + EventType: models.EventSuspiciousActivity, + Severity: models.SeverityCritical, + ActorUserID: reusedToken.UserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: reusedToken.ID, + Action: "Refresh token reuse detected — token family revoked", Details: models.AuditDetails{ "family_id": familyID, "reused_token_id": reusedToken.ID, @@ -205,6 +208,7 @@ func (s *TokenService) RefreshAccessToken( s.metrics.RecordTokenRefresh(true) // Log token refresh + actorUsername := s.resolveUsername(newAccessToken.UserID) providerName := s.tokenProvider.Name() details := models.AuditDetails{ "client_id": newAccessToken.ClientID, @@ -220,14 +224,15 @@ func (s *TokenService) RefreshAccessToken( } s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventTokenRefreshed, - Severity: models.SeverityInfo, - ActorUserID: newAccessToken.UserID, - ResourceType: models.ResourceToken, - ResourceID: newAccessToken.ID, - Action: "Access token refreshed", - Details: details, - Success: true, + EventType: models.EventTokenRefreshed, + Severity: models.SeverityInfo, + ActorUserID: newAccessToken.UserID, + ActorUsername: actorUsername, + ResourceType: models.ResourceToken, + ResourceID: newAccessToken.ID, + Action: "Access token refreshed", + Details: details, + Success: true, }) return newAccessToken, newRefreshToken, nil diff --git a/internal/util/context.go b/internal/util/context.go index d60dc27c..5332423b 100644 --- a/internal/util/context.go +++ b/internal/util/context.go @@ -9,6 +9,9 @@ type contextKey int const ( contextKeyClientIP contextKey = iota + contextKeyUserAgent + contextKeyRequestPath + contextKeyRequestMethod ) // SetIPContext embeds client IP into a standard context @@ -27,3 +30,38 @@ func GetIPFromContext(ctx context.Context) string { } return "" } + +// SetRequestMetadataContext embeds HTTP request metadata into a standard context. +func SetRequestMetadataContext( + ctx context.Context, + userAgent, path, method string, +) context.Context { + ctx = context.WithValue(ctx, contextKeyUserAgent, userAgent) + ctx = context.WithValue(ctx, contextKeyRequestPath, path) + ctx = context.WithValue(ctx, contextKeyRequestMethod, method) + return ctx +} + +// GetUserAgentFromContext extracts the User-Agent from the context. +func GetUserAgentFromContext(ctx context.Context) string { + if v, ok := ctx.Value(contextKeyUserAgent).(string); ok { + return v + } + return "" +} + +// GetRequestPathFromContext extracts the request path from the context. +func GetRequestPathFromContext(ctx context.Context) string { + if v, ok := ctx.Value(contextKeyRequestPath).(string); ok { + return v + } + return "" +} + +// GetRequestMethodFromContext extracts the HTTP method from the context. +func GetRequestMethodFromContext(ctx context.Context) string { + if v, ok := ctx.Value(contextKeyRequestMethod).(string); ok { + return v + } + return "" +} diff --git a/internal/util/context_test.go b/internal/util/context_test.go index f147608c..4ae92b52 100644 --- a/internal/util/context_test.go +++ b/internal/util/context_test.go @@ -81,6 +81,35 @@ func TestGetIPFromContext(t *testing.T) { } } +func TestSetRequestMetadataContext(t *testing.T) { + ctx := context.Background() + ctx = SetRequestMetadataContext(ctx, "Mozilla/5.0", "/oauth/token", "POST") + + assert.Equal(t, "Mozilla/5.0", GetUserAgentFromContext(ctx)) + assert.Equal(t, "/oauth/token", GetRequestPathFromContext(ctx)) + assert.Equal(t, "POST", GetRequestMethodFromContext(ctx)) +} + +func TestGetRequestMetadataFromContext_Empty(t *testing.T) { + ctx := context.Background() + + assert.Empty(t, GetUserAgentFromContext(ctx)) + assert.Empty(t, GetRequestPathFromContext(ctx)) + assert.Empty(t, GetRequestMethodFromContext(ctx)) +} + +func TestRequestMetadataContextChaining(t *testing.T) { + ctx := context.Background() + ctx = SetIPContext(ctx, "10.0.0.1") + ctx = SetRequestMetadataContext(ctx, "curl/7.68", "/api/v1", "GET") + + // All values should coexist + assert.Equal(t, "10.0.0.1", GetIPFromContext(ctx)) + assert.Equal(t, "curl/7.68", GetUserAgentFromContext(ctx)) + assert.Equal(t, "/api/v1", GetRequestPathFromContext(ctx)) + assert.Equal(t, "GET", GetRequestMethodFromContext(ctx)) +} + func TestIPContextChaining(t *testing.T) { type testKey int const testKeyOther testKey = 0 From 466c5bd040eb258659600b3dd59e3e3d88e29952 Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Wed, 8 Apr 2026 23:04:03 +0800 Subject: [PATCH 02/12] refactor(audit): prefer context-first username resolution and harden metric registration - Make resolveUsername context-aware: check request context before falling back to DB lookup, avoiding unnecessary queries on authenticated routes - Lazily fetch user profile in ExchangeAuthorizationCode only when openid profile/email claims are needed - Register audit events_dropped_total counter via sync.Once singleton to prevent duplicate-registration panics in tests - Make TestShutdown_DrainsLogChan deterministic by constructing the service without auto-starting the worker and verifying persisted rows Co-Authored-By: Claude Opus 4.6 (1M context) --- internal/services/audit.go | 37 +++++++++++++++------ internal/services/audit_test.go | 37 ++++++++++++++++----- internal/services/token.go | 11 ++++-- internal/services/token_exchange.go | 48 +++++++++++++-------------- internal/services/token_management.go | 4 +-- internal/services/token_refresh.go | 4 +-- 6 files changed, 90 insertions(+), 51 deletions(-) diff --git a/internal/services/audit.go b/internal/services/audit.go index 74f3a713..77082dbf 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -21,6 +21,26 @@ import ( // Compile-time interface check. var _ core.AuditLogger = (*AuditService)(nil) +// auditEventsDropped is a singleton counter registered once via sync.Once +// to avoid duplicate-registration panics when multiple AuditService +// instances are created (e.g. in tests). +var ( + auditEventsDropped prometheus.Counter + auditEventsDroppedOnce sync.Once +) + +func getAuditEventsDroppedCounter() prometheus.Counter { + auditEventsDroppedOnce.Do(func() { + auditEventsDropped = promauto.NewCounter(prometheus.CounterOpts{ + Namespace: "authgate", + Subsystem: "audit", + Name: "events_dropped_total", + Help: "Total number of audit log events dropped due to a full buffer.", + }) + }) + return auditEventsDropped +} + // AuditService handles audit logging operations type AuditService struct { store core.Store @@ -49,17 +69,12 @@ func NewAuditService(s core.Store, bufferSize int) *AuditService { } service := &AuditService{ - store: s, - bufferSize: bufferSize, - logChan: make(chan *models.AuditLog, bufferSize), - batchBuffer: make([]*models.AuditLog, 0, 100), - shutdownCh: make(chan struct{}), - eventsDropped: promauto.NewCounter(prometheus.CounterOpts{ - Namespace: "authgate", - Subsystem: "audit", - Name: "events_dropped_total", - Help: "Total number of audit log events dropped due to a full buffer.", - }), + store: s, + bufferSize: bufferSize, + logChan: make(chan *models.AuditLog, bufferSize), + batchBuffer: make([]*models.AuditLog, 0, 100), + shutdownCh: make(chan struct{}), + eventsDropped: getAuditEventsDroppedCounter(), } service.batchTicker = time.NewTicker(1 * time.Second) diff --git a/internal/services/audit_test.go b/internal/services/audit_test.go index f5174e6e..9f550d3c 100644 --- a/internal/services/audit_test.go +++ b/internal/services/audit_test.go @@ -2,10 +2,13 @@ package services import ( "context" + "fmt" "testing" + "time" "github.com/go-authgate/authgate/internal/core" "github.com/go-authgate/authgate/internal/models" + storetypes "github.com/go-authgate/authgate/internal/store/types" "github.com/go-authgate/authgate/internal/util" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -147,24 +150,42 @@ func TestBuildAuditLog_EnrichesUserFromContext(t *testing.T) { } func TestShutdown_DrainsLogChan(t *testing.T) { - // Build the service manually so we can use a real store and avoid nil panics. + // Construct the service struct directly (without starting the worker) + // so we can populate the channel deterministically before the drain runs. s := setupTestStore(t) - svc := NewAuditService(s, 100) + svc := &AuditService{ + store: s, + bufferSize: 100, + logChan: make(chan *models.AuditLog, 100), + batchBuffer: make([]*models.AuditLog, 0, 100), + shutdownCh: make(chan struct{}), + eventsDropped: getAuditEventsDroppedCounter(), + } - // Directly enqueue entries into logChan (bypass Log to avoid buildAuditLog) - for i := range 5 { + // Populate the channel before the worker starts + const numEntries = 5 + for i := range numEntries { svc.logChan <- &models.AuditLog{ - ID: "drain-test-" + string(rune('0'+i)), + ID: fmt.Sprintf("drain-test-%d", i), EventType: models.EventAccessTokenIssued, Severity: models.SeverityInfo, Action: "drain-test", } } - // Shutdown should drain all entries without losing them + // Now start the worker and immediately shut down + svc.batchTicker = time.NewTicker(1 * time.Second) + svc.wg.Add(1) + go svc.worker() + err := svc.Shutdown(context.Background()) require.NoError(t, err) - // logChan should be empty after shutdown - assert.Empty(t, svc.logChan) + // Verify entries were persisted to the store + logs, _, err := s.GetAuditLogsPaginated( + storetypes.PaginationParams{Page: 1, PageSize: 10}, + storetypes.AuditLogFilters{}, + ) + require.NoError(t, err) + assert.GreaterOrEqual(t, len(logs), numEntries, "all drain-test entries should be persisted") } diff --git a/internal/services/token.go b/internal/services/token.go index 472c9c0c..2cb17b8b 100644 --- a/internal/services/token.go +++ b/internal/services/token.go @@ -79,9 +79,14 @@ func NewTokenService( } } -// resolveUsername looks up the username for a given userID. -// Returns empty string on error (best-effort for audit logging). -func (s *TokenService) resolveUsername(userID string) string { +// resolveUsername returns the username for a given userID. +// It first checks the request context (populated by auth middleware for +// authenticated routes), falling back to a DB lookup only when the context +// does not carry the user. Returns empty string on error (best-effort). +func (s *TokenService) resolveUsername(ctx context.Context, userID string) string { + if username := models.GetUsernameFromContext(ctx); username != "" { + return username + } user, err := s.store.GetUserByID(userID) if err != nil { return "" diff --git a/internal/services/token_exchange.go b/internal/services/token_exchange.go index c1bcb3ec..6139d0e5 100644 --- a/internal/services/token_exchange.go +++ b/internal/services/token_exchange.go @@ -78,7 +78,7 @@ func (s *TokenService) ExchangeDeviceCode( _ = s.store.DeleteDeviceCodeByID(dc.ID) // Log token issuance - actorUsername := s.resolveUsername(accessToken.UserID) + actorUsername := s.resolveUsername(ctx, accessToken.UserID) s.auditService.Log(ctx, core.AuditLogEntry{ EventType: models.EventAccessTokenIssued, @@ -141,12 +141,8 @@ func (s *TokenService) ExchangeAuthorizationCode( return nil, nil, "", err } - // Fetch user once for both audit logging (username) and ID token profile claims. - actorUser, actorUserErr := s.store.GetUserByID(authCode.UserID) - actorUsername := "" - if actorUserErr == nil { - actorUsername = actorUser.Username - } + // Resolve username from context (set by auth middleware) or DB fallback. + actorUsername := s.resolveUsername(ctx, authCode.UserID) // Generate OIDC ID Token when openid scope was granted (OIDC Core 1.0 §3.1.3.3). // ID tokens are not stored in the database; they are short-lived and non-revocable. @@ -164,25 +160,27 @@ func (s *TokenService) ExchangeAuthorizationCode( AtHash: token.ComputeAtHash(accessToken.RawToken), } - // Populate scope-gated claims from the user fetched above - if actorUserErr == nil { - if scopeSet["profile"] { - params.Name = actorUser.FullName - params.PreferredUsername = actorUser.Username - params.Picture = actorUser.AvatarURL - updatedAt := actorUser.UpdatedAt - params.UpdatedAt = &updatedAt - } - if scopeSet["email"] { - params.Email = actorUser.Email - params.EmailVerified = false // AuthGate does not verify email addresses + // Fetch user profile only when scope-gated claims are needed + if scopeSet["profile"] || scopeSet["email"] { + if user, err := s.store.GetUserByID(authCode.UserID); err == nil { + if scopeSet["profile"] { + params.Name = user.FullName + params.PreferredUsername = user.Username + params.Picture = user.AvatarURL + updatedAt := user.UpdatedAt + params.UpdatedAt = &updatedAt + } + if scopeSet["email"] { + params.Email = user.Email + params.EmailVerified = false // AuthGate does not verify email addresses + } + } else { + log.Printf( + "[Token] ID token: failed to fetch user profile for user_id=%s, profile/email claims will be omitted: %v", + authCode.UserID, + err, + ) } - } else if scopeSet["profile"] || scopeSet["email"] { - log.Printf( - "[Token] ID token: failed to fetch user profile for user_id=%s, profile/email claims will be omitted: %v", - authCode.UserID, - actorUserErr, - ) } if generated, err := idp.GenerateIDToken(params); err == nil { diff --git a/internal/services/token_management.go b/internal/services/token_management.go index f49f1ccb..c0f25627 100644 --- a/internal/services/token_management.go +++ b/internal/services/token_management.go @@ -40,7 +40,7 @@ func (s *TokenService) RevokeTokenByID(ctx context.Context, tokenID, actorUserID return err } - actorUsername := s.resolveUsername(actorUserID) + actorUsername := s.resolveUsername(ctx, actorUserID) err = s.store.RevokeToken(tokenID) if err != nil { @@ -135,7 +135,7 @@ func (s *TokenService) updateTokenStatusWithAudit( } } - actorUsername := s.resolveUsername(actorUserID) + actorUsername := s.resolveUsername(ctx, actorUserID) err = s.store.UpdateTokenStatus(tokenID, newStatus) if err != nil { diff --git a/internal/services/token_refresh.go b/internal/services/token_refresh.go index 3adbc083..2c699ea3 100644 --- a/internal/services/token_refresh.go +++ b/internal/services/token_refresh.go @@ -53,7 +53,7 @@ func (s *TokenService) revokeTokenFamilyWithAudit( } // Audit log — CRITICAL severity because this indicates potential token theft - actorUsername := s.resolveUsername(reusedToken.UserID) + actorUsername := s.resolveUsername(ctx, reusedToken.UserID) _ = s.auditService.LogSync(ctx, core.AuditLogEntry{ EventType: models.EventSuspiciousActivity, @@ -208,7 +208,7 @@ func (s *TokenService) RefreshAccessToken( s.metrics.RecordTokenRefresh(true) // Log token refresh - actorUsername := s.resolveUsername(newAccessToken.UserID) + actorUsername := s.resolveUsername(ctx, newAccessToken.UserID) providerName := s.tokenProvider.Name() details := models.AuditDetails{ "client_id": newAccessToken.ClientID, From 8f49811552ac9fd7c2e5787f2b4c8ca6cbff5bec Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Wed, 8 Apr 2026 23:14:04 +0800 Subject: [PATCH 03/12] perf(audit): eliminate duplicate GetUserByID in auth code exchange Reuse the user object fetched for ID-token profile/email claims to populate actorUsername, so the sessionless /oauth/token path never issues two GetUserByID calls for the same user. Co-Authored-By: Claude Opus 4.6 (1M context) --- internal/services/token_exchange.go | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) diff --git a/internal/services/token_exchange.go b/internal/services/token_exchange.go index 6139d0e5..9ef5d43c 100644 --- a/internal/services/token_exchange.go +++ b/internal/services/token_exchange.go @@ -141,8 +141,11 @@ func (s *TokenService) ExchangeAuthorizationCode( return nil, nil, "", err } - // Resolve username from context (set by auth middleware) or DB fallback. - actorUsername := s.resolveUsername(ctx, authCode.UserID) + // Resolve actor username for audit logging. Prefer request context (set by + // auth middleware); fall back to DB only when context is empty. The user + // object fetched for ID-token profile claims below is reused so that the + // sessionless /oauth/token path never issues two GetUserByID calls. + actorUsername := models.GetUsernameFromContext(ctx) // Generate OIDC ID Token when openid scope was granted (OIDC Core 1.0 §3.1.3.3). // ID tokens are not stored in the database; they are short-lived and non-revocable. @@ -163,6 +166,11 @@ func (s *TokenService) ExchangeAuthorizationCode( // Fetch user profile only when scope-gated claims are needed if scopeSet["profile"] || scopeSet["email"] { if user, err := s.store.GetUserByID(authCode.UserID); err == nil { + // Reuse the fetched user for actorUsername so we don't + // need a separate DB call via resolveUsername. + if actorUsername == "" { + actorUsername = user.Username + } if scopeSet["profile"] { params.Name = user.FullName params.PreferredUsername = user.Username @@ -207,6 +215,12 @@ func (s *TokenService) ExchangeAuthorizationCode( } } + // Fall back to DB lookup only when context had no user and the ID-token + // profile/email path above did not already populate actorUsername. + if actorUsername == "" { + actorUsername = s.resolveUsername(ctx, authCode.UserID) + } + // Metrics duration := time.Since(start) s.metrics.RecordTokenIssued("access", "authorization_code", duration, providerName) From 45f85a447c4e4f6e85fa9f82c05d2a1b9a62e92c Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Wed, 8 Apr 2026 23:22:52 +0800 Subject: [PATCH 04/12] fix(audit): verify context user ID before reuse and bound shutdown drain - resolveUsername now checks that the context user ID matches the requested userID before using the context username, preventing misattribution when IDs differ - Shutdown drain uses a length snapshot instead of an unbounded loop, so late-arriving producers cannot prevent the worker from exiting Co-Authored-By: Claude Opus 4.6 (1M context) --- internal/services/audit.go | 18 +++++++++--------- internal/services/token.go | 11 +++++++---- 2 files changed, 16 insertions(+), 13 deletions(-) diff --git a/internal/services/audit.go b/internal/services/audit.go index 77082dbf..e00158ad 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -99,16 +99,16 @@ func (s *AuditService) worker() { s.flushBatch() case <-s.shutdownCh: - // Drain remaining events from logChan before shutdown - for { - select { - case entry := <-s.logChan: - s.addToBatch(entry) - default: - s.flushBatch() - return - } + // Drain only the backlog present when shutdown begins. + // Snapshot the length to avoid an unbounded drain if + // producers continue sending after shutdown has started. + pending := len(s.logChan) + for range pending { + entry := <-s.logChan + s.addToBatch(entry) } + s.flushBatch() + return } } } diff --git a/internal/services/token.go b/internal/services/token.go index 2cb17b8b..9280946e 100644 --- a/internal/services/token.go +++ b/internal/services/token.go @@ -81,11 +81,14 @@ func NewTokenService( // resolveUsername returns the username for a given userID. // It first checks the request context (populated by auth middleware for -// authenticated routes), falling back to a DB lookup only when the context -// does not carry the user. Returns empty string on error (best-effort). +// authenticated routes) and uses it only when the context user ID matches +// the requested userID, falling back to a DB lookup otherwise. +// Returns empty string on error (best-effort). func (s *TokenService) resolveUsername(ctx context.Context, userID string) string { - if username := models.GetUsernameFromContext(ctx); username != "" { - return username + if models.GetUserIDFromContext(ctx) == userID { + if username := models.GetUsernameFromContext(ctx); username != "" { + return username + } } user, err := s.store.GetUserByID(userID) if err != nil { From 6b59e9d4d1a3dc767b969d831f8269c3dd276a8f Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Thu, 9 Apr 2026 15:58:55 +0800 Subject: [PATCH 05/12] fix(audit): truncate fields and gate metrics registration - Truncate UserAgent, RequestPath, RequestMethod to match model varchar limits before persisting, preventing write failures from long values - Gate audit dropped-events Prometheus counter behind an explicit registerer so deployments with metrics disabled do not register collectors from the services layer --- internal/bootstrap/bootstrap.go | 4 ++++ internal/services/audit.go | 42 +++++++++++++++++++++++++++++---- 2 files changed, 41 insertions(+), 5 deletions(-) diff --git a/internal/bootstrap/bootstrap.go b/internal/bootstrap/bootstrap.go index 59cbc6f5..8587cfed 100644 --- a/internal/bootstrap/bootstrap.go +++ b/internal/bootstrap/bootstrap.go @@ -13,6 +13,7 @@ import ( "github.com/appleboy/graceful" "github.com/gin-gonic/gin" + "github.com/prometheus/client_golang/prometheus" "github.com/redis/go-redis/v9" ) @@ -142,6 +143,9 @@ func (app *Application) initializeInfrastructure(ctx context.Context) error { // initializeBusinessLayer sets up services func (app *Application) initializeBusinessLayer() { // Audit service (required by other services) + if app.Config.MetricsEnabled { + services.SetAuditMetricsRegisterer(prometheus.DefaultRegisterer) + } if app.Config.EnableAuditLogging { app.AuditService = services.NewAuditService( app.DB, diff --git a/internal/services/audit.go b/internal/services/audit.go index e00158ad..15fbecb1 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -15,7 +15,6 @@ import ( "github.com/google/uuid" "github.com/prometheus/client_golang/prometheus" - "github.com/prometheus/client_golang/prometheus/promauto" ) // Compile-time interface check. @@ -24,19 +23,47 @@ var _ core.AuditLogger = (*AuditService)(nil) // auditEventsDropped is a singleton counter registered once via sync.Once // to avoid duplicate-registration panics when multiple AuditService // instances are created (e.g. in tests). +// +// The counter is only registered with Prometheus when a registerer is +// explicitly provided via SetAuditMetricsRegisterer, so deployments with +// metrics disabled do not leak collectors from the services layer. var ( - auditEventsDropped prometheus.Counter - auditEventsDroppedOnce sync.Once + auditEventsDropped prometheus.Counter + auditEventsDroppedOnce sync.Once + auditEventsDroppedRegisterer prometheus.Registerer ) +// SetAuditMetricsRegisterer configures the Prometheus registerer used by the +// audit service. It must be called before any AuditService is created in order +// for the dropped-events counter to be registered with Prometheus. +func SetAuditMetricsRegisterer(registerer prometheus.Registerer) { + auditEventsDroppedRegisterer = registerer +} + func getAuditEventsDroppedCounter() prometheus.Counter { auditEventsDroppedOnce.Do(func() { - auditEventsDropped = promauto.NewCounter(prometheus.CounterOpts{ + opts := prometheus.CounterOpts{ Namespace: "authgate", Subsystem: "audit", Name: "events_dropped_total", Help: "Total number of audit log events dropped due to a full buffer.", - }) + } + counter := prometheus.NewCounter(opts) + + if auditEventsDroppedRegisterer != nil { + if err := auditEventsDroppedRegisterer.Register(counter); err != nil { + if existing, ok := err.(prometheus.AlreadyRegisteredError); ok { + if c, ok := existing.ExistingCollector.(prometheus.Counter); ok { + auditEventsDropped = c + return + } + } + log.Printf("failed to register audit dropped-events counter: %v", err) + } + } + // When no registerer is set, the counter still works in-memory but + // is not exposed via the Prometheus /metrics endpoint. + auditEventsDropped = counter }) return auditEventsDropped } @@ -176,6 +203,11 @@ func (s *AuditService) buildAuditLog( } entry.Details = maskSensitiveDetails(entry.Details) + // Truncate fields to match database column size limits. + entry.UserAgent = util.TruncateString(entry.UserAgent, 500) + entry.RequestPath = util.TruncateString(entry.RequestPath, 500) + entry.RequestMethod = util.TruncateString(entry.RequestMethod, 10) + now := time.Now() return &models.AuditLog{ ID: uuid.New().String(), From a279c27fda3813683d5813ec294237348112a354 Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Thu, 9 Apr 2026 16:23:39 +0800 Subject: [PATCH 06/12] fix(audit): account for ellipsis in truncation and gate post-shutdown enqueue - Subtract 3 from varchar limits passed to TruncateString so the appended "..." does not exceed column size constraints - Add atomic stopped flag to reject events in Log() after Shutdown() begins, preventing events from being stuck in logChan --- internal/services/audit.go | 22 ++++++++++++++++++---- 1 file changed, 18 insertions(+), 4 deletions(-) diff --git a/internal/services/audit.go b/internal/services/audit.go index 15fbecb1..9fa1a341 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -6,6 +6,7 @@ import ( "log" "strings" "sync" + "sync/atomic" "time" "github.com/go-authgate/authgate/internal/core" @@ -84,6 +85,7 @@ type AuditService struct { // Graceful shutdown wg sync.WaitGroup shutdownCh chan struct{} + stopped atomic.Bool // Prometheus counter for dropped events eventsDropped prometheus.Counter @@ -204,9 +206,11 @@ func (s *AuditService) buildAuditLog( entry.Details = maskSensitiveDetails(entry.Details) // Truncate fields to match database column size limits. - entry.UserAgent = util.TruncateString(entry.UserAgent, 500) - entry.RequestPath = util.TruncateString(entry.RequestPath, 500) - entry.RequestMethod = util.TruncateString(entry.RequestMethod, 10) + // TruncateString appends "..." (3 chars) when truncating, so subtract 3 + // from the varchar limit to guarantee the final length fits the column. + entry.UserAgent = util.TruncateString(entry.UserAgent, 497) + entry.RequestPath = util.TruncateString(entry.RequestPath, 497) + entry.RequestMethod = util.TruncateString(entry.RequestMethod, 7) now := time.Now() return &models.AuditLog{ @@ -231,8 +235,14 @@ func (s *AuditService) buildAuditLog( } } -// Log records an audit log entry asynchronously +// Log records an audit log entry asynchronously. +// Events submitted after Shutdown has been called are dropped. func (s *AuditService) Log(ctx context.Context, entry core.AuditLogEntry) { + if s.stopped.Load() { + log.Printf("WARNING: Audit service stopped, dropping event: %s", entry.Action) + s.eventsDropped.Inc() + return + } auditLog := s.buildAuditLog(ctx, entry) select { case s.logChan <- auditLog: @@ -268,6 +278,10 @@ func (s *AuditService) GetAuditLogStats(startTime, endTime time.Time) (store.Aud // Shutdown gracefully shuts down the audit service func (s *AuditService) Shutdown(ctx context.Context) error { + // Reject new events before draining the channel so nothing is + // enqueued after the worker exits. + s.stopped.Store(true) + // Stop ticker s.batchTicker.Stop() From 5f99f6e4d61c4a549c6d46877d2734ac2bb5ec0c Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Thu, 9 Apr 2026 16:31:36 +0800 Subject: [PATCH 07/12] fix(audit): resolve username before ID token log, drain fully on shutdown, and fix method truncation - Resolve actorUsername via DB fallback before the ID token audit entry so openid-only requests (without profile/email) are not left empty - Replace len()-snapshot drain with non-blocking receive loop in shutdown worker to flush entries enqueued during the race window - Hard-truncate RequestMethod to varchar(10) limit without ellipsis so standard HTTP methods like PROPFIND (8 chars) are preserved --- internal/services/audit.go | 29 +++++++++++++++++++---------- internal/services/token_exchange.go | 7 +++++++ 2 files changed, 26 insertions(+), 10 deletions(-) diff --git a/internal/services/audit.go b/internal/services/audit.go index 9fa1a341..de1d36ea 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -128,16 +128,19 @@ func (s *AuditService) worker() { s.flushBatch() case <-s.shutdownCh: - // Drain only the backlog present when shutdown begins. - // Snapshot the length to avoid an unbounded drain if - // producers continue sending after shutdown has started. - pending := len(s.logChan) - for range pending { - entry := <-s.logChan - s.addToBatch(entry) + // Drain all queued entries that were accepted before shutdown + // completed. Use a non-blocking receive loop rather than a + // len() snapshot so entries enqueued concurrently after the + // snapshot are still flushed. + for { + select { + case entry := <-s.logChan: + s.addToBatch(entry) + default: + s.flushBatch() + return + } } - s.flushBatch() - return } } } @@ -210,7 +213,13 @@ func (s *AuditService) buildAuditLog( // from the varchar limit to guarantee the final length fits the column. entry.UserAgent = util.TruncateString(entry.UserAgent, 497) entry.RequestPath = util.TruncateString(entry.RequestPath, 497) - entry.RequestMethod = util.TruncateString(entry.RequestMethod, 7) + + // RequestMethod is stored in a varchar(10) column. Preserve values up to + // the full column width and hard-truncate anything longer without adding + // an ellipsis. + if len(entry.RequestMethod) > 10 { + entry.RequestMethod = entry.RequestMethod[:10] + } now := time.Now() return &models.AuditLog{ diff --git a/internal/services/token_exchange.go b/internal/services/token_exchange.go index 9ef5d43c..39ae3fa9 100644 --- a/internal/services/token_exchange.go +++ b/internal/services/token_exchange.go @@ -191,6 +191,13 @@ func (s *TokenService) ExchangeAuthorizationCode( } } + // Ensure actorUsername is resolved before logging ID token audit + // entry. The profile/email block above may have set it already; + // fall back to a DB lookup for openid-only requests. + if actorUsername == "" { + actorUsername = s.resolveUsername(ctx, authCode.UserID) + } + if generated, err := idp.GenerateIDToken(params); err == nil { idToken = generated s.auditService.Log(ctx, core.AuditLogEntry{ From 39cbce883aeb4fc68e44085b9a21094f420626a8 Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Thu, 9 Apr 2026 16:41:47 +0800 Subject: [PATCH 08/12] fix(audit): close logChan with RWMutex coordination to eliminate shutdown race - Replace shutdownCh with closing logChan to signal the worker, so range-based drain is guaranteed to see all accepted events - Guard Log() sends with sendMu.RLock; Shutdown() takes sendMu.Lock after setting stopped, ensuring all in-flight sends complete before the channel is closed - Worker uses ok-check on receive to detect closed channel and flush --- internal/services/audit.go | 53 ++++++++++++++++----------------- internal/services/audit_test.go | 1 - 2 files changed, 26 insertions(+), 28 deletions(-) diff --git a/internal/services/audit.go b/internal/services/audit.go index de1d36ea..a2424cf1 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -83,9 +83,9 @@ type AuditService struct { batchTicker *time.Ticker // Graceful shutdown - wg sync.WaitGroup - shutdownCh chan struct{} - stopped atomic.Bool + wg sync.WaitGroup + sendMu sync.RWMutex // coordinates Log() senders with Shutdown() + stopped atomic.Bool // Prometheus counter for dropped events eventsDropped prometheus.Counter @@ -102,7 +102,6 @@ func NewAuditService(s core.Store, bufferSize int) *AuditService { bufferSize: bufferSize, logChan: make(chan *models.AuditLog, bufferSize), batchBuffer: make([]*models.AuditLog, 0, 100), - shutdownCh: make(chan struct{}), eventsDropped: getAuditEventsDroppedCounter(), } @@ -114,33 +113,25 @@ func NewAuditService(s core.Store, bufferSize int) *AuditService { return service } -// worker is the background goroutine that processes audit logs +// worker is the background goroutine that processes audit logs. +// It drains logChan until the channel is closed by Shutdown, then +// flushes any remaining batch and exits. func (s *AuditService) worker() { defer s.wg.Done() for { select { - case log := <-s.logChan: - s.addToBatch(log) + case entry, ok := <-s.logChan: + if !ok { + // Channel closed by Shutdown — flush remaining batch. + s.flushBatch() + return + } + s.addToBatch(entry) case <-s.batchTicker.C: // Flush batch every second s.flushBatch() - - case <-s.shutdownCh: - // Drain all queued entries that were accepted before shutdown - // completed. Use a non-blocking receive loop rather than a - // len() snapshot so entries enqueued concurrently after the - // snapshot are still flushed. - for { - select { - case entry := <-s.logChan: - s.addToBatch(entry) - default: - s.flushBatch() - return - } - } } } } @@ -246,7 +237,12 @@ func (s *AuditService) buildAuditLog( // Log records an audit log entry asynchronously. // Events submitted after Shutdown has been called are dropped. +// The RWMutex ensures all in-flight sends complete before Shutdown +// closes logChan, eliminating the send-on-closed-channel race. func (s *AuditService) Log(ctx context.Context, entry core.AuditLogEntry) { + s.sendMu.RLock() + defer s.sendMu.RUnlock() + if s.stopped.Load() { log.Printf("WARNING: Audit service stopped, dropping event: %s", entry.Action) s.eventsDropped.Inc() @@ -287,16 +283,19 @@ func (s *AuditService) GetAuditLogStats(startTime, endTime time.Time) (store.Aud // Shutdown gracefully shuts down the audit service func (s *AuditService) Shutdown(ctx context.Context) error { - // Reject new events before draining the channel so nothing is - // enqueued after the worker exits. + // 1. Reject new events so future Log() calls return immediately. s.stopped.Store(true) + // 2. Wait for all in-flight Log() calls to finish, then close + // logChan. The exclusive lock ensures no sender is mid-send + // when the channel is closed. + s.sendMu.Lock() + close(s.logChan) + s.sendMu.Unlock() + // Stop ticker s.batchTicker.Stop() - // Signal worker to stop - close(s.shutdownCh) - // Wait for worker to finish with timeout done := make(chan struct{}) go func() { diff --git a/internal/services/audit_test.go b/internal/services/audit_test.go index 9f550d3c..4109965c 100644 --- a/internal/services/audit_test.go +++ b/internal/services/audit_test.go @@ -158,7 +158,6 @@ func TestShutdown_DrainsLogChan(t *testing.T) { bufferSize: 100, logChan: make(chan *models.AuditLog, 100), batchBuffer: make([]*models.AuditLog, 0, 100), - shutdownCh: make(chan struct{}), eventsDropped: getAuditEventsDroppedCounter(), } From c86c362df83906387887cdacf414773447bd8ee4 Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Thu, 9 Apr 2026 17:25:33 +0800 Subject: [PATCH 09/12] test(util): rename misleading test to match actual behavior Rename TestGetRequestMetadataFromContext_Empty to TestRequestMetadataContext_Empty since it tests individual getters, not a single GetRequestMetadataFromContext helper. --- internal/util/context_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/util/context_test.go b/internal/util/context_test.go index 4ae92b52..17ac3bdc 100644 --- a/internal/util/context_test.go +++ b/internal/util/context_test.go @@ -90,7 +90,7 @@ func TestSetRequestMetadataContext(t *testing.T) { assert.Equal(t, "POST", GetRequestMethodFromContext(ctx)) } -func TestGetRequestMetadataFromContext_Empty(t *testing.T) { +func TestRequestMetadataContext_Empty(t *testing.T) { ctx := context.Background() assert.Empty(t, GetUserAgentFromContext(ctx)) From 85e0319daf14153f8a40fe7ed52799660e68dda6 Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Thu, 9 Apr 2026 18:33:21 +0800 Subject: [PATCH 10/12] fix(audit): guard ActorUsername context fill, align metric name, skip noop lookups - buildAuditLog only fills ActorUsername from context when entry ActorUserID is empty or matches the context user, preventing misattribution when call sites set only ActorUserID - Align audit_events_dropped_total naming with the rest of the metrics package (single Name field, no Namespace/Subsystem) - resolveUsername short-circuits when audit logging is the noop service, avoiding wasted DB round-trips on hot token paths Co-Authored-By: Claude Opus 4.6 (1M context) --- internal/services/audit.go | 16 +++++++++++----- internal/services/token.go | 7 ++++++- 2 files changed, 17 insertions(+), 6 deletions(-) diff --git a/internal/services/audit.go b/internal/services/audit.go index a2424cf1..5d5bf190 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -43,11 +43,11 @@ func SetAuditMetricsRegisterer(registerer prometheus.Registerer) { func getAuditEventsDroppedCounter() prometheus.Counter { auditEventsDroppedOnce.Do(func() { + // Use a single fully-prefixed Name (no Namespace/Subsystem) to + // match the convention used by metrics in internal/metrics. opts := prometheus.CounterOpts{ - Namespace: "authgate", - Subsystem: "audit", - Name: "events_dropped_total", - Help: "Total number of audit log events dropped due to a full buffer.", + Name: "audit_events_dropped_total", + Help: "Total number of audit log events dropped due to a full buffer.", } counter := prometheus.NewCounter(opts) @@ -182,8 +182,14 @@ func (s *AuditService) buildAuditLog( if entry.ActorIP == "" { entry.ActorIP = util.GetIPFromContext(ctx) } + // Fill ActorUsername from context only when the entry's ActorUserID is + // empty or matches the context user — otherwise the username could be + // misattributed to a different principal than ActorUserID identifies. if entry.ActorUsername == "" { - entry.ActorUsername = models.GetUsernameFromContext(ctx) + ctxUserID := models.GetUserIDFromContext(ctx) + if entry.ActorUserID == "" || entry.ActorUserID == ctxUserID { + entry.ActorUsername = models.GetUsernameFromContext(ctx) + } } if entry.ActorUserID == "" { entry.ActorUserID = models.GetUserIDFromContext(ctx) diff --git a/internal/services/token.go b/internal/services/token.go index 9280946e..cfc3d367 100644 --- a/internal/services/token.go +++ b/internal/services/token.go @@ -83,8 +83,13 @@ func NewTokenService( // It first checks the request context (populated by auth middleware for // authenticated routes) and uses it only when the context user ID matches // the requested userID, falling back to a DB lookup otherwise. -// Returns empty string on error (best-effort). +// Returns empty string on error or when audit logging is disabled (noop). func (s *TokenService) resolveUsername(ctx context.Context, userID string) string { + // Skip lookup entirely when audit logging is disabled — the result + // would be discarded by the noop logger anyway. + if _, isNoop := s.auditService.(*NoopAuditService); isNoop { + return "" + } if models.GetUserIDFromContext(ctx) == userID { if username := models.GetUsernameFromContext(ctx); username != "" { return username From b28509da6cb4aafa10019c3757e8ccfbfef7cede Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Thu, 9 Apr 2026 18:44:11 +0800 Subject: [PATCH 11/12] fix(audit): support late metric registerer initialization Replace the sync.Once-based counter init with a mutex-protected pattern that allows SetAuditMetricsRegisterer to register a previously created counter. This eliminates the silent misconfiguration when AuditService is constructed before metrics are configured (common in tests). Co-Authored-By: Claude Opus 4.6 (1M context) --- internal/services/audit.go | 70 ++++++++++++++++++++++++-------------- 1 file changed, 44 insertions(+), 26 deletions(-) diff --git a/internal/services/audit.go b/internal/services/audit.go index 5d5bf190..08832463 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -21,51 +21,69 @@ import ( // Compile-time interface check. var _ core.AuditLogger = (*AuditService)(nil) -// auditEventsDropped is a singleton counter registered once via sync.Once -// to avoid duplicate-registration panics when multiple AuditService -// instances are created (e.g. in tests). +// auditEventsDropped is a singleton counter protected by a mutex so it can +// be created before metrics are configured and registered later once a +// registerer becomes available. // // The counter is only registered with Prometheus when a registerer is // explicitly provided via SetAuditMetricsRegisterer, so deployments with // metrics disabled do not leak collectors from the services layer. var ( auditEventsDropped prometheus.Counter - auditEventsDroppedOnce sync.Once + auditEventsDroppedMu sync.Mutex + auditEventsDroppedRegistered bool auditEventsDroppedRegisterer prometheus.Registerer ) +// registerAuditDroppedCounterLocked attempts to register the existing counter +// with the configured registerer. The caller must hold auditEventsDroppedMu. +func registerAuditDroppedCounterLocked() { + if auditEventsDropped == nil || + auditEventsDroppedRegisterer == nil || + auditEventsDroppedRegistered { + return + } + if err := auditEventsDroppedRegisterer.Register(auditEventsDropped); err != nil { + if existing, ok := err.(prometheus.AlreadyRegisteredError); ok { + if c, ok := existing.ExistingCollector.(prometheus.Counter); ok { + auditEventsDropped = c + auditEventsDroppedRegistered = true + return + } + } + log.Printf("failed to register audit dropped-events counter: %v", err) + return + } + auditEventsDroppedRegistered = true +} + // SetAuditMetricsRegisterer configures the Prometheus registerer used by the -// audit service. It must be called before any AuditService is created in order -// for the dropped-events counter to be registered with Prometheus. +// audit service. If the dropped-events counter was created before metrics +// were configured, setting a non-nil registerer will register the existing +// counter, ensuring late initialization (e.g. in tests) is not silently lost. func SetAuditMetricsRegisterer(registerer prometheus.Registerer) { + auditEventsDroppedMu.Lock() + defer auditEventsDroppedMu.Unlock() + auditEventsDroppedRegisterer = registerer + registerAuditDroppedCounterLocked() } func getAuditEventsDroppedCounter() prometheus.Counter { - auditEventsDroppedOnce.Do(func() { + auditEventsDroppedMu.Lock() + defer auditEventsDroppedMu.Unlock() + + if auditEventsDropped == nil { // Use a single fully-prefixed Name (no Namespace/Subsystem) to // match the convention used by metrics in internal/metrics. - opts := prometheus.CounterOpts{ + auditEventsDropped = prometheus.NewCounter(prometheus.CounterOpts{ Name: "audit_events_dropped_total", Help: "Total number of audit log events dropped due to a full buffer.", - } - counter := prometheus.NewCounter(opts) - - if auditEventsDroppedRegisterer != nil { - if err := auditEventsDroppedRegisterer.Register(counter); err != nil { - if existing, ok := err.(prometheus.AlreadyRegisteredError); ok { - if c, ok := existing.ExistingCollector.(prometheus.Counter); ok { - auditEventsDropped = c - return - } - } - log.Printf("failed to register audit dropped-events counter: %v", err) - } - } - // When no registerer is set, the counter still works in-memory but - // is not exposed via the Prometheus /metrics endpoint. - auditEventsDropped = counter - }) + }) + } + registerAuditDroppedCounterLocked() + // When no registerer is set, the counter still works in-memory but + // is not exposed via the Prometheus /metrics endpoint. return auditEventsDropped } From faa9863ce6579f4dd6db08ab5bf48ab70df8d120 Mon Sep 17 00:00:00 2001 From: Bo-Yi Wu Date: Thu, 9 Apr 2026 19:31:39 +0800 Subject: [PATCH 12/12] refactor(audit): centralize ActorUsername enrichment in buildAuditLog Remove TokenService.resolveUsername and the explicit ActorUsername settings from 11 audit entries across token exchange, refresh, and management. The audit service is now the single source of truth for ActorUsername resolution: - buildAuditLog tries the request context (zero cost) when the entry's ActorUserID matches the context user, then falls back to a DB lookup when context did not help - Synthetic machine identities ("client:" from the client_credentials grant) are detected by prefix and skip the DB lookup, avoiding wasted queries on hot introspection paths - ExchangeAuthorizationCode caches the user it fetches for OIDC profile/email claims into context (via SetUserContext) so the audit layer's context-match check picks it up without a duplicate query Removes the leaky type assertion against *NoopAuditService and the asymmetry where ActorUsername needed service-layer help while every other auto-enriched field (IP, UA, path, method, ActorUserID) was handled in buildAuditLog. Co-Authored-By: Claude Opus 4.6 (1M context) --- internal/services/audit.go | 10 +++ internal/services/audit_test.go | 49 +++++++++++++ internal/services/token.go | 23 ------ internal/services/token_exchange.go | 100 ++++++++++---------------- internal/services/token_management.go | 76 +++++++++----------- internal/services/token_refresh.go | 38 +++++----- 6 files changed, 147 insertions(+), 149 deletions(-) diff --git a/internal/services/audit.go b/internal/services/audit.go index 08832463..f8c940c4 100644 --- a/internal/services/audit.go +++ b/internal/services/audit.go @@ -209,6 +209,16 @@ func (s *AuditService) buildAuditLog( entry.ActorUsername = models.GetUsernameFromContext(ctx) } } + // Fall back to a DB lookup when context did not provide a username and + // the actor is a real user (not a synthetic machine identity from the + // client_credentials grant, which uses a "client:" format and + // has no corresponding user row). + if entry.ActorUsername == "" && entry.ActorUserID != "" && + !strings.HasPrefix(entry.ActorUserID, "client:") { + if user, err := s.store.GetUserByID(entry.ActorUserID); err == nil { + entry.ActorUsername = user.Username + } + } if entry.ActorUserID == "" { entry.ActorUserID = models.GetUserIDFromContext(ctx) } diff --git a/internal/services/audit_test.go b/internal/services/audit_test.go index 4109965c..9f14f568 100644 --- a/internal/services/audit_test.go +++ b/internal/services/audit_test.go @@ -149,6 +149,55 @@ func TestBuildAuditLog_EnrichesUserFromContext(t *testing.T) { assert.Equal(t, "testuser", result.ActorUsername) } +func TestBuildAuditLog_FillsActorUsernameFromDBFallback(t *testing.T) { + // When context has no user but the entry's ActorUserID points to a real + // user, buildAuditLog should resolve the username via a DB lookup. + s := setupTestStore(t) + user := &models.User{ + ID: "fallback-user-id", + Username: "fallback-user", + Email: "fallback@example.com", + PasswordHash: "x", + AuthSource: models.AuthSourceLocal, + } + require.NoError(t, s.CreateUser(user)) + + svc := &AuditService{store: s} + + entry := core.AuditLogEntry{ + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: user.ID, + Action: "test", + Success: true, + } + + result := svc.buildAuditLog(context.Background(), entry) + + assert.Equal(t, user.ID, result.ActorUserID) + assert.Equal(t, "fallback-user", result.ActorUsername) +} + +func TestBuildAuditLog_SkipsDBLookupForMachineIdentity(t *testing.T) { + // Synthetic machine identities (client_credentials grant) use the + // "client:" format and have no user row, so buildAuditLog + // must not attempt a DB lookup. A nil store would panic if a query ran. + svc := &AuditService{} + + entry := core.AuditLogEntry{ + EventType: models.EventClientCredentialsTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: "client:test-client-id", + Action: "test", + Success: true, + } + + result := svc.buildAuditLog(context.Background(), entry) + + assert.Equal(t, "client:test-client-id", result.ActorUserID) + assert.Empty(t, result.ActorUsername) +} + func TestShutdown_DrainsLogChan(t *testing.T) { // Construct the service struct directly (without starting the worker) // so we can populate the channel deterministically before the drain runs. diff --git a/internal/services/token.go b/internal/services/token.go index cfc3d367..0866c9f3 100644 --- a/internal/services/token.go +++ b/internal/services/token.go @@ -79,29 +79,6 @@ func NewTokenService( } } -// resolveUsername returns the username for a given userID. -// It first checks the request context (populated by auth middleware for -// authenticated routes) and uses it only when the context user ID matches -// the requested userID, falling back to a DB lookup otherwise. -// Returns empty string on error or when audit logging is disabled (noop). -func (s *TokenService) resolveUsername(ctx context.Context, userID string) string { - // Skip lookup entirely when audit logging is disabled — the result - // would be discarded by the noop logger anyway. - if _, isNoop := s.auditService.(*NoopAuditService); isNoop { - return "" - } - if models.GetUserIDFromContext(ctx) == userID { - if username := models.GetUsernameFromContext(ctx); username != "" { - return username - } - } - user, err := s.store.GetUserByID(userID) - if err != nil { - return "" - } - return user.Username -} - // getAccessTokenByHash looks up a token, using cache if available. // On cache backend errors (e.g. Redis unavailable), falls back to direct DB lookup // so that valid tokens are not rejected due to cache infrastructure issues. diff --git a/internal/services/token_exchange.go b/internal/services/token_exchange.go index 39ae3fa9..4e5c08e4 100644 --- a/internal/services/token_exchange.go +++ b/internal/services/token_exchange.go @@ -77,17 +77,14 @@ func (s *TokenService) ExchangeDeviceCode( // Delete the used device code _ = s.store.DeleteDeviceCodeByID(dc.ID) - // Log token issuance - actorUsername := s.resolveUsername(ctx, accessToken.UserID) - + // Log token issuance — ActorUsername is auto-resolved by buildAuditLog. s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventAccessTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: accessToken.UserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: accessToken.ID, - Action: "Access token issued via device code exchange", + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: accessToken.UserID, + ResourceType: models.ResourceToken, + ResourceID: accessToken.ID, + Action: "Access token issued via device code exchange", Details: models.AuditDetails{ "client_id": accessToken.ClientID, "scopes": accessToken.Scopes, @@ -98,13 +95,12 @@ func (s *TokenService) ExchangeDeviceCode( }) s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventRefreshTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: refreshToken.UserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: refreshToken.ID, - Action: "Refresh token issued via device code exchange", + EventType: models.EventRefreshTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: refreshToken.UserID, + ResourceType: models.ResourceToken, + ResourceID: refreshToken.ID, + Action: "Refresh token issued via device code exchange", Details: models.AuditDetails{ "client_id": refreshToken.ClientID, "scopes": refreshToken.Scopes, @@ -141,12 +137,6 @@ func (s *TokenService) ExchangeAuthorizationCode( return nil, nil, "", err } - // Resolve actor username for audit logging. Prefer request context (set by - // auth middleware); fall back to DB only when context is empty. The user - // object fetched for ID-token profile claims below is reused so that the - // sessionless /oauth/token path never issues two GetUserByID calls. - actorUsername := models.GetUsernameFromContext(ctx) - // Generate OIDC ID Token when openid scope was granted (OIDC Core 1.0 §3.1.3.3). // ID tokens are not stored in the database; they are short-lived and non-revocable. // ID token generation is only supported when the provider implements IDTokenProvider. @@ -166,11 +156,9 @@ func (s *TokenService) ExchangeAuthorizationCode( // Fetch user profile only when scope-gated claims are needed if scopeSet["profile"] || scopeSet["email"] { if user, err := s.store.GetUserByID(authCode.UserID); err == nil { - // Reuse the fetched user for actorUsername so we don't - // need a separate DB call via resolveUsername. - if actorUsername == "" { - actorUsername = user.Username - } + // Cache the user in context so the audit service's + // ActorUsername enrichment hits context (no extra DB call). + ctx = models.SetUserContext(ctx, user) if scopeSet["profile"] { params.Name = user.FullName params.PreferredUsername = user.Username @@ -191,23 +179,15 @@ func (s *TokenService) ExchangeAuthorizationCode( } } - // Ensure actorUsername is resolved before logging ID token audit - // entry. The profile/email block above may have set it already; - // fall back to a DB lookup for openid-only requests. - if actorUsername == "" { - actorUsername = s.resolveUsername(ctx, authCode.UserID) - } - if generated, err := idp.GenerateIDToken(params); err == nil { idToken = generated s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventIDTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: authCode.UserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: accessToken.ID, - Action: "ID token issued via authorization code exchange", + EventType: models.EventIDTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: authCode.UserID, + ResourceType: models.ResourceToken, + ResourceID: accessToken.ID, + Action: "ID token issued via authorization code exchange", Details: models.AuditDetails{ "client_id": authCode.ClientID, "scopes": authCode.Scopes, @@ -222,26 +202,21 @@ func (s *TokenService) ExchangeAuthorizationCode( } } - // Fall back to DB lookup only when context had no user and the ID-token - // profile/email path above did not already populate actorUsername. - if actorUsername == "" { - actorUsername = s.resolveUsername(ctx, authCode.UserID) - } - // Metrics duration := time.Since(start) s.metrics.RecordTokenIssued("access", "authorization_code", duration, providerName) s.metrics.RecordTokenIssued("refresh", "authorization_code", duration, providerName) - // Audit + // Audit — ActorUsername is auto-resolved by buildAuditLog (from the + // context user cached above when openid+profile/email was requested, + // or via DB fallback otherwise). s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventAccessTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: accessToken.UserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: accessToken.ID, - Action: "Access token issued via authorization code exchange", + EventType: models.EventAccessTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: accessToken.UserID, + ResourceType: models.ResourceToken, + ResourceID: accessToken.ID, + Action: "Access token issued via authorization code exchange", Details: models.AuditDetails{ "client_id": accessToken.ClientID, "scopes": accessToken.Scopes, @@ -251,13 +226,12 @@ func (s *TokenService) ExchangeAuthorizationCode( Success: true, }) s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventRefreshTokenIssued, - Severity: models.SeverityInfo, - ActorUserID: refreshToken.UserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: refreshToken.ID, - Action: "Refresh token issued via authorization code exchange", + EventType: models.EventRefreshTokenIssued, + Severity: models.SeverityInfo, + ActorUserID: refreshToken.UserID, + ResourceType: models.ResourceToken, + ResourceID: refreshToken.ID, + Action: "Refresh token issued via authorization code exchange", Details: models.AuditDetails{ "client_id": refreshToken.ClientID, "scopes": refreshToken.Scopes, diff --git a/internal/services/token_management.go b/internal/services/token_management.go index c0f25627..0b67159c 100644 --- a/internal/services/token_management.go +++ b/internal/services/token_management.go @@ -40,22 +40,19 @@ func (s *TokenService) RevokeTokenByID(ctx context.Context, tokenID, actorUserID return err } - actorUsername := s.resolveUsername(ctx, actorUserID) - err = s.store.RevokeToken(tokenID) if err != nil { - // Log revocation failure + // Log revocation failure — ActorUsername is auto-resolved by buildAuditLog. s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventTokenRevoked, - Severity: models.SeverityError, - ActorUserID: actorUserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: tokenID, - Action: "Token revocation failed", - Details: models.AuditDetails{"token_category": tok.TokenCategory}, - Success: false, - ErrorMessage: err.Error(), + EventType: models.EventTokenRevoked, + Severity: models.SeverityError, + ActorUserID: actorUserID, + ResourceType: models.ResourceToken, + ResourceID: tokenID, + Action: "Token revocation failed", + Details: models.AuditDetails{"token_category": tok.TokenCategory}, + Success: false, + ErrorMessage: err.Error(), }) return err } @@ -65,15 +62,14 @@ func (s *TokenService) RevokeTokenByID(ctx context.Context, tokenID, actorUserID // Record revocation s.metrics.RecordTokenRevoked(tok.TokenCategory, "user_request") - // Log token revocation + // Log token revocation — ActorUsername is auto-resolved by buildAuditLog. s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventTokenRevoked, - Severity: models.SeverityInfo, - ActorUserID: actorUserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: tokenID, - Action: "Token revoked", + EventType: models.EventTokenRevoked, + Severity: models.SeverityInfo, + ActorUserID: actorUserID, + ResourceType: models.ResourceToken, + ResourceID: tokenID, + Action: "Token revoked", Details: models.AuditDetails{ "token_category": tok.TokenCategory, "client_id": tok.ClientID, @@ -135,37 +131,33 @@ func (s *TokenService) updateTokenStatusWithAudit( } } - actorUsername := s.resolveUsername(ctx, actorUserID) - err = s.store.UpdateTokenStatus(tokenID, newStatus) if err != nil { - // Log failure + // Log failure — ActorUsername is auto-resolved by buildAuditLog. s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: eventType, - Severity: models.SeverityError, - ActorUserID: actorUserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: tokenID, - Action: actionFailed, - Details: models.AuditDetails{"token_category": tok.TokenCategory}, - Success: false, - ErrorMessage: err.Error(), + EventType: eventType, + Severity: models.SeverityError, + ActorUserID: actorUserID, + ResourceType: models.ResourceToken, + ResourceID: tokenID, + Action: actionFailed, + Details: models.AuditDetails{"token_category": tok.TokenCategory}, + Success: false, + ErrorMessage: err.Error(), }) return err } s.invalidateTokenCache(ctx, tok.TokenHash) - // Log success + // Log success — ActorUsername is auto-resolved by buildAuditLog. s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: eventType, - Severity: models.SeverityInfo, - ActorUserID: actorUserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: tokenID, - Action: actionSuccess, + EventType: eventType, + Severity: models.SeverityInfo, + ActorUserID: actorUserID, + ResourceType: models.ResourceToken, + ResourceID: tokenID, + Action: actionSuccess, Details: models.AuditDetails{ "token_category": tok.TokenCategory, "client_id": tok.ClientID, diff --git a/internal/services/token_refresh.go b/internal/services/token_refresh.go index 2c699ea3..4a164059 100644 --- a/internal/services/token_refresh.go +++ b/internal/services/token_refresh.go @@ -52,17 +52,15 @@ func (s *TokenService) revokeTokenFamilyWithAudit( s.metrics.RecordTokenRevoked("family", "replay_detection") } - // Audit log — CRITICAL severity because this indicates potential token theft - actorUsername := s.resolveUsername(ctx, reusedToken.UserID) - + // Audit log — CRITICAL severity because this indicates potential token theft. + // ActorUsername is auto-resolved by buildAuditLog. _ = s.auditService.LogSync(ctx, core.AuditLogEntry{ - EventType: models.EventSuspiciousActivity, - Severity: models.SeverityCritical, - ActorUserID: reusedToken.UserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: reusedToken.ID, - Action: "Refresh token reuse detected — token family revoked", + EventType: models.EventSuspiciousActivity, + Severity: models.SeverityCritical, + ActorUserID: reusedToken.UserID, + ResourceType: models.ResourceToken, + ResourceID: reusedToken.ID, + Action: "Refresh token reuse detected — token family revoked", Details: models.AuditDetails{ "family_id": familyID, "reused_token_id": reusedToken.ID, @@ -207,8 +205,7 @@ func (s *TokenService) RefreshAccessToken( // Record successful refresh s.metrics.RecordTokenRefresh(true) - // Log token refresh - actorUsername := s.resolveUsername(ctx, newAccessToken.UserID) + // Log token refresh — ActorUsername is auto-resolved by buildAuditLog. providerName := s.tokenProvider.Name() details := models.AuditDetails{ "client_id": newAccessToken.ClientID, @@ -224,15 +221,14 @@ func (s *TokenService) RefreshAccessToken( } s.auditService.Log(ctx, core.AuditLogEntry{ - EventType: models.EventTokenRefreshed, - Severity: models.SeverityInfo, - ActorUserID: newAccessToken.UserID, - ActorUsername: actorUsername, - ResourceType: models.ResourceToken, - ResourceID: newAccessToken.ID, - Action: "Access token refreshed", - Details: details, - Success: true, + EventType: models.EventTokenRefreshed, + Severity: models.SeverityInfo, + ActorUserID: newAccessToken.UserID, + ResourceType: models.ResourceToken, + ResourceID: newAccessToken.ID, + Action: "Access token refreshed", + Details: details, + Success: true, }) return newAccessToken, newRefreshToken, nil