Files
2025-08-12 06:37:16 -07:00

787 lines
20 KiB
Go

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(&currentConcurrent, 1)
defer atomic.AddInt64(&currentConcurrent, -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)
})
}