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

@@ -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)
 
 		}
 

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
 					}

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

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
 }
 

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
 }
 

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
 }

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
+}

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)
+	}
+}

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
+}

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")
+	}
+}