fix(cloud): audit denied request authentication (#1134)

cmd/engram/cloud_runtime_auth_integration_test.go

@@ -0,0 +1,60 @@
+package main
+
+import (
+	"context"
+	"fmt"
+	"net/http"
+	"strings"
+	"testing"
+
+	"github.com/Gentleman-Programming/engram/v2/internal/cloud"
+	"github.com/Gentleman-Programming/engram/v2/internal/cloud/cloudstore"
+)
+
+func TestCloudRuntimePersistsUnknownTokenRequestAuthAudit(t *testing.T) {
+	testDSN := openIsolatedCloudRuntimeSchema(t)
+
+	const legacySyncToken = "audit-integration-legacy-token"
+	const unknownToken = "audit-integration-unknown-token"
+	t.Setenv("ENGRAM_CLOUD_TOKEN", legacySyncToken)
+	t.Setenv("ENGRAM_CLOUD_INSECURE_NO_AUTH", "")
+
+	runtime, err := newCloudRuntime(cloud.Config{
+		DSN:              testDSN,
+		JWTSecret:        "audit-integration-jwt-secret-32-bytes-plus",
+		AllowedProjects:  []string{"audit-project"},
+		TokenPepper:      "audit-integration-token-pepper-at-least-32-bytes",
+		MaxPushBodyBytes: cloud.DefaultMaxPushBodyBytes,
+	})
+	if err != nil {
+		t.Fatalf("newCloudRuntime: %v", err)
+	}
+	dcr, ok := runtime.(*defaultCloudRuntime)
+	if !ok {
+		t.Fatalf("expected *defaultCloudRuntime, got %T", runtime)
+	}
+	t.Cleanup(func() { _ = dcr.store.Close() })
+
+	status, body := doBearerRequest(t, dcr.server.Handler(), http.MethodGet, "/sync/pull?project=audit-project", unknownToken)
+	if status != http.StatusUnauthorized {
+		t.Fatalf("unknown token status = %d, want %d body=%q", status, http.StatusUnauthorized, body)
+	}
+	if body != "unauthorized: unknown token\n" {
+		t.Fatalf("unknown token 401 body = %q", body)
+	}
+
+	events, err := dcr.store.ListAuthAuditEvents(context.Background(), cloudstore.AuthAuditQuery{Limit: 10})
+	if err != nil {
+		t.Fatalf("ListAuthAuditEvents: %v", err)
+	}
+	if len(events) != 1 {
+		t.Fatalf("auth audit events = %d, want 1: %+v", len(events), events)
+	}
+	event := events[0]
+	if event.ActorPrincipalID != "" || event.ActorSource != "request" || event.Project != "" || event.Action != "sync.auth" || event.Outcome != "denied" || event.ReasonCode != "unknown_token" {
+		t.Fatalf("unexpected persisted unknown-token auth audit event: %+v", event)
+	}
+	if event.Metadata["source"] != "request" || strings.Contains(fmt.Sprintf("%+v", event), unknownToken) {
+		t.Fatalf("unknown-token audit event must contain only safe metadata: %+v", event)
+	}
+}

cmd/engram/cloud_runtime_auth_test.go

@@ -401,7 +401,7 @@ func TestCloudRuntimeAuthenticatorRejectsPrincipalTokenMismatch(t *testing.T) {
 		principal: cloudstore.Principal{ID: "p-mismatched", Kind: cloudstore.PrincipalKindHuman, DisplayName: "Alice", Role: cloudstore.PrincipalRoleAdmin, Enabled: true},
 	})
 
-	if _, err := runtimeAuth.ResolveBearerToken(context.Background(), rawToken); !errors.Is(err, auth.ErrInvalidPrincipal) {
-		t.Fatalf("expected a token/principal ID mismatch to be rejected with auth.ErrInvalidPrincipal, got %v", err)
+	if _, err := runtimeAuth.ResolveBearerToken(context.Background(), rawToken); !errors.Is(err, auth.ErrTokenPrincipalMismatch) {
+		t.Fatalf("expected a token/principal ID mismatch to be rejected with auth.ErrTokenPrincipalMismatch, got %v", err)
 	}
 }

internal/cloud/auth/foundation.go

@@ -53,6 +53,12 @@ var ErrTokenRevoked = errors.New("token is revoked")
 var ErrPrincipalDisabled = errors.New("principal is disabled")
 var ErrInvalidPrincipal = errors.New("invalid principal")
 
