From 647c33e164a69d62df278e2e1ad2c303a58006ea Mon Sep 17 00:00:00 2001 From: Evan Jarrett Date: Fri, 2 Jan 2026 14:45:55 -0600 Subject: [PATCH] fix backoff not clearing correctly. add better logging to find out why someone is denied access (backoff, pds issue, missing record etc) --- cmd/appview/serve.go | 15 ++- pkg/appview/middleware/registry.go | 10 +- pkg/appview/storage/crew.go | 13 +- pkg/appview/storage/crew_test.go | 2 +- pkg/appview/storage/proxy_blob_store.go | 33 ++++- pkg/auth/hold_authorizer.go | 16 ++- pkg/auth/hold_local.go | 6 + pkg/auth/hold_local_test.go | 11 ++ pkg/auth/hold_remote.go | 87 ++++++++++++- pkg/auth/hold_remote_test.go | 154 ++++++++++++++++++++++++ 10 files changed, 330 insertions(+), 17 deletions(-) diff --git a/cmd/appview/serve.go b/cmd/appview/serve.go index 268a07b..bef4154 100644 --- a/cmd/appview/serve.go +++ b/cmd/appview/serve.go @@ -158,6 +158,15 @@ func serveRegistry(cmd *cobra.Command, args []string) error { middleware.SetGlobalAuthorizer(holdAuthorizer) slog.Info("Hold authorizer initialized with database caching") + // Clear all denial caches on startup for a clean slate (non-blocking) + if remote, ok := holdAuthorizer.(*auth.RemoteHoldAuthorizer); ok { + go func() { + if err := remote.ClearAllDenials(); err != nil { + slog.Warn("Failed to clear denial caches on startup", "error", err) + } + }() + } + // Initialize Jetstream workers (background services before HTTP routes) initializeJetstream(uiDatabase, &cfg.Jetstream, defaultHoldDID, testMode, refresher) @@ -303,10 +312,10 @@ func serveRegistry(cmd *cobra.Command, args []string) error { // Run in background to avoid blocking OAuth callback if hold is offline // Use background context - don't inherit request context which gets canceled on response slog.Debug("Attempting crew registration", "component", "appview/callback", "did", did, "hold_did", holdDID) - go func(client *atproto.Client, refresher *oauth.Refresher, holdDID string) { + go func(client *atproto.Client, refresher *oauth.Refresher, holdDID string, authorizer auth.HoldAuthorizer) { ctx := context.Background() - storage.EnsureCrewMembership(ctx, client, refresher, holdDID) - }(client, refresher, holdDID) + storage.EnsureCrewMembership(ctx, client, refresher, holdDID, authorizer) + }(client, refresher, holdDID, holdAuthorizer) } diff --git a/pkg/appview/middleware/registry.go b/pkg/appview/middleware/registry.go index ea1dca0..4590b5d 100644 --- a/pkg/appview/middleware/registry.go +++ b/pkg/appview/middleware/registry.go @@ -196,6 +196,12 @@ func SetGlobalAuthorizer(authorizer auth.HoldAuthorizer) { globalAuthorizer = authorizer } +// GetGlobalAuthorizer returns the global authorizer instance +// Used by components that need to clear denial cache (e.g., EnsureCrewMembership) +func GetGlobalAuthorizer() auth.HoldAuthorizer { + return globalAuthorizer +} + func init() { // Register the name resolution middleware registrymw.Register("atproto-resolver", initATProtoResolver) @@ -298,7 +304,7 @@ func (nr *NamespaceResolver) Repository(ctx context.Context, name reference.Name if holdDID != "" && nr.refresher != nil { slog.Debug("Auto-reconciling crew membership", "component", "registry/middleware", "did", did, "hold_did", holdDID) client := atproto.NewClient(pdsEndpoint, did, "") - storage.EnsureCrewMembership(ctx, client, nr.refresher, holdDID) + storage.EnsureCrewMembership(ctx, client, nr.refresher, holdDID, nr.authorizer) } // Get service token for hold authentication (only if authenticated) @@ -345,6 +351,7 @@ func (nr *NamespaceResolver) Repository(ctx context.Context, name reference.Name "pullerDID", pullerDID, "holdDID", holdDID, "pullerPDSEndpoint", pullerPDSEndpoint, + "denial_reason", "service_token_app_password_failed", "error", err) return "", err } @@ -363,6 +370,7 @@ func (nr *NamespaceResolver) Repository(ctx context.Context, name reference.Name "pullerDID", pullerDID, "holdDID", holdDID, "pullerPDSEndpoint", pullerPDSEndpoint, + "denial_reason", "service_token_oauth_failed", "error", err) return "", err } diff --git a/pkg/appview/storage/crew.go b/pkg/appview/storage/crew.go index 780f05a..47747f8 100644 --- a/pkg/appview/storage/crew.go +++ b/pkg/appview/storage/crew.go @@ -15,8 +15,9 @@ import ( // EnsureCrewMembership attempts to register the user as a crew member on their default hold. // The hold's requestCrew endpoint handles all authorization logic (checking allowAllCrew, existing membership, etc). +// On success, clears any cached denial to ensure immediate access. // This is best-effort and does not fail on errors. -func EnsureCrewMembership(ctx context.Context, client *atproto.Client, refresher *oauth.Refresher, defaultHoldDID string) { +func EnsureCrewMembership(ctx context.Context, client *atproto.Client, refresher *oauth.Refresher, defaultHoldDID string, authorizer auth.HoldAuthorizer) { if defaultHoldDID == "" { return } @@ -55,6 +56,16 @@ func EnsureCrewMembership(ctx context.Context, client *atproto.Client, refresher } slog.Info("successfully registered as crew member", "holdDID", holdDID, "userDID", client.DID()) + + // Clear any cached denial to ensure immediate access + if authorizer != nil { + if err := authorizer.ClearCrewDenial(ctx, holdDID, client.DID()); err != nil { + slog.Warn("failed to clear denial cache after crew registration", + "holdDID", holdDID, + "userDID", client.DID(), + "error", err) + } + } } // requestCrewMembership calls the hold's requestCrew endpoint diff --git a/pkg/appview/storage/crew_test.go b/pkg/appview/storage/crew_test.go index 5ffcac5..58a29b5 100644 --- a/pkg/appview/storage/crew_test.go +++ b/pkg/appview/storage/crew_test.go @@ -7,7 +7,7 @@ import ( func TestEnsureCrewMembership_EmptyHoldDID(t *testing.T) { // Test that empty hold DID returns early without error (best-effort function) - EnsureCrewMembership(context.Background(), nil, nil, "") + EnsureCrewMembership(context.Background(), nil, nil, "", nil) // If we get here without panic, test passes } diff --git a/pkg/appview/storage/proxy_blob_store.go b/pkg/appview/storage/proxy_blob_store.go index db9304b..ce6099b 100644 --- a/pkg/appview/storage/proxy_blob_store.go +++ b/pkg/appview/storage/proxy_blob_store.go @@ -96,20 +96,43 @@ func (p *ProxyBlobStore) checkReadAccess(ctx context.Context) error { // checkWriteAccess validates that the user has write access to blobs in this hold func (p *ProxyBlobStore) checkWriteAccess(ctx context.Context) error { if p.ctx.Authorizer == nil { - return nil // No authorization check if authorizer not configured + slog.Debug("Write access check skipped - no authorizer configured", + "component", "proxy_blob_store") + return nil } - slog.Debug("Checking write access", "component", "proxy_blob_store", "user_did", p.ctx.DID, "hold_did", p.ctx.HoldDID) + slog.Debug("Checking write access", + "component", "proxy_blob_store", + "user_did", p.ctx.DID, + "hold_did", p.ctx.HoldDID) + allowed, err := p.ctx.Authorizer.CheckWriteAccess(ctx, p.ctx.HoldDID, p.ctx.DID) if err != nil { - slog.Error("Authorization check error", "component", "proxy_blob_store", "error", err) + // Authorization check itself failed (network, PDS error, etc.) + slog.Error("Write access authorization check failed", + "component", "proxy_blob_store", + "user_did", p.ctx.DID, + "hold_did", p.ctx.HoldDID, + "denial_reason", "authorization_check_error", + "error", err) return fmt.Errorf("authorization check failed: %w", err) } + if !allowed { - slog.Warn("Write access denied", "component", "proxy_blob_store", "user_did", p.ctx.DID, "hold_did", p.ctx.HoldDID) + // Access explicitly denied (logged in detail by authorizer) + slog.Warn("Write access denied", + "component", "proxy_blob_store", + "user_did", p.ctx.DID, + "hold_did", p.ctx.HoldDID, + "denial_reason", "access_denied_by_authorizer", + "hint", "check DEBUG logs for specific denial reason (denial_reason field)") return errcode.ErrorCodeDenied.WithMessage(fmt.Sprintf("write access denied to hold %s", p.ctx.HoldDID)) } - slog.Debug("Write access allowed", "component", "proxy_blob_store", "user_did", p.ctx.DID, "hold_did", p.ctx.HoldDID) + + slog.Debug("Write access allowed", + "component", "proxy_blob_store", + "user_did", p.ctx.DID, + "hold_did", p.ctx.HoldDID) return nil } diff --git a/pkg/auth/hold_authorizer.go b/pkg/auth/hold_authorizer.go index cacacdc..b06008a 100644 --- a/pkg/auth/hold_authorizer.go +++ b/pkg/auth/hold_authorizer.go @@ -25,6 +25,11 @@ type HoldAuthorizer interface { // IsCrewMember checks if userDID is a crew member of holdDID IsCrewMember(ctx context.Context, holdDID, userDID string) (bool, error) + + // ClearCrewDenial removes any cached denial for a user/hold pair + // Called when user successfully becomes a crew member to ensure immediate access + // Returns nil if no denial cache exists or invalidation succeeds + ClearCrewDenial(ctx context.Context, holdDID, userDID string) error } // CheckReadAccessWithCaptain implements the standard read authorization logic @@ -60,7 +65,10 @@ func CheckWriteAccessWithCaptain(captain *atproto.CaptainRecord, userDID string, if userDID == "" { // Anonymous writes not allowed - slog.Debug("Write access denied: anonymous user") + slog.Debug("Write access denied", + "userDID", userDID, + "denial_reason", "anonymous_user", + "message", "anonymous writes not allowed") return false } @@ -75,7 +83,11 @@ func CheckWriteAccessWithCaptain(captain *atproto.CaptainRecord, userDID string, if isCrew { slog.Debug("Write access allowed: user is crew member") } else { - slog.Debug("Write access denied: user is not owner or crew") + slog.Debug("Write access denied", + "userDID", userDID, + "owner", captain.Owner, + "denial_reason", "not_owner_or_crew", + "message", "user is not owner or crew member") } return isCrew } diff --git a/pkg/auth/hold_local.go b/pkg/auth/hold_local.go index d0d636c..2007771 100644 --- a/pkg/auth/hold_local.go +++ b/pkg/auth/hold_local.go @@ -99,3 +99,9 @@ func (a *LocalHoldAuthorizer) CheckWriteAccess(ctx context.Context, holdDID, use return CheckWriteAccessWithCaptain(captain, userDID, isCrew), nil } + +// ClearCrewDenial is a no-op for LocalHoldAuthorizer +// Local authorizer queries PDS directly without caching +func (a *LocalHoldAuthorizer) ClearCrewDenial(ctx context.Context, holdDID, userDID string) error { + return nil +} diff --git a/pkg/auth/hold_local_test.go b/pkg/auth/hold_local_test.go index c1f22fc..e3ff9a5 100644 --- a/pkg/auth/hold_local_test.go +++ b/pkg/auth/hold_local_test.go @@ -386,3 +386,14 @@ func TestLocalHoldAuthorizer_CheckReadAccess_CrewMember(t *testing.T) { t.Error("Expected read access for crew member on private hold") } } + +func TestLocalHoldAuthorizer_ClearCrewDenial(t *testing.T) { + // LocalHoldAuthorizer.ClearCrewDenial should be a no-op (returns nil) + // since local authorizer doesn't have caching + authorizer := NewLocalHoldAuthorizer(sharedEmptyPDS) + + err := authorizer.ClearCrewDenial(context.Background(), "did:web:hold.example.com", "did:plc:user123") + if err != nil { + t.Errorf("LocalHoldAuthorizer.ClearCrewDenial should return nil, got %v", err) + } +} diff --git a/pkg/auth/hold_remote.go b/pkg/auth/hold_remote.go index 8fdd685..e7cc14d 100644 --- a/pkg/auth/hold_remote.go +++ b/pkg/auth/hold_remote.go @@ -117,7 +117,11 @@ func (a *RemoteHoldAuthorizer) GetCaptainRecord(ctx context.Context, holdDID str // Cache miss or expired - query XRPC endpoint record, err := a.fetchCaptainRecordFromXRPC(ctx, holdDID) if err != nil { - return nil, err + slog.Error("Captain record fetch failed", + "holdDID", holdDID, + "denial_reason", "captain_record_fetch_failed", + "error", err) + return nil, fmt.Errorf("failed to get captain record for %s: %w", holdDID, err) } // Update cache @@ -293,7 +297,7 @@ func (a *RemoteHoldAuthorizer) IsCrewMember(ctx context.Context, holdDID, userDI // Check denial cache with backoff if blocked, err := a.isBlockedByDenialBackoff(holdDID, userDID); err == nil && blocked { // Still in backoff period - don't query again - slog.Debug("Blocked by denial backoff cache", "holdDID", holdDID, "userDID", userDID) + // Detailed logging already emitted by isBlockedByDenialBackoff return false, nil } @@ -470,6 +474,14 @@ func (a *RemoteHoldAuthorizer) isBlockedByDenialBackoff(holdDID, userDID string) entry := val.(denialEntry) // Check if still within first denial backoff period if time.Since(entry.timestamp) < a.firstDenialBackoff { + slog.Debug("Write access blocked by in-memory denial cache", + "holdDID", holdDID, + "userDID", userDID, + "denial_reason", "first_denial_backoff", + "backoff_type", "in_memory", + "backoff_duration", a.firstDenialBackoff, + "denied_at", entry.timestamp, + "retry_after", entry.timestamp.Add(a.firstDenialBackoff)) return true, nil // Still blocked by in-memory first denial } } @@ -494,6 +506,13 @@ func (a *RemoteHoldAuthorizer) isBlockedByDenialBackoff(holdDID, userDID string) // Check if still in backoff period if time.Now().Before(nextRetryAt) { + slog.Debug("Write access blocked by database denial cache", + "holdDID", holdDID, + "userDID", userDID, + "denial_reason", "exponential_backoff", + "backoff_type", "database", + "next_retry_at", nextRetryAt, + "retry_in", time.Until(nextRetryAt).Round(time.Second)) return true, nil // Still blocked } @@ -522,7 +541,15 @@ func (a *RemoteHoldAuthorizer) cacheDenial(holdDID, userDID string) error { // If not in memory and not in DB, this is the first denial if !inMemory && !inDB { // First denial: store only in memory with configurable backoff - a.recentDenials.Store(key, denialEntry{timestamp: time.Now()}) + now := time.Now() + a.recentDenials.Store(key, denialEntry{timestamp: now}) + slog.Info("Cached first crew denial (in-memory)", + "holdDID", holdDID, + "userDID", userDID, + "denial_count", 1, + "backoff_type", "in_memory", + "backoff_duration", a.firstDenialBackoff, + "retry_after", now.Add(a.firstDenialBackoff)) return nil } @@ -543,11 +570,22 @@ func (a *RemoteHoldAuthorizer) cacheDenial(holdDID, userDID string) error { ` _, err = a.db.Exec(upsertQuery, holdDID, userDID, denialCount, nextRetry, now) + if err != nil { + return err + } // Remove from in-memory cache since we're now tracking in DB a.recentDenials.Delete(key) - return err + slog.Info("Cached crew denial with exponential backoff", + "holdDID", holdDID, + "userDID", userDID, + "denial_count", denialCount, + "backoff_type", "database", + "backoff_duration", backoff, + "next_retry_at", nextRetry) + + return nil } // getBackoffDuration returns the backoff duration based on denial count @@ -563,3 +601,44 @@ func (a *RemoteHoldAuthorizer) getBackoffDuration(denialCount int) time.Duration return backoffs[idx] } + +// ClearCrewDenial removes crew denial from both in-memory and database caches +// This allows immediate access after a user becomes a crew member +func (a *RemoteHoldAuthorizer) ClearCrewDenial(ctx context.Context, holdDID, userDID string) error { + // Clear in-memory cache + key := fmt.Sprintf("%s:%s", holdDID, userDID) + a.recentDenials.Delete(key) + + // Clear database cache + if a.db != nil { + query := `DELETE FROM hold_crew_denials WHERE hold_did = ? AND user_did = ?` + _, err := a.db.ExecContext(ctx, query, holdDID, userDID) + if err != nil { + return fmt.Errorf("failed to clear denial cache: %w", err) + } + } + + slog.Debug("Cleared crew denial cache", "holdDID", holdDID, "userDID", userDID) + return nil +} + +// ClearAllDenials removes all crew denials from both in-memory and database caches +// Called on startup to ensure a clean slate +func (a *RemoteHoldAuthorizer) ClearAllDenials() error { + // Clear all in-memory denials + a.recentDenials.Range(func(key, value any) bool { + a.recentDenials.Delete(key) + return true + }) + + // Clear all database denials + if a.db != nil { + _, err := a.db.Exec("DELETE FROM hold_crew_denials") + if err != nil { + return fmt.Errorf("failed to clear all denial caches: %w", err) + } + } + + slog.Info("Cleared all crew denial caches on startup") + return nil +} diff --git a/pkg/auth/hold_remote_test.go b/pkg/auth/hold_remote_test.go index 35b1d9c..32fbd8a 100644 --- a/pkg/auth/hold_remote_test.go +++ b/pkg/auth/hold_remote_test.go @@ -304,3 +304,157 @@ func TestCheckReadAccess_PublicHold(t *testing.T) { _ = server } + +func TestClearCrewDenial_InMemory(t *testing.T) { + testDB := setupTestDB(t) + remote := NewRemoteHoldAuthorizerWithBackoffs( + testDB, false, + 10*time.Millisecond, // firstDenialBackoff + 50*time.Millisecond, // cleanupInterval + 50*time.Millisecond, // cleanupGracePeriod + []time.Duration{10 * time.Millisecond, 20 * time.Millisecond}, + ).(*RemoteHoldAuthorizer) + defer close(remote.stopCleanup) + + holdDID := "did:web:hold01.atcr.io" + userDID := "did:plc:user123" + + // Cache first denial (in-memory only) + _ = remote.cacheDenial(holdDID, userDID) + + // Verify blocked + blocked, _ := remote.isBlockedByDenialBackoff(holdDID, userDID) + if !blocked { + t.Error("Expected to be blocked by denial") + } + + // Clear denial + err := remote.ClearCrewDenial(context.Background(), holdDID, userDID) + if err != nil { + t.Fatalf("ClearCrewDenial failed: %v", err) + } + + // Verify no longer blocked + blocked, _ = remote.isBlockedByDenialBackoff(holdDID, userDID) + if blocked { + t.Error("Expected denial to be cleared") + } +} + +func TestClearCrewDenial_Database(t *testing.T) { + testDB := setupTestDB(t) + remote := NewRemoteHoldAuthorizerWithBackoffs( + testDB, false, + 10*time.Millisecond, // firstDenialBackoff + 50*time.Millisecond, // cleanupInterval + 50*time.Millisecond, // cleanupGracePeriod + []time.Duration{10 * time.Millisecond, 20 * time.Millisecond}, + ).(*RemoteHoldAuthorizer) + defer close(remote.stopCleanup) + + holdDID := "did:web:hold01.atcr.io" + userDID := "did:plc:user123" + + // Cache first denial (in-memory) + _ = remote.cacheDenial(holdDID, userDID) + + // Wait for backoff, then trigger second denial (goes to DB) + time.Sleep(15 * time.Millisecond) + _ = remote.cacheDenial(holdDID, userDID) + + // Verify blocked by DB denial + blocked, _ := remote.isBlockedByDenialBackoff(holdDID, userDID) + if !blocked { + t.Error("Expected to be blocked by DB denial") + } + + // Clear denial + err := remote.ClearCrewDenial(context.Background(), holdDID, userDID) + if err != nil { + t.Fatalf("ClearCrewDenial failed: %v", err) + } + + // Verify no longer blocked + blocked, _ = remote.isBlockedByDenialBackoff(holdDID, userDID) + if blocked { + t.Error("Expected denial to be cleared from DB") + } +} + +func TestDeniedUserBecomesCrewImmediateAccess(t *testing.T) { + testDB := setupTestDB(t) + remote := NewRemoteHoldAuthorizerWithBackoffs( + testDB, false, + 1*time.Hour, // Long backoff to ensure test would fail without fix + 50*time.Millisecond, + 50*time.Millisecond, + []time.Duration{1 * time.Hour}, // Long DB backoff + ).(*RemoteHoldAuthorizer) + defer close(remote.stopCleanup) + + holdDID := "did:web:hold01.atcr.io" + userDID := "did:plc:user123" + + // Simulate denial being cached (user not yet crew) + _ = remote.cacheDenial(holdDID, userDID) + + // User is now blocked + blocked, _ := remote.isBlockedByDenialBackoff(holdDID, userDID) + if !blocked { + t.Fatal("Expected user to be blocked initially") + } + + // Simulate successful crew registration + cache clear + // (This is what EnsureCrewMembership does after requestCrew succeeds) + err := remote.ClearCrewDenial(context.Background(), holdDID, userDID) + if err != nil { + t.Fatalf("ClearCrewDenial failed: %v", err) + } + + // User should no longer be blocked + blocked, _ = remote.isBlockedByDenialBackoff(holdDID, userDID) + if blocked { + t.Error("User should have immediate access after crew registration") + } +} + +func TestClearAllDenials_OnStartup(t *testing.T) { + testDB := setupTestDB(t) + remote := NewRemoteHoldAuthorizerWithBackoffs( + testDB, false, + 1*time.Hour, // Long backoff + 50*time.Millisecond, + 50*time.Millisecond, + []time.Duration{1 * time.Hour}, + ).(*RemoteHoldAuthorizer) + defer close(remote.stopCleanup) + + // Add multiple denials for different users/holds + _ = remote.cacheDenial("did:web:hold01.atcr.io", "did:plc:user1") + _ = remote.cacheDenial("did:web:hold01.atcr.io", "did:plc:user2") + _ = remote.cacheDenial("did:web:hold02.atcr.io", "did:plc:user1") + + // Verify all are blocked + blocked1, _ := remote.isBlockedByDenialBackoff("did:web:hold01.atcr.io", "did:plc:user1") + blocked2, _ := remote.isBlockedByDenialBackoff("did:web:hold01.atcr.io", "did:plc:user2") + blocked3, _ := remote.isBlockedByDenialBackoff("did:web:hold02.atcr.io", "did:plc:user1") + + if !blocked1 || !blocked2 || !blocked3 { + t.Fatal("Expected all users to be blocked initially") + } + + // Clear all denials (simulating startup) + err := remote.ClearAllDenials() + if err != nil { + t.Fatalf("ClearAllDenials failed: %v", err) + } + + // Verify none are blocked + blocked1, _ = remote.isBlockedByDenialBackoff("did:web:hold01.atcr.io", "did:plc:user1") + blocked2, _ = remote.isBlockedByDenialBackoff("did:web:hold01.atcr.io", "did:plc:user2") + blocked3, _ = remote.isBlockedByDenialBackoff("did:web:hold02.atcr.io", "did:plc:user1") + + if blocked1 || blocked2 || blocked3 { + t.Error("Expected all denials to be cleared after ClearAllDenials") + } +}