package backgroundtask import ( "bytes" "context" "errors" "log/slog" "strings" "sync" "sync/atomic" "testing" "time" ) // TestStats_WorkCycles verifies work cycle counting func TestStats_WorkCycles(t *testing.T) { config := NewTestConfigMap() runner, err := Initialize( config, slog.Default(), FastWorkFunc, WithInterval(50*time.Millisecond), ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } // Check initial stats stats := runner.Stats() if stats.WorkCycles() != 0 { t.Errorf("Expected 0 initial work cycles, got %d", stats.WorkCycles()) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } }() // Wait for some work cycles from ticker if !WaitForWorkCycles(runner, 3, 300*time.Millisecond) { t.Fatal("Expected at least 3 work cycles from ticker") } tickerCycles := runner.Stats().WorkCycles() // Add some signaled work for i := 0; i < 5; i++ { if err := runner.Signal(); err != nil { t.Fatalf("Signal %d failed: %v", i, err) } } // Wait for signal work to complete time.Sleep(100 * time.Millisecond) finalStats := runner.Stats() finalCycles := finalStats.WorkCycles() // Should have more cycles after signals if finalCycles <= tickerCycles { t.Errorf("Expected work cycles to increase after signals: before=%d, after=%d", tickerCycles, finalCycles) } // Should have at least the ticker cycles if finalCycles < 3 { t.Errorf("Expected at least 3 work cycles, got %d", finalCycles) } } // TestStats_Timestamps verifies last start/finish timestamp tracking func TestStats_Timestamps(t *testing.T) { config := NewTestConfigMap() testConfig, _ := GetTestConfig(config) testConfig.WorkDuration = 50 * time.Millisecond runner, err := Initialize( config, slog.Default(), TestWorkFunc, WithInterval(1*time.Hour), // Long interval ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } }() // Check initial timestamps (should be zero) stats := runner.Stats() if !stats.LastStart().IsZero() { t.Error("Expected zero LastStart initially") } if !stats.LastFinish().IsZero() { t.Error("Expected zero LastFinish initially") } beforeSignal := time.Now() // Signal work if err := runner.Signal(); err != nil { t.Fatalf("Signal failed: %v", err) } // Wait for work to complete if !WaitForWorkCycles(runner, 1, 200*time.Millisecond) { t.Fatal("Expected work to complete") } afterWork := time.Now() stats = runner.Stats() // Timestamps should be set and reasonable if stats.LastStart().IsZero() { t.Error("Expected LastStart to be set after work") } if stats.LastFinish().IsZero() { t.Error("Expected LastFinish to be set after work") } // Timestamps should be in reasonable range if stats.LastStart().Before(beforeSignal) || stats.LastStart().After(afterWork) { t.Errorf("LastStart timestamp out of range: %v (should be between %v and %v)", stats.LastStart(), beforeSignal, afterWork) } if stats.LastFinish().Before(stats.LastStart()) { t.Error("LastFinish should be after LastStart") } if stats.LastFinish().After(afterWork) { t.Errorf("LastFinish timestamp after expected: %v > %v", stats.LastFinish(), afterWork) } // Duration should be reasonable duration := stats.LastFinish().Sub(stats.LastStart()) if duration < testConfig.WorkDuration/2 || duration > testConfig.WorkDuration*3 { t.Errorf("Work duration seems wrong: %v (expected around %v)", duration, testConfig.WorkDuration) } } // TestStats_ErrorTracking verifies error tracking in stats // //nolint:cyclop // Test function with multiple subtests func TestStats_ErrorTracking(t *testing.T) { t.Run("NoErrorInitially", func(t *testing.T) { config := NewTestConfigMap() runner, err := Initialize( config, slog.Default(), FastWorkFunc, // No error initially WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } }() // Signal successful work if err := runner.Signal(); err != nil { t.Fatalf("Signal failed: %v", err) } if !WaitForWorkCycles(runner, 1, 200*time.Millisecond) { t.Fatal("Expected work to complete") } // Should have no error stats := runner.Stats() if stats.LastErr() != nil { t.Errorf("Expected no error initially, got: %v", stats.LastErr()) } }) t.Run("ErrorRecording", func(t *testing.T) { config := NewTestConfigMap() errorWorkFunc := func(ctx context.Context, logger *slog.Logger, config map[string]any) error { return errors.New("test error message") } errorRunner, err := Initialize( config, slog.Default(), errorWorkFunc, WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize error runner: %v", err) } if err := errorRunner.Run(); err != nil { t.Fatalf("Failed to start error runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := errorRunner.Shutdown(ctx); err != nil { t.Errorf("Error runner shutdown error: %v", err) } }() // Signal error work if err := errorRunner.Signal(); err != nil { t.Fatalf("Error runner signal failed: %v", err) } if !WaitForWorkCycles(errorRunner, 1, 200*time.Millisecond) { t.Fatal("Expected error work to complete") } // Should have error recorded errorStats := errorRunner.Stats() if errorStats.LastErr() == nil { t.Error("Expected error to be recorded") } else if errorStats.LastErr().Error() != "test error message" { t.Errorf("Expected 'test error message', got: %v", errorStats.LastErr()) } }) t.Run("ErrorClearing", func(t *testing.T) { config := NewTestConfigMap() successWorkFunc := func(ctx context.Context, logger *slog.Logger, config map[string]any) error { return nil } successRunner, err := Initialize( config, slog.Default(), successWorkFunc, WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize success runner: %v", err) } // Set an initial error successRunner.stats.setLastErr(errors.New("initial error")) if err := successRunner.Run(); err != nil { t.Fatalf("Failed to start success runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := successRunner.Shutdown(ctx); err != nil { t.Errorf("Success runner shutdown error: %v", err) } }() if err := successRunner.Signal(); err != nil { t.Fatalf("Success runner signal failed: %v", err) } if !WaitForWorkCycles(successRunner, 1, 200*time.Millisecond) { t.Fatal("Expected success work to complete") } // Error should be cleared finalStats := successRunner.Stats() if finalStats.LastErr() != nil { t.Errorf("Expected error to be cleared after successful work, got: %v", finalStats.LastErr()) } }) } // TestStats_ThreadSafety verifies thread-safe access to stats func TestStats_ThreadSafety(t *testing.T) { config := NewTestConfigMap() runner, err := Initialize( config, slog.Default(), FastWorkFunc, WithInterval(10*time.Millisecond), // Fast interval ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } var wg sync.WaitGroup const numReaders = 10 const numWrites = 100 var errors int64 // Start multiple readers for i := 0; i < numReaders; i++ { wg.Add(1) go func() { defer wg.Done() for j := 0; j < numWrites; j++ { stats := runner.Stats() // Access all stats methods concurrently _ = stats.WorkCycles() _ = stats.LastStart() _ = stats.LastFinish() _ = stats.LastErr() _ = stats.MaxConcurrent() _ = stats.CurrentConcurrent() time.Sleep(1 * time.Millisecond) } }() } // Also send signals to trigger work and stats updates wg.Add(1) go func() { defer wg.Done() for i := 0; i < 50; i++ { if err := runner.Signal(); err != nil && err != ErrStopped { atomic.AddInt64(&errors, 1) } time.Sleep(5 * time.Millisecond) } }() wg.Wait() ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } // Check that we didn't get any signal errors (except possibly ErrStopped at the end) if errors > 5 { // Allow a few ErrStopped at shutdown t.Errorf("Too many signal errors during concurrent access: %d", errors) } // Final stats should be consistent finalStats := runner.Stats() if finalStats.WorkCycles() == 0 { t.Error("Expected some work cycles") } if finalStats.CurrentConcurrent() != 0 { t.Errorf("Expected current concurrent to be 0 after shutdown, got %d", finalStats.CurrentConcurrent()) } } // TestStats_MaxConcurrent verifies max concurrent tracking func TestStats_MaxConcurrent(t *testing.T) { config := map[string]any{"test": true} var currentConcurrent int64 var maxObserved int64 // Work function that simulates overlapping work attempts workFunc := func(ctx context.Context, logger *slog.Logger, cfg map[string]any) error { current := atomic.AddInt64(¤tConcurrent, 1) defer atomic.AddInt64(¤tConcurrent, -1) // Track max we observe for { max := atomic.LoadInt64(&maxObserved) if current <= max || atomic.CompareAndSwapInt64(&maxObserved, max, current) { break } } time.Sleep(50 * time.Millisecond) return nil } runner, err := Initialize( config, slog.Default(), workFunc, WithInterval(25*time.Millisecond), // Faster than work duration ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } // Initial max concurrent should be 0 stats := runner.Stats() if stats.MaxConcurrent() != 0 { t.Errorf("Expected initial max concurrent to be 0, got %d", stats.MaxConcurrent()) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } // Let it run with fast ticking and send some signals time.Sleep(100 * time.Millisecond) for i := 0; i < 10; i++ { if err := runner.Signal(); err != nil { t.Fatalf("Signal failed: %v", err) } } time.Sleep(200 * time.Millisecond) ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Fatalf("Shutdown failed: %v", err) } // Max concurrent should be 1 (no actual concurrency in background task) finalStats := runner.Stats() if finalStats.MaxConcurrent() != 1 { t.Errorf("Expected max concurrent to be 1, got %d", finalStats.MaxConcurrent()) } // Our test tracking should also show max of 1 if maxObserved != 1 { t.Errorf("Expected observed max concurrent to be 1, got %d", maxObserved) } // Current should be 0 after shutdown if finalStats.CurrentConcurrent() != 0 { t.Errorf("Expected current concurrent to be 0 after shutdown, got %d", finalStats.CurrentConcurrent()) } } // TestStats_Reset verifies stats reset functionality func TestStats_Reset(t *testing.T) { config := NewTestConfigMap() runner, err := Initialize( config, slog.Default(), ErrorWorkFunc, // Will set error WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } }() // Do some work to populate stats if err := runner.Signal(); err != nil { t.Fatalf("Signal failed: %v", err) } if !WaitForWorkCycles(runner, 1, 200*time.Millisecond) { t.Fatal("Expected work to complete") } // Verify stats are populated stats := runner.Stats() if stats.WorkCycles() == 0 { t.Fatal("Expected work cycles to be > 0") } if stats.LastErr() == nil { t.Fatal("Expected error to be set") } if stats.LastStart().IsZero() { t.Fatal("Expected LastStart to be set") } if stats.MaxConcurrent() == 0 { t.Fatal("Expected MaxConcurrent to be > 0") } // Reset stats runner.stats.Reset() // Verify stats are cleared resetStats := runner.Stats() if resetStats.WorkCycles() != 0 { t.Errorf("Expected work cycles to be 0 after reset, got %d", resetStats.WorkCycles()) } if resetStats.LastErr() != nil { t.Errorf("Expected error to be nil after reset, got %v", resetStats.LastErr()) } if !resetStats.LastStart().IsZero() { t.Error("Expected LastStart to be zero after reset") } if !resetStats.LastFinish().IsZero() { t.Error("Expected LastFinish to be zero after reset") } if resetStats.MaxConcurrent() != 0 { t.Errorf("Expected MaxConcurrent to be 0 after reset, got %d", resetStats.MaxConcurrent()) } if resetStats.CurrentConcurrent() != 0 { t.Errorf("Expected CurrentConcurrent to be 0 after reset, got %d", resetStats.CurrentConcurrent()) } } // TestStats_ConsistentStateAfterWork verifies stats are consistent after work execution func TestStats_ConsistentStateAfterWork(t *testing.T) { config := NewTestConfigMap() testConfig, _ := GetTestConfig(config) runner, err := Initialize( config, slog.Default(), TestWorkFunc, WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } }() const numCycles = 5 for i := 0; i < numCycles; i++ { if err := runner.Signal(); err != nil { t.Fatalf("Signal %d failed: %v", i, err) } // Small delay between signals to ensure they're processed time.Sleep(10 * time.Millisecond) } // Wait for all work to complete if !WaitForWorkCycles(runner, int64(numCycles), 2*time.Second) { t.Fatalf("Expected all work cycles to complete, got %d", runner.Stats().WorkCycles()) } // Verify consistency stats := runner.Stats() // Work cycles should match what we triggered if stats.WorkCycles() != int64(numCycles) { t.Errorf("Expected %d work cycles, got %d", numCycles, stats.WorkCycles()) } // Counter should also match if testConfig.Counter.Load() != int64(numCycles) { t.Errorf("Expected counter to be %d, got %d", numCycles, testConfig.Counter.Load()) } // Should have no current concurrent work if stats.CurrentConcurrent() != 0 { t.Errorf("Expected current concurrent to be 0, got %d", stats.CurrentConcurrent()) } // Max concurrent should be 1 if stats.MaxConcurrent() != 1 { t.Errorf("Expected max concurrent to be 1, got %d", stats.MaxConcurrent()) } // Should have valid timestamps if stats.LastStart().IsZero() || stats.LastFinish().IsZero() { t.Error("Expected valid last start/finish timestamps") } if stats.LastFinish().Before(stats.LastStart()) { t.Error("LastFinish should not be before LastStart") } } // TestStats_Print verifies the Print function output // //nolint:cyclop // Multiple subtests with setup/teardown logic func TestStats_Print(t *testing.T) { t.Run("EmptyStats", func(t *testing.T) { config := NewTestConfigMap() runner, err := Initialize( config, slog.Default(), TestWorkFunc, WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } // Print stats before any work var buf bytes.Buffer runner.Stats().Print(&buf) output := buf.String() // Verify key elements are present if !strings.Contains(output, "Background Task Runner Stats") { t.Error("Expected title in output") } if !strings.Contains(output, "Work Cycles: 0") { t.Error("Expected 0 work cycles") } if !strings.Contains(output, "Last Start: Never") { t.Error("Expected 'Never' for last start") } if !strings.Contains(output, "Last Error: None") { t.Error("Expected 'None' for last error") } t.Logf("Empty stats output:\n%s", output) }) t.Run("StatsAfterWork", func(t *testing.T) { config := NewTestConfigMap() runner, err := Initialize( config, slog.Default(), TestWorkFunc, WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } }() // Trigger work if err := runner.Signal(); err != nil { t.Fatalf("Signal failed: %v", err) } if !WaitForWorkCycles(runner, 1, 500*time.Millisecond) { t.Fatal("Expected work to complete") } // Print stats after work var buf bytes.Buffer runner.Stats().Print(&buf) output := buf.String() // Verify stats reflect work if !strings.Contains(output, "Work Cycles: 1") { t.Error("Expected 1 work cycle") } if strings.Contains(output, "Last Start: Never") { t.Error("Expected valid last start time") } if strings.Contains(output, "Last Finish: Never") { t.Error("Expected valid last finish time") } if !strings.Contains(output, "Duration:") { t.Error("Expected duration to be shown") } t.Logf("Stats after work output:\n%s", output) }) t.Run("StatsWithError", func(t *testing.T) { config := NewTestConfigMap() runner, err := Initialize( config, slog.Default(), ErrorWorkFunc, WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } }() // Trigger work that will error if err := runner.Signal(); err != nil { t.Fatalf("Signal failed: %v", err) } if !WaitForWorkCycles(runner, 1, 500*time.Millisecond) { t.Fatal("Expected work to complete") } // Print stats with error var buf bytes.Buffer runner.Stats().Print(&buf) output := buf.String() // Verify error is shown if !strings.Contains(output, "Last Error: test error") { t.Error("Expected error to be shown in output") } t.Logf("Stats with error output:\n%s", output) }) t.Run("LongErrorTruncation", func(t *testing.T) { config := NewTestConfigMap() // Create work function with long error message longErrorFunc := func(ctx context.Context, logger *slog.Logger, cfg map[string]any) error { return errors.New("this is a very long error message that should be truncated in the pretty print output") } runner, err := Initialize( config, slog.Default(), longErrorFunc, WithInterval(1*time.Hour), ) if err != nil { t.Fatalf("Failed to initialize runner: %v", err) } if err := runner.Run(); err != nil { t.Fatalf("Failed to start runner: %v", err) } defer func() { ctx, cancel := context.WithTimeout(t.Context(), 2*time.Second) defer cancel() if err := runner.Shutdown(ctx); err != nil { t.Errorf("Shutdown error: %v", err) } }() // Trigger work that will error if err := runner.Signal(); err != nil { t.Fatalf("Signal failed: %v", err) } if !WaitForWorkCycles(runner, 1, 500*time.Millisecond) { t.Fatal("Expected work to complete") } // Print stats with long error var buf bytes.Buffer runner.Stats().Print(&buf) output := buf.String() // Verify error is truncated with ellipsis if !strings.Contains(output, "...") { t.Error("Expected long error to be truncated with ellipsis") } t.Logf("Stats with truncated error output:\n%s", output) }) }