+// ErrTokenPrincipalMismatch reports a managed-token record whose principal
+// ID does not match the resolved principal (a storage invariant violation).
+// It is kept distinct from ErrInvalidPrincipal so audit classification can
+// separate a token/record join mismatch from a malformed stored principal.
+var ErrTokenPrincipalMismatch = errors.New("token principal mismatch")
+
 type PrincipalKind string
 
 type Role string
@@ -259,7 +265,7 @@ func (r *PrincipalResolver) ResolveBearerToken(ctx context.Context, token string
 		record, principal, err := r.managedTokens.FindManagedTokenByHash(ctx, hash)
 		if err == nil {
 			if record.PrincipalID == "" || record.PrincipalID != principal.ID {
-				return Principal{}, fmt.Errorf("%w: token principal mismatch", ErrInvalidPrincipal)
+				return Principal{}, ErrTokenPrincipalMismatch
 			}
 			if principal.Source == "" {
 				principal.Source = PrincipalSourceManagedToken

internal/cloud/auth/foundation_test.go

@@ -184,11 +184,11 @@ func TestResolverRejectsUnsafeManagedTokenRecords(t *testing.T) {
 	if _, err := resolver.ResolveBearerToken(context.Background(), "disabled-token"); !errors.Is(err, ErrPrincipalDisabled) {
 		t.Fatalf("expected disabled principal rejection, got %v", err)
 	}
-	if _, err := resolver.ResolveBearerToken(context.Background(), "mismatch-token"); !errors.Is(err, ErrInvalidPrincipal) {
-		t.Fatalf("expected token/principal mismatch rejection, got %v", err)
+	if _, err := resolver.ResolveBearerToken(context.Background(), "mismatch-token"); !errors.Is(err, ErrTokenPrincipalMismatch) || errors.Is(err, ErrInvalidPrincipal) {
+		t.Fatalf("expected token/principal mismatch rejection with ErrTokenPrincipalMismatch (not ErrInvalidPrincipal), got %v", err)
 	}
-	if _, err := resolver.ResolveBearerToken(context.Background(), "invalid-token"); !errors.Is(err, ErrInvalidPrincipal) {
-		t.Fatalf("expected invalid stored principal rejection, got %v", err)
+	if _, err := resolver.ResolveBearerToken(context.Background(), "invalid-token"); !errors.Is(err, ErrInvalidPrincipal) || errors.Is(err, ErrTokenPrincipalMismatch) {
+		t.Fatalf("expected invalid stored principal rejection with ErrInvalidPrincipal (not ErrTokenPrincipalMismatch), got %v", err)
 	}
 }
 

internal/cloud/cloudserver/cloudserver.go

@@ -93,6 +93,38 @@ const dashboardSessionCookieName = "engram_dashboard_token"
 
 var ErrDashboardSessionCodecRequired = errors.New("dashboard session codec is required for dashboard auth")
 
+// Request-auth audit vocabulary (engram#1134): every rejected sync/admin
+// request authentication is audited best-effort into cloud_auth_audit_log via
+// the same AdminIdentityStore sink the dashboard login/bootstrap flows use.
+const (
+	authAuditActionRequestAuth            = "sync.auth"
+	authAuditActionProjectAuthorize       = "sync.authorize"
+	authAuditActorSourceRequest           = "request"
+	authAuditReasonMissingHeader          = "missing_header"
+	authAuditReasonMalformedBearer        = "malformed_bearer"
+	authAuditReasonUnknownToken           = "unknown_token"
+	authAuditReasonTokenRevoked           = "token_revoked"
+	authAuditReasonPrincipalDisabled      = "principal_disabled"
+	authAuditReasonTokenPrincipalMismatch = "token_principal_mismatch"
+	authAuditReasonPepperMissing          = "pepper_missing"
+	authAuditReasonResolverError          = "resolver_error"
+	authAuditReasonAuthorizeError         = "authorize_error"
+	authAuditReasonProjectForbidden       = "project_forbidden"
+)
+
+// requestAuthAuditInsertTimeout bounds the best-effort insert after a rejected
+// request auth: the rejection is already decided, so a stalled audit insert
+// may delay the response only within this fixed budget, never indefinitely.
+const requestAuthAuditInsertTimeout = 3 * time.Second
+
+// Bearer-extraction failure sentinels. bearerTokenFromRequest's error text is
+// part of the established 401 response body; the sentinels keep audit reason
+// classification independent from those byte-sensitive messages.
+var (
+	errMissingAuthorizationHeader = errors.New("missing authorization header")
+	errAuthorizationNotBearer     = errors.New("authorization must use Bearer token")
+)
+
 func WithSyncStatusProvider(provider dashboard.SyncStatusProvider) Option {
 	return func(s *CloudServer) {
 		s.syncStatus = provider
@@ -319,39 +351,119 @@ func (s *CloudServer) authenticateRequest(w http.ResponseWriter, r *http.Request
 	if s.principalAuth != nil {
 		token, err := bearerTokenFromRequest(r)
 		if err != nil {
+			s.recordRequestAuthDeniedAudit(r, requestAuthDenyReason(err))
 			http.Error(w, fmt.Sprintf("unauthorized: %v", err), http.StatusUnauthorized)
 			return r, false
 		}
 		principal, err := s.principalAuth.ResolveBearerToken(r.Context(), token)
 		if err != nil {
+			s.recordRequestAuthDeniedAudit(r, requestAuthDenyReason(err))
 			http.Error(w, fmt.Sprintf("unauthorized: %v", err), http.StatusUnauthorized)
 			return r, false
 		}
 		return r.WithContext(WithPrincipal(r.Context(), principal)), true
 	}
 	if s.auth != nil {
 		if err := s.auth.Authorize(r); err != nil {
+			s.recordRequestAuthDeniedAudit(r, authAuditReasonAuthorizeError)
 			http.Error(w, fmt.Sprintf("unauthorized: %v", err), http.StatusUnauthorized)
 			return r, false
 		}
 	}
 	return r, true
 }
 
+// requestAuthDenyReason maps a request-auth rejection to its audit
+// reason_code. Resolver errors are classified with errors.Is against the
+// sentinel classes ResolveBearerToken returns and wraps. A token record whose
+// principal ID does not match the resolved principal is
+// ErrTokenPrincipalMismatch (token_principal_mismatch); a stored principal
+// that fails Validate() wraps ErrInvalidPrincipal and is a malformed stored
+// principal, so it falls to the generic resolver_error bucket.
+func requestAuthDenyReason(err error) string {
+	switch {
+	case errors.Is(err, errMissingAuthorizationHeader):
+		return authAuditReasonMissingHeader
+	case errors.Is(err, errAuthorizationNotBearer):
+		return authAuditReasonMalformedBearer
+	case errors.Is(err, cloudauth.ErrUnknownToken):
+		return authAuditReasonUnknownToken
+	case errors.Is(err, cloudauth.ErrTokenRevoked):
+		return authAuditReasonTokenRevoked
+	case errors.Is(err, cloudauth.ErrPrincipalDisabled):
+		return authAuditReasonPrincipalDisabled
+	case errors.Is(err, cloudauth.ErrTokenPrincipalMismatch):
+		return authAuditReasonTokenPrincipalMismatch
+	case errors.Is(err, cloudauth.ErrTokenPepperRequired):
+		return authAuditReasonPepperMissing
+	default:
+		return authAuditReasonResolverError
+	}
+}
+
+// recordRequestAuthDeniedAudit emits the per-rejection server log line and
+// records a best-effort cloud_auth_audit_log row for a rejected request
+// authentication (engram#1134). Successful request auth is intentionally
+// unaudited per request because it is a high-volume path.
+func (s *CloudServer) recordRequestAuthDeniedAudit(r *http.Request, reason string) {
+	log.Printf("[engram-cloud] request auth denied: %s (reason=%s)", r.RemoteAddr, reason)
+	s.recordAuthAuditBestEffort(r.Context(), cloudstore.AuthAuditEvent{
+		ActorSource: authAuditActorSourceRequest,
+		Action:      authAuditActionRequestAuth,
+		Outcome:     authAuditOutcomeDenied,
+		ReasonCode:  reason,
+		Metadata:    map[string]any{"source": authAuditActorSourceRequest},
+	}, "request auth")
+}
+
+// recordProjectPolicyDeniedAudit records a project authorization denial after
+// authentication has succeeded. It deliberately carries only principal and
+// project identity; bearer credentials are never logged or persisted.
+func (s *CloudServer) recordProjectPolicyDeniedAudit(ctx context.Context, project string) {
+	principal, ok := PrincipalFromContext(ctx)
+	actorID := ""
+	actorSource := authAuditActorSourceRequest
+	if ok {
+		actorID = auditActorPrincipalIDRef(principal)
+		actorSource = auditActorSource(principal)
+	}
+	log.Printf("[engram-cloud] project authorization denied: project=%q actor=%q actor_source=%q reason=%s", project, actorID, actorSource, authAuditReasonProjectForbidden)
+	s.recordAuthAuditBestEffort(ctx, cloudstore.AuthAuditEvent{
+		ActorPrincipalID: actorID,
+		ActorSource:      actorSource,
+		Project:          project,
+		Action:           authAuditActionProjectAuthorize,
+		Outcome:          authAuditOutcomeDenied,
+		ReasonCode:       authAuditReasonProjectForbidden,
+		Metadata:         map[string]any{"source": actorSource},
+	}, "project authorization")
+}
+
+// recordAuthAuditBestEffort uses a request-derived context with cancellation
+// detached so audits survive client disconnects, while the fixed timeout keeps
+// each synchronous insert bounded.
+func (s *CloudServer) recordAuthAuditBestEffort(ctx context.Context, event cloudstore.AuthAuditEvent, auditName string) {
+	if s.adminIdentity == nil {
+		log.Printf("cloudserver: admin identity store is not configured; %s audit skipped", auditName)
+		return
+	}
+	insertCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), requestAuthAuditInsertTimeout)
+	defer cancel()
+	if err := s.adminIdentity.InsertAuthAuditEvent(insertCtx, event); err != nil {
+		log.Printf("[engram-cloud] %s audit insert failed (best-effort): %v", auditName, err)
+	}
+}
+
 func bearerTokenFromRequest(r *http.Request) (string, error) {
 	header := strings.TrimSpace(r.Header.Get("Authorization"))
 	if header == "" {
-		return "", fmt.Errorf("missing authorization header")
+		return "", errMissingAuthorizationHeader
 	}
 	parts := strings.Fields(header)
 	if len(parts) != 2 || !strings.EqualFold(parts[0], "Bearer") {
-		return "", fmt.Errorf("authorization must use Bearer token")
-	}
-	token := strings.TrimSpace(parts[1])
-	if token == "" {
-		return "", fmt.Errorf("bearer token is required")
+		return "", errAuthorizationNotBearer
 	}
-	return token, nil
+	return parts[1], nil
 }
 
 func (s *CloudServer) authorizeDashboardRequest(r *http.Request) error {
@@ -667,12 +779,13 @@ func (s *CloudServer) authorizeProjectScope(ctx context.Context, w http.Response
 	if s.principalProject != nil {
 		principal, ok := PrincipalFromContext(ctx)
 		if !ok {
+			s.recordProjectPolicyDeniedAudit(ctx, project)
 			writeActionableError(w, http.StatusForbidden, constants.UpgradeErrorClassPolicy, constants.ReasonPolicyForbidden, "forbidden: principal is required")
 			return false
 		}
 		if usesManagedProjectGrants(principal) {
 			if err := s.principalProject.AuthorizeProjectForPrincipal(ctx, principal, project); err != nil {
-				writeProjectPolicyDenied(w, project)
+				s.writeProjectPolicyDenied(ctx, w, project)
 				return false
 			}
 			return true
@@ -682,7 +795,7 @@ func (s *CloudServer) authorizeProjectScope(ctx context.Context, w http.Response
 		return true
 	}
 	if err := s.projectAuth.AuthorizeProject(project); err != nil {
-		writeProjectPolicyDenied(w, project)
+		s.writeProjectPolicyDenied(ctx, w, project)
 		return false
 	}
 	return true
@@ -700,7 +813,8 @@ func writeActionableError(w http.ResponseWriter, status int, class, code, messag
 	})
 }
 
-func writeProjectPolicyDenied(w http.ResponseWriter, project string) {
+func (s *CloudServer) writeProjectPolicyDenied(ctx context.Context, w http.ResponseWriter, project string) {
+	s.recordProjectPolicyDeniedAudit(ctx, project)
 	writeActionableError(w, http.StatusForbidden, constants.UpgradeErrorClassPolicy, constants.ReasonPolicyForbidden, fmt.Sprintf("forbidden: project %q is not allowed", project))
 }