dance-lessons-coach/pkg/bdd/testserver/STATE_TRACER_README.md

BDD State Tracer

Overview

The BDD State Tracer is a debugging tool that logs scenario execution, database operations, and state modifications to a file in $TMPDIR for analysis of test execution order and state pollution issues.

Purpose

Why Tracing Was Added

During multi-iteration BDD test runs with ./scripts/validate-test-suite.sh, intermittent failures occurred that were difficult to diagnose:

• Tests passed when run individually
• Tests failed when run together in the validation script
• Patterns suggested database state pollution between scenarios across different feature packages

The tracer was created to answer key questions:

1. Execution Order: Which scenarios run in which order?
2. State Modifications: What database writes/cleanups occur and when?
3. Overlap Detection: Are scenarios running in parallel (causing race conditions)?
4. Isolation Verification: Is schema isolation working as expected?

Key Findings from Tracing

1. Sequential Execution: Each feature package runs in a separate process (separate PIDs), but scenarios within each feature run sequentially
2. Shared Database: All processes share the same PostgreSQL database connection
3. Schema Isolation Status: When BDD_SCHEMA_ISOLATION=false (default in validate script), all scenarios share the public schema
4. Cleanup Operations: Database cleanup (CleanupDatabase) runs after each scenario, deleting all test data from all tables
5. In-Memory State: JWT secrets are stored in-memory only, not in database - schema isolation doesn't prevent JWT secret pollution

Example Trace Output

2026-04-11T10:10:53.032156 | auth            | User registration               | SCENARIO_START   | 
2026-04-11T10:10:53.146438 | auth            | User registration               | SCENARIO_END     | PASSED
2026-04-11T10:10:53.152398 | auth            | User registration               | JWT_RESET        | ok
2026-04-11T10:10:53.162357 | auth            | Failed authentication          | SCENARIO_START   | 
2026-04-11T10:10:53.268273 | auth            | Failed authentication          | SCENARIO_END     | PASSED

Usage

Enable Tracing

Set the environment variable BDD_TRACE_STATE=1 before running tests:

# Single run with tracing
BDD_TRACE_STATE=1 go test ./features/auth -v

# Validation script with tracing
BDD_TRACE_STATE=1 ./scripts/validate-test-suite.sh 1

# Multiple runs with tracing
BDD_TRACE_STATE=1 ./scripts/validate-test-suite.sh 5

Trace File Location

Trace files are written to $TMPDIR (typically /var/folders/.../T/ on macOS or /tmp on Linux):

# Find trace files
ls -la $TMPDIR/bdd-state-trace-*.log

# View a trace file
cat $TMPDIR/bdd-state-trace-20260411-101053-12345.log

Trace File Format

TIMESTAMP | FEATURE          | SCENARIO                              | ACTION           | DETAILS
2026-04-11T10:10:53.032156 | auth            | User registration               | SCENARIO_START   | 
2026-04-11T10:10:53.146438 | auth            | User registration               | SCENARIO_END     | PASSED
2026-04-11T10:10:53.152398 | auth            | User registration               | JWT_RESET        | ok
2026-04-11T10:10:53.162357 | auth            | User registration               | DB_CLEANUP       | all_tables

Columns:

• TIMESTAMP: ISO 8601 format with microseconds
• FEATURE: Feature name from FEATURE environment variable
• SCENARIO: Scenario name (includes URI for disambiguation)
• ACTION: Type of action (see below)
• DETAILS: Additional context

Action Types:

• SCENARIO_START - Scenario execution begins
• SCENARIO_END - Scenario execution completes (PASSED or FAILED)
• DB_CLEANUP - Database cleanup operation
• DB_SELECT - Database read operation
• JWT_RESET - JWT secrets reset to initial state
• DB_INSERT/UPDATE/DELETE - Database write operations (future)
• SCHEMA_* - Schema isolation operations (future)
• TX_* - Transaction boundary operations (future)

Implementation

Architecture

The state tracer uses a simple file-based approach:

1. Per-Process Tracing: Each go test process creates its own trace file with unique filename based on timestamp and PID
2. Immediate Flush: Each trace line is flushed immediately to disk using Sync() to prevent data loss
3. No Dependencies: Uses only standard library (os, fmt, time, path/filepath)
4. Singleton Pattern: Package-level functions for easy usage across the codebase

Files

• pkg/bdd/testserver/state_tracer.go - Core tracing functions
• pkg/bdd/suite.go - Integration with godog Before/After scenario hooks

