diff --git a/cmd/appview/serve.go b/cmd/appview/serve.go index 59f4e2f..75424b7 100644 --- a/cmd/appview/serve.go +++ b/cmd/appview/serve.go @@ -265,13 +265,25 @@ func serveRegistry(cmd *cobra.Command, args []string) error { } // Store user in database (with or without avatar) - err = db.UpsertUserIgnoreAvatar(uiDatabase, &db.User{ - DID: did, - Handle: handle, - PDSEndpoint: pdsEndpoint, - Avatar: avatarURL, - LastSeen: time.Now(), - }) + // Use UpsertUser if we successfully fetched an avatar (to update existing users) + // Use UpsertUserIgnoreAvatar if fetch failed (to preserve existing avatars) + if avatarURL != "" { + err = db.UpsertUser(uiDatabase, &db.User{ + DID: did, + Handle: handle, + PDSEndpoint: pdsEndpoint, + Avatar: avatarURL, + LastSeen: time.Now(), + }) + } else { + err = db.UpsertUserIgnoreAvatar(uiDatabase, &db.User{ + DID: did, + Handle: handle, + PDSEndpoint: pdsEndpoint, + Avatar: avatarURL, + LastSeen: time.Now(), + }) + } if err != nil { slog.Warn("Failed to store user in database", "component", "appview/callback", "error", err) return nil // Non-fatal diff --git a/pkg/appview/db/queries.go b/pkg/appview/db/queries.go index 8a4bbdc..961d0f5 100644 --- a/pkg/appview/db/queries.go +++ b/pkg/appview/db/queries.go @@ -374,6 +374,15 @@ func UpdateUserLastSeen(db *sql.DB, did string) error { return err } +// UpdateUserHandle updates a user's handle when an identity change event is received +// This is called when Jetstream receives an identity event indicating a handle change +func UpdateUserHandle(db *sql.DB, did string, newHandle string) error { + _, err := db.Exec(` + UPDATE users SET handle = ?, last_seen = ? WHERE did = ? + `, newHandle, time.Now(), did) + return err +} + // GetManifestDigestsForDID returns all manifest digests for a DID func GetManifestDigestsForDID(db *sql.DB, did string) ([]string, error) { rows, err := db.Query(` diff --git a/pkg/appview/db/queries_test.go b/pkg/appview/db/queries_test.go index 0e7a4b4..8a07179 100644 --- a/pkg/appview/db/queries_test.go +++ b/pkg/appview/db/queries_test.go @@ -977,3 +977,78 @@ func TestGetTagsWithPlatforms(t *testing.T) { // Don't use manifestID1 since it's not accessed after assignment _ = manifestID1 } + +func TestUpdateUserHandle(t *testing.T) { + // Create in-memory test database + db, err := InitDB(":memory:") + if err != nil { + t.Fatalf("Failed to init database: %v", err) + } + defer db.Close() + + // Setup: Create test user + testUser := &User{ + DID: "did:plc:alice123", + Handle: "alice.bsky.social", + PDSEndpoint: "https://bsky.social", + Avatar: "https://example.com/avatar.jpg", + LastSeen: time.Now(), + } + err = UpsertUser(db, testUser) + if err != nil { + t.Fatalf("Failed to create test user: %v", err) + } + + // Test 1: Update handle for existing user + newHandle := "alice-new.bsky.social" + err = UpdateUserHandle(db, testUser.DID, newHandle) + if err != nil { + t.Fatalf("Failed to update user handle: %v", err) + } + + // Verify handle was updated + retrieved, err := GetUserByDID(db, testUser.DID) + if err != nil { + t.Fatalf("Failed to get user after handle update: %v", err) + } + if retrieved == nil { + t.Fatal("Expected user to be found, got nil") + } + if retrieved.Handle != newHandle { + t.Errorf("Expected handle '%s', got '%s'", newHandle, retrieved.Handle) + } + + // Verify other fields unchanged + if retrieved.DID != testUser.DID { + t.Errorf("DID changed unexpectedly: %s -> %s", testUser.DID, retrieved.DID) + } + if retrieved.PDSEndpoint != testUser.PDSEndpoint { + t.Errorf("PDS endpoint changed unexpectedly") + } + if retrieved.Avatar != testUser.Avatar { + t.Errorf("Avatar changed unexpectedly") + } + + // Test 2: Update handle for non-existent user (should not error, but no rows affected) + err = UpdateUserHandle(db, "did:plc:nonexistent", "new.handle.social") + if err != nil { + t.Errorf("Expected no error for non-existent user, got: %v", err) + } + + // Test 3: Update handle multiple times + handles := []string{"alice1.bsky.social", "alice2.bsky.social", "alice3.bsky.social"} + for _, handle := range handles { + err = UpdateUserHandle(db, testUser.DID, handle) + if err != nil { + t.Fatalf("Failed to update handle to '%s': %v", handle, err) + } + + retrieved, err = GetUserByDID(db, testUser.DID) + if err != nil { + t.Fatalf("Failed to retrieve user: %v", err) + } + if retrieved.Handle != handle { + t.Errorf("Expected handle '%s', got '%s'", handle, retrieved.Handle) + } + } +} diff --git a/pkg/appview/jetstream/processor.go b/pkg/appview/jetstream/processor.go index ad30dc4..09ec095 100644 --- a/pkg/appview/jetstream/processor.go +++ b/pkg/appview/jetstream/processor.go @@ -87,7 +87,12 @@ func (p *Processor) EnsureUser(ctx context.Context, did string) error { p.userCache.cache[did] = user } - // Upsert to database - preserve existing avatar if fetch failed + // Upsert to database + // Use UpsertUser if we successfully fetched an avatar (to update existing users) + // Use UpsertUserIgnoreAvatar if fetch failed (to preserve existing avatars) + if avatarURL != "" { + return db.UpsertUser(p.db, user) + } return db.UpsertUserIgnoreAvatar(p.db, user) } @@ -275,3 +280,72 @@ func (p *Processor) ProcessSailorProfile(ctx context.Context, did string, record return nil } + +// ProcessIdentity handles identity change events (handle updates) +// This is called when Jetstream receives an identity event indicating a handle change. +// The identity cache is invalidated to ensure the next lookup uses the new handle, +// and the database is updated to reflect the change in the UI. +func (p *Processor) ProcessIdentity(ctx context.Context, did string, newHandle string) error { + // Update handle in database + if err := db.UpdateUserHandle(p.db, did, newHandle); err != nil { + slog.Warn("Failed to update user handle in database", + "component", "processor", + "did", did, + "handle", newHandle, + "error", err) + // Continue to invalidate cache even if DB update fails + } + + // Invalidate cached identity data to force re-resolution on next lookup + if err := atproto.InvalidateIdentity(ctx, did); err != nil { + slog.Warn("Failed to invalidate identity cache", + "component", "processor", + "did", did, + "error", err) + return err + } + + slog.Info("Processed identity change event", + "component", "processor", + "did", did, + "new_handle", newHandle) + + return nil +} + +// ProcessAccount handles account status events (deactivation/reactivation) +// This is called when Jetstream receives an account event indicating status changes. +// +// IMPORTANT: Deactivation events are ambiguous - they could indicate: +// 1. Permanent account deactivation (user deleted account) +// 2. PDS migration (account deactivated at old PDS, reactivated at new PDS) +// +// We DO NOT delete user data on deactivation events. Instead, we invalidate the +// identity cache. On the next resolution attempt: +// - If migrated: Resolution finds the new PDS and updates the database automatically +// - If truly deactivated: Resolution fails and user won't appear in new queries +// +// This approach prevents data loss from PDS migrations while still handling deactivations. +func (p *Processor) ProcessAccount(ctx context.Context, did string, active bool, status string) error { + // Only process deactivation events + if active || status != "deactivated" { + return nil + } + + // Invalidate cached identity data to force re-resolution on next lookup + // This will discover if the account was migrated (new PDS) or truly deactivated (resolution fails) + if err := atproto.InvalidateIdentity(ctx, did); err != nil { + slog.Warn("Failed to invalidate identity cache for deactivated account", + "component", "processor", + "did", did, + "error", err) + return err + } + + slog.Info("Processed account deactivation event - cache invalidated", + "component", "processor", + "did", did, + "status", status) + + return nil +} diff --git a/pkg/appview/jetstream/processor_test.go b/pkg/appview/jetstream/processor_test.go index 51e211b..9132227 100644 --- a/pkg/appview/jetstream/processor_test.go +++ b/pkg/appview/jetstream/processor_test.go @@ -549,3 +549,145 @@ func TestProcessManifest_EmptyAnnotations(t *testing.T) { t.Errorf("Expected 0 annotations for nil annotations, got %d", annotationCount) } } + +func TestProcessIdentity(t *testing.T) { + db := setupTestDB(t) + defer db.Close() + + processor := NewProcessor(db, false) + + // Setup: Create test user + testDID := "did:plc:alice123" + testHandle := "alice.bsky.social" + testPDS := "https://bsky.social" + _, err := db.Exec(` + INSERT INTO users (did, handle, pds_endpoint, last_seen) + VALUES (?, ?, ?, ?) + `, testDID, testHandle, testPDS, time.Now()) + if err != nil { + t.Fatalf("Failed to insert test user: %v", err) + } + + // Test 1: Process identity change event + newHandle := "alice-new.bsky.social" + err = processor.ProcessIdentity(context.Background(), testDID, newHandle) + // Note: This will fail to invalidate cache since we don't have a real identity directory, + // but we can still verify the database update happened + if err != nil { + t.Logf("Expected cache invalidation error (no real directory): %v", err) + } + + // Verify handle was updated in database + var retrievedHandle string + err = db.QueryRow(` + SELECT handle FROM users WHERE did = ? + `, testDID).Scan(&retrievedHandle) + if err != nil { + t.Fatalf("Failed to query updated user: %v", err) + } + if retrievedHandle != newHandle { + t.Errorf("Expected handle '%s', got '%s'", newHandle, retrievedHandle) + } + + // Test 2: Process identity change for non-existent user + // Should not error (UPDATE just affects 0 rows) + err = processor.ProcessIdentity(context.Background(), "did:plc:nonexistent", "new.handle") + if err != nil { + t.Logf("Expected cache invalidation error: %v", err) + } + + // Test 3: Process multiple identity changes + handles := []string{"alice1.bsky.social", "alice2.bsky.social", "alice3.bsky.social"} + for _, handle := range handles { + err = processor.ProcessIdentity(context.Background(), testDID, handle) + if err != nil { + t.Logf("Expected cache invalidation error: %v", err) + } + + err = db.QueryRow(` + SELECT handle FROM users WHERE did = ? + `, testDID).Scan(&retrievedHandle) + if err != nil { + t.Fatalf("Failed to query user after handle update: %v", err) + } + if retrievedHandle != handle { + t.Errorf("Expected handle '%s', got '%s'", handle, retrievedHandle) + } + } +} + +func TestProcessAccount(t *testing.T) { + db := setupTestDB(t) + defer db.Close() + + processor := NewProcessor(db, false) + + // Setup: Create test user + testDID := "did:plc:bob456" + testHandle := "bob.bsky.social" + testPDS := "https://bsky.social" + _, err := db.Exec(` + INSERT INTO users (did, handle, pds_endpoint, last_seen) + VALUES (?, ?, ?, ?) + `, testDID, testHandle, testPDS, time.Now()) + if err != nil { + t.Fatalf("Failed to insert test user: %v", err) + } + + // Test 1: Process account deactivation event + err = processor.ProcessAccount(context.Background(), testDID, false, "deactivated") + // Note: Cache invalidation will fail without real directory, but that's expected + if err != nil { + t.Logf("Expected cache invalidation error (no real directory): %v", err) + } + + // Verify user still exists in database (we don't delete on deactivation) + var exists bool + err = db.QueryRow(` + SELECT EXISTS(SELECT 1 FROM users WHERE did = ?) + `, testDID).Scan(&exists) + if err != nil { + t.Fatalf("Failed to check if user exists: %v", err) + } + if !exists { + t.Error("User should still exist after deactivation event (no deletion)") + } + + // Test 2: Process account with active=true (should be ignored) + err = processor.ProcessAccount(context.Background(), testDID, true, "active") + if err != nil { + t.Errorf("Expected no error for active account, got: %v", err) + } + + // Test 3: Process account with status != "deactivated" (should be ignored) + err = processor.ProcessAccount(context.Background(), testDID, false, "suspended") + if err != nil { + t.Errorf("Expected no error for non-deactivated status, got: %v", err) + } + + // Test 4: Process account deactivation for non-existent user + err = processor.ProcessAccount(context.Background(), "did:plc:nonexistent", false, "deactivated") + // Cache invalidation will fail, but that's expected + if err != nil { + t.Logf("Expected cache invalidation error: %v", err) + } + + // Test 5: Process multiple deactivation events (idempotent) + for i := 0; i < 3; i++ { + err = processor.ProcessAccount(context.Background(), testDID, false, "deactivated") + if err != nil { + t.Logf("Expected cache invalidation error on iteration %d: %v", i, err) + } + } + + // User should still exist after multiple deactivations + err = db.QueryRow(` + SELECT EXISTS(SELECT 1 FROM users WHERE did = ?) + `, testDID).Scan(&exists) + if err != nil { + t.Fatalf("Failed to check if user exists after multiple deactivations: %v", err) + } + if !exists { + t.Error("User should still exist after multiple deactivation events") + } +} diff --git a/pkg/appview/jetstream/worker.go b/pkg/appview/jetstream/worker.go index d8aff69..c116e4e 100644 --- a/pkg/appview/jetstream/worker.go +++ b/pkg/appview/jetstream/worker.go @@ -284,38 +284,53 @@ func (w *Worker) processMessage(message []byte) error { w.eventCallback(event.TimeUS) } - // Only process commit events - if event.Kind != "commit" { - return nil - } + // Process based on event kind + switch event.Kind { + case "commit": + commit := event.Commit + if commit == nil { + return nil + } - commit := event.Commit - if commit == nil { - return nil - } + // Set DID on commit from parent event + commit.DID = event.DID - // Set DID on commit from parent event - commit.DID = event.DID + // Debug: log first few collections we see to understand what's coming through + if w.debugCollectionCount < 5 { + slog.Debug("Jetstream received collection", "collection", commit.Collection, "did", commit.DID) + w.debugCollectionCount++ + } - // Debug: log first few collections we see to understand what's coming through - if w.debugCollectionCount < 5 { - slog.Debug("Jetstream received collection", "collection", commit.Collection, "did", commit.DID) - w.debugCollectionCount++ - } + // Process based on collection + switch commit.Collection { + case atproto.ManifestCollection: + slog.Info("Jetstream processing manifest event", "did", commit.DID, "operation", commit.Operation, "rkey", commit.RKey) + return w.processManifest(commit) + case atproto.TagCollection: + slog.Info("Jetstream processing tag event", "did", commit.DID, "operation", commit.Operation, "rkey", commit.RKey) + return w.processTag(commit) + case atproto.StarCollection: + slog.Info("Jetstream processing star event", "did", commit.DID, "operation", commit.Operation, "rkey", commit.RKey) + return w.processStar(commit) + default: + // Ignore other collections + return nil + } + + case "identity": + if event.Identity == nil { + return nil + } + return w.processIdentity(&event) + + case "account": + if event.Account == nil { + return nil + } + return w.processAccount(&event) - // Process based on collection - switch commit.Collection { - case atproto.ManifestCollection: - slog.Info("Jetstream processing manifest event", "did", commit.DID, "operation", commit.Operation, "rkey", commit.RKey) - return w.processManifest(commit) - case atproto.TagCollection: - slog.Info("Jetstream processing tag event", "did", commit.DID, "operation", commit.Operation, "rkey", commit.RKey) - return w.processTag(commit) - case atproto.StarCollection: - slog.Info("Jetstream processing star event", "did", commit.DID, "operation", commit.Operation, "rkey", commit.RKey) - return w.processStar(commit) default: - // Ignore other collections + // Ignore unknown event kinds return nil } } @@ -421,6 +436,39 @@ func (w *Worker) processStar(commit *CommitEvent) error { return w.processor.ProcessStar(context.Background(), commit.DID, recordBytes) } +// processIdentity processes an identity event (handle change) +func (w *Worker) processIdentity(event *JetstreamEvent) error { + if event.Identity == nil { + return nil + } + + identity := event.Identity + slog.Info("Jetstream processing identity event", + "did", identity.DID, + "handle", identity.Handle, + "seq", identity.Seq) + + // Process via shared processor + return w.processor.ProcessIdentity(context.Background(), identity.DID, identity.Handle) +} + +// processAccount processes an account event (status change) +func (w *Worker) processAccount(event *JetstreamEvent) error { + if event.Account == nil { + return nil + } + + account := event.Account + slog.Info("Jetstream processing account event", + "did", account.DID, + "active", account.Active, + "status", account.Status, + "seq", account.Seq) + + // Process via shared processor + return w.processor.ProcessAccount(context.Background(), account.DID, account.Active, account.Status) +} + // JetstreamEvent represents a Jetstream event type JetstreamEvent struct { DID string `json:"did"` diff --git a/pkg/atproto/directory.go b/pkg/atproto/directory.go index 6f27d92..3273879 100644 --- a/pkg/atproto/directory.go +++ b/pkg/atproto/directory.go @@ -17,9 +17,12 @@ var ( directoryOnce sync.Once ) -// GetDirectory returns a shared identity.Directory instance with an 8-hour cache TTL. -// This is based on indigo's DefaultDirectory() but with a reduced cache TTL -// to allow faster recovery from PDS migrations (8h instead of 24h). +// GetDirectory returns a shared identity.Directory instance with a 24-hour cache TTL. +// This is based on indigo's DefaultDirectory() with event-driven cache invalidation. +// +// Cache entries are invalidated via Jetstream events (identity changes, account status) +// which allows for a longer TTL while maintaining freshness. The Purge() method is called +// when identity or account events are received, ensuring the cache reflects real-time changes. // // Using a shared instance ensures all identity lookups across the application // use the same cache, which is more memory-efficient and provides better cache hit rates. @@ -48,10 +51,10 @@ func GetDirectory() identity.Directory { } // Cache configuration: // - capacity: 250,000 entries - // - hitTTL: 8 hours (reduced from indigo's default 24h for faster PDS migration recovery) + // - hitTTL: 24 hours (event-driven invalidation via Jetstream provides freshness) // - errTTL: 2 minutes // - invalidHandleTTL: 5 minutes - cached := identity.NewCacheDirectory(&base, 250_000, time.Hour*8, time.Minute*2, time.Minute*5) + cached := identity.NewCacheDirectory(&base, 250_000, time.Hour*24, time.Minute*2, time.Minute*5) sharedDirectory = &cached }) return sharedDirectory diff --git a/pkg/atproto/resolver.go b/pkg/atproto/resolver.go index a984037..69d9ae4 100644 --- a/pkg/atproto/resolver.go +++ b/pkg/atproto/resolver.go @@ -8,7 +8,7 @@ import ( ) // ResolveDIDToPDS resolves a DID to its PDS endpoint. -// Uses the shared identity directory with 8h cache TTL. +// Uses the shared identity directory with cache TTL and event-driven invalidation. func ResolveDIDToPDS(ctx context.Context, did string) (string, error) { directory := GetDirectory() didParsed, err := syntax.ParseDID(did) @@ -30,7 +30,7 @@ func ResolveDIDToPDS(ctx context.Context, did string) (string, error) { } // ResolveIdentity resolves an ATProto identifier (handle or DID) to DID, handle, and PDS endpoint. -// Uses the shared identity directory with 8h cache TTL. +// Uses the shared identity directory with cache TTL and event-driven invalidation. // // If the handle is invalid (handle.invalid), it returns the DID as the handle for display purposes. // Returns: did, handle, pdsEndpoint, error @@ -64,7 +64,7 @@ func ResolveIdentity(ctx context.Context, identifier string) (string, string, st } // ResolveHandleToDID resolves a handle or DID to just the DID. -// Uses the shared identity directory with 8h cache TTL. +// Uses the shared identity directory with cache TTL and event-driven invalidation. // This is useful when you only need the DID and don't care about handle/PDS. func ResolveHandleToDID(ctx context.Context, identifier string) (string, error) { directory := GetDirectory() @@ -80,3 +80,21 @@ func ResolveHandleToDID(ctx context.Context, identifier string) (string, error) return ident.DID.String(), nil } + +// InvalidateIdentity purges cached identity data for a DID or handle. +// This should be called when identity changes are detected (e.g., via Jetstream events) +// to ensure the cache is refreshed on the next lookup. +// +// Use cases: +// - Handle changes (identity events from Jetstream) +// - Account deactivation/migration (account events from Jetstream) +// - PDS migrations (deactivation followed by reactivation at new PDS) +func InvalidateIdentity(ctx context.Context, identifier string) error { + directory := GetDirectory() + atID, err := syntax.ParseAtIdentifier(identifier) + if err != nil { + return fmt.Errorf("invalid identifier for cache invalidation: %w", err) + } + + return directory.Purge(ctx, *atID) +} diff --git a/pkg/logging/logger_test.go b/pkg/logging/logger_test.go new file mode 100644 index 0000000..961f181 --- /dev/null +++ b/pkg/logging/logger_test.go @@ -0,0 +1,397 @@ +package logging + +import ( + "bytes" + "log/slog" + "strings" + "testing" +) + +// captureLogOutput runs a function and captures slog output +func captureLogOutput(level string, logFunc func()) string { + var buf bytes.Buffer + + // Save original logger + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + // Parse level + var logLevel slog.Level + switch strings.ToLower(strings.TrimSpace(level)) { + case "debug": + logLevel = slog.LevelDebug + case "info", "": + logLevel = slog.LevelInfo + case "warn", "warning": + logLevel = slog.LevelWarn + case "error": + logLevel = slog.LevelError + default: + logLevel = slog.LevelInfo + } + + // Create logger that writes to buffer + opts := &slog.HandlerOptions{ + Level: logLevel, + } + handler := slog.NewTextHandler(&buf, opts) + slog.SetDefault(slog.New(handler)) + + // Run the function that generates logs + logFunc() + + return buf.String() +} + +func TestInitLogger(t *testing.T) { + // Save original logger to restore after all tests + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + tests := []struct { + name string + level string + shouldLogDebug bool + shouldLogInfo bool + shouldLogWarn bool + shouldLogError bool + }{ + { + name: "debug level logs all", + level: "debug", + shouldLogDebug: true, + shouldLogInfo: true, + shouldLogWarn: true, + shouldLogError: true, + }, + { + name: "info level logs info and above", + level: "info", + shouldLogDebug: false, + shouldLogInfo: true, + shouldLogWarn: true, + shouldLogError: true, + }, + { + name: "warn level logs warn and above", + level: "warn", + shouldLogDebug: false, + shouldLogInfo: false, + shouldLogWarn: true, + shouldLogError: true, + }, + { + name: "error level logs only errors", + level: "error", + shouldLogDebug: false, + shouldLogInfo: false, + shouldLogWarn: false, + shouldLogError: true, + }, + { + name: "empty level defaults to info", + level: "", + shouldLogDebug: false, + shouldLogInfo: true, + shouldLogWarn: true, + shouldLogError: true, + }, + { + name: "invalid level defaults to info", + level: "invalid", + shouldLogDebug: false, + shouldLogInfo: true, + shouldLogWarn: true, + shouldLogError: true, + }, + { + name: "case insensitive - DEBUG", + level: "DEBUG", + shouldLogDebug: true, + shouldLogInfo: true, + shouldLogWarn: true, + shouldLogError: true, + }, + { + name: "case insensitive - WaRn", + level: "WaRn", + shouldLogDebug: false, + shouldLogInfo: false, + shouldLogWarn: true, + shouldLogError: true, + }, + { + name: "whitespace handling - ' info '", + level: " info ", + shouldLogDebug: false, + shouldLogInfo: true, + shouldLogWarn: true, + shouldLogError: true, + }, + { + name: "warning alias for warn", + level: "warning", + shouldLogDebug: false, + shouldLogInfo: false, + shouldLogWarn: true, + shouldLogError: true, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + output := captureLogOutput(tt.level, func() { + slog.Debug("debug message") + slog.Info("info message") + slog.Warn("warn message") + slog.Error("error message") + }) + + // Check debug + if tt.shouldLogDebug { + if !strings.Contains(output, "debug message") { + t.Errorf("Expected debug message to be logged") + } + } else { + if strings.Contains(output, "debug message") { + t.Errorf("Did not expect debug message to be logged") + } + } + + // Check info + if tt.shouldLogInfo { + if !strings.Contains(output, "info message") { + t.Errorf("Expected info message to be logged") + } + } else { + if strings.Contains(output, "info message") { + t.Errorf("Did not expect info message to be logged") + } + } + + // Check warn + if tt.shouldLogWarn { + if !strings.Contains(output, "warn message") { + t.Errorf("Expected warn message to be logged") + } + } else { + if strings.Contains(output, "warn message") { + t.Errorf("Did not expect warn message to be logged") + } + } + + // Check error + if tt.shouldLogError { + if !strings.Contains(output, "error message") { + t.Errorf("Expected error message to be logged") + } + } else { + if strings.Contains(output, "error message") { + t.Errorf("Did not expect error message to be logged") + } + } + }) + } +} + +func TestInitLogger_LogLevels(t *testing.T) { + // Save original logger + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + // Test that InitLogger actually calls slog.SetDefault + InitLogger("debug") + + // Create a buffer to capture output + var buf bytes.Buffer + handler := slog.NewTextHandler(&buf, &slog.HandlerOptions{ + Level: slog.LevelDebug, + }) + slog.SetDefault(slog.New(handler)) + + // Log at debug level + slog.Debug("test debug message") + + // Verify output contains the message + if !strings.Contains(buf.String(), "test debug message") { + t.Error("Debug message not logged after InitLogger") + } +} + +func TestSetupTestLogger(t *testing.T) { + // Save original logger + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + // Test 1: SetupTestLogger suppresses INFO and DEBUG + cleanup := SetupTestLogger() + + // Create a buffer to capture what SHOULD be discarded + // (but we can't really test io.Discard directly, so we'll test behavior) + + // Log at different levels - since it's set to WARN, debug/info should be suppressed + // We can't capture io.Discard output, but we can verify the logger is configured correctly + logger := slog.Default() + + // Verify handler is configured to discard + if logger == nil { + t.Error("Expected logger to be set") + } + + // Test 2: Cleanup restores original logger + cleanup() + + if slog.Default() != originalLogger { + t.Error("Expected cleanup to restore original logger") + } +} + +func TestSetupTestLogger_LevelFiltering(t *testing.T) { + // Save original logger + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + // Setup test logger (WARN level, io.Discard) + cleanup := SetupTestLogger() + defer cleanup() + + // Replace the handler output with a buffer so we can test + // (This is a bit of a workaround since the real SetupTestLogger uses io.Discard) + var buf bytes.Buffer + handler := slog.NewTextHandler(&buf, &slog.HandlerOptions{ + Level: slog.LevelWarn, + }) + slog.SetDefault(slog.New(handler)) + + // Log at different levels + slog.Debug("debug message") + slog.Info("info message") + slog.Warn("warn message") + slog.Error("error message") + + output := buf.String() + + // Debug and Info should NOT be in output (filtered by WARN level) + if strings.Contains(output, "debug message") { + t.Error("Debug message should be filtered out at WARN level") + } + if strings.Contains(output, "info message") { + t.Error("Info message should be filtered out at WARN level") + } + + // Warn and Error SHOULD be in output + if !strings.Contains(output, "warn message") { + t.Error("Warn message should be logged at WARN level") + } + if !strings.Contains(output, "error message") { + t.Error("Error message should be logged at WARN level") + } +} + +func TestSetupTestLogger_UsageWithTCleanup(t *testing.T) { + // This test demonstrates the intended usage pattern + originalLogger := slog.Default() + + // Simulate using SetupTestLogger in a test + cleanup := SetupTestLogger() + t.Cleanup(cleanup) + + // Logger should be different now + if slog.Default() == originalLogger { + t.Error("Expected logger to be changed after SetupTestLogger") + } + + // When test ends, t.Cleanup will run and restore the logger + // We can't directly test this since it happens after the test function returns, + // but we're verifying the pattern works +} + +func TestSetupTestLogger_MultipleCallsIndependent(t *testing.T) { + // Save original logger + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + // First call + cleanup1 := SetupTestLogger() + logger1 := slog.Default() + + // Second call + cleanup2 := SetupTestLogger() + logger2 := slog.Default() + + // Loggers might be different instances + if logger1 == nil || logger2 == nil { + t.Error("Expected loggers to be set") + } + + // Cleanup in reverse order (like defer) + cleanup2() + cleanup1() +} + +func TestInitLogger_OutputFormat(t *testing.T) { + // Save original logger + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + var buf bytes.Buffer + + // Configure logger with buffer + opts := &slog.HandlerOptions{ + Level: slog.LevelInfo, + } + handler := slog.NewTextHandler(&buf, opts) + slog.SetDefault(slog.New(handler)) + + // Log a message + slog.Info("test message", "key", "value") + + output := buf.String() + + // Verify text format (not JSON) + if !strings.Contains(output, "test message") { + t.Error("Expected message in output") + } + if !strings.Contains(output, "key=value") { + t.Error("Expected key=value in text format") + } + // Should NOT be JSON + if strings.HasPrefix(output, "{") { + t.Error("Expected text format, not JSON") + } +} + +func BenchmarkInitLogger(b *testing.B) { + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + b.ResetTimer() + for i := 0; i < b.N; i++ { + InitLogger("info") + } +} + +func BenchmarkSetupTestLogger(b *testing.B) { + originalLogger := slog.Default() + defer slog.SetDefault(originalLogger) + + b.ResetTimer() + for i := 0; i < b.N; i++ { + cleanup := SetupTestLogger() + cleanup() + } +} + +// Example test showing how to use SetupTestLogger +func ExampleSetupTestLogger() { + // In a test function: + cleanup := SetupTestLogger() + defer cleanup() + + // Now logs at DEBUG and INFO are suppressed + slog.Debug("This won't show") + slog.Info("This won't show either") + slog.Warn("This WILL show") + + // cleanup() will restore the original logger when defer runs +}