add identity invalidation to logstream. refresh avatar urls on login

This commit is contained in:
Evan Jarrett
2025-10-28 10:12:34 -05:00
parent e62ebdaa53
commit 93b1d0d4ba
9 changed files with 821 additions and 43 deletions
+19 -7
View File
@@ -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
+9
View File
@@ -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(`
+75
View File
@@ -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)
}
}
}
+75 -1
View File
@@ -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
}
+142
View File
@@ -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")
}
}
+75 -27
View File
@@ -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"`
+8 -5
View File
@@ -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
+21 -3
View File
@@ -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)
}
+397
View File
@@ -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
}