Key Functions

// Package-level functions (called from anywhere)
TraceStateScenarioStart(feature, scenario string)
TraceStateScenarioEnd(feature, scenario string, err error)
TraceStateDBCleanup(feature, scenario, table string)
TraceStateJWTSecretOperation(feature, scenario, operation, details string)
TraceStateSchemaIsolation(feature, scenario, operation, details string)
TraceStateTransaction(feature, scenario, action, details string)
TraceStateDBRead(feature, scenario, table, details string)

Limitations

Current Limitations

1. Per-Process Files: Each go test process creates its own file, making correlation across processes manual
2. No Database Write Tracing: Currently only traces cleanup, not individual INSERT/UPDATE/DELETE operations
3. No API Call Tracing: Doesn't trace HTTP requests made during scenarios
4. No Timing Analysis: Doesn't measure duration between operations automatically
5. No Schema Name in Trace: When schema isolation is enabled, doesn't show which schema is active
6. File Rotation: No automatic cleanup of old trace files

Known Issues

1. PID-based filenames: If multiple runs happen in the same second, filenames could collide
2. Large file sizes: High-volume tracing could create large files (mitigated by per-run files)
3. No header/footer: Trace files start immediately with data, no metadata about the run

Future Enhancements

Priority 1: Process Correlation

• Add a unique run ID that can be passed across all processes
• Include process start/end markers to show process lifecycle
• Add parent PID tracking to show process hierarchy

Priority 2: Database Operation Tracing

• Add tracing for all database writes (INSERT, UPDATE, DELETE)
• Include query text and affected rows
• Trace transaction boundaries with IDs
• Add schema name to all database operations when isolation is enabled

Priority 3: API Call Tracing

• Trace all HTTP requests made during scenarios
• Include request method, path, status code, and duration
• Mark requests that modify state (POST, PUT, DELETE vs GET)

Priority 4: Analysis Tools

• Create a bdd-trace-analyzer tool to:
  • Merge trace files from all processes in correct order
  • Detect overlapping scenarios (parallel execution)
  • Identify database state pollution patterns
  • Generate visualization of scenario execution timeline
  • Flag potential race conditions

Priority 5: Improved Output

• Add trace file header with metadata (run ID, start time, config, etc.)
• Color-coded output for different action types
• JSON output option for programmatic analysis
• Trace level filtering (DEBUG, INFO, WARN, ERROR)

Priority 6: Performance Optimization

• Batch writes instead of per-line flush (with configurable flush interval)
• Compress old trace files
• Automatic cleanup of old files

Analysis Use Cases

Detecting State Pollution

Look for patterns like:

PID 1234 | auth | Scenario A | DB_CLEANUP | all_tables
PID 5678 | greet | Scenario B | SCENARIO_START |
# ^ Scenario B starts AFTER auth cleanup - potential issue

Detecting Parallel Execution

Check if timestamps overlap:

PID 1234 | 10:10:53.032 | auth | Scenario A | SCENARIO_START
PID 5678 | 10:10:53.035 | greet | Scenario B | SCENARIO_START
# ^ Both started within 3ms - likely parallel

Verifying Schema Isolation

Check that each scenario gets its own schema:

PID 1234 | auth | Scenario A | SCHEMA_CREATE | test_a1b2c3d4
PID 1234 | auth | Scenario B | SCHEMA_CREATE | test_e5f6g7h8
# ^ Different schemas for different scenarios - good

Troubleshooting

Tracing Not Working

1. Verify BDD_TRACE_STATE=1 is set:

   echo $BDD_TRACE_STATE
   

2. Check if trace files are being created:

   ls -la $TMPDIR/bdd-state-trace-*.log
   

3. Verify the testserver package is being used (tracing is integrated there)

No Trace Files Found

• Tracing only works when BDD_TRACE_STATE=1 is set before the test process starts
• Each go test process creates its own file - if tests pass quickly, files may be short
• Files are created in $TMPDIR which defaults to /tmp on Linux and a temp folder on macOS

Trace Files Too Large

• Tracing every operation can generate large files
• Consider filtering to specific scenarios:

  # Run only failing scenarios with tracing
  BDD_TRACE_STATE=1 go test ./features/auth -v -run "TestAuthBDD/Password_reset"
  

Related Files

• pkg/bdd/suite.go - Godog test suite initialization with tracing hooks
• pkg/bdd/testserver/server.go - Test server with tracing integration
• scripts/validate-test-suite.sh - Test validation script