foxhunt/docs/testing/WAVE4_DEBUGGING_GUIDE.md

# Wave 4 Test Failure Debugging Guide

**Version**: 1.0
**Date**: 2025-10-22
**Author**: Agent W4-5 (Test Documentation Specialist)

---

## Quick Reference

```bash
# Enable backtrace
RUST_BACKTRACE=1 cargo test failing_test

# Enable full backtrace
RUST_BACKTRACE=full cargo test failing_test

# Enable logging
RUST_LOG=debug cargo test failing_test
RUST_LOG=trading_engine=trace cargo test failing_test

# Run single test
cargo test --lib test_specific_failure -- --nocapture

# Run with debugger
cargo test --no-run failing_test
gdb target/debug/deps/crate_name-HASH

# Check database state
psql postgresql://foxhunt:foxhunt_dev_password@localhost:5432/foxhunt
SELECT * FROM orders WHERE status = 'FAILED';
```

---

## 1. Common Test Failures & Fixes

### Failure: Connection Refused (os error 111)

**Symptom**:
```
thread 'integration::test_grpc_client' panicked at 'Connection refused (os error 111)'
```

**Root Cause**: Docker services not running

**Fix**:
```bash
# Start services
docker-compose up -d

# Verify health
docker-compose ps
# Expected: postgres, redis, vault all "healthy"

# Check logs if unhealthy
docker-compose logs postgres
docker-compose logs redis
```

### Failure: Relation Does Not Exist

**Symptom**:
```
thread 'test_order_insert' panicked at 'relation "orders" does not exist'
```

**Root Cause**: Database migrations not applied

**Fix**:
```bash
# Apply migrations
cargo sqlx migrate run

# Verify migrations
psql postgresql://foxhunt:foxhunt_dev_password@localhost:5432/foxhunt
\dt  # List tables
\d orders  # Describe orders table

# If migrations are corrupted, reset:
docker-compose down -v
docker-compose up -d
cargo sqlx migrate run
```

### Failure: Test Timeout

**Symptom**:
```
test test_async_operation has been running for over 60 seconds
```

**Root Cause**: Deadlock, infinite loop, or missing await

**Debugging**:
```rust
// Add timeout to test
#[tokio::test]
#[timeout(Duration::from_secs(5))]
async fn test_async_operation() {
    // Test code
}

// Or use tokio::time::timeout
tokio::time::timeout(Duration::from_secs(5), async {
    // Async operation
}).await.expect("Timeout waiting for operation");
```

**Common Causes**:
- Missing `.await` on async function
- Deadlock in mutex/RwLock
- Infinite loop in retry logic
- gRPC client waiting for unavailable service

### Failure: Assertion Failed

**Symptom**:
```
thread 'test_order_matching' panicked at 'assertion failed: `(left == right)`
  left: `100`,
 right: `99`'
```

**Debugging**:
```rust
// Add detailed assertion messages
assert_eq!(filled_quantity, expected_quantity,
    "Order fill quantity mismatch: order_id={}, side={:?}, price={}",
    order_id, order.side, order.price
);

// Use assert! with custom message for complex conditions
assert!(
    filled_quantity <= order.quantity,
    "Filled quantity {} exceeds order quantity {}",
    filled_quantity, order.quantity
);

// Use approx for floating point comparisons
use approx::assert_relative_eq;
assert_relative_eq!(actual_price, expected_price, epsilon = 0.01);
```

### Failure: Panic in Drop

**Symptom**:
```
thread 'test_resource_cleanup' panicked at 'Panic in Drop: connection pool not cleaned up'
```

**Root Cause**: Resource not properly cleaned up

**Fix**:
```rust
// Use Drop guard
struct TestContext {
    db_pool: PgPool,
}

impl Drop for TestContext {
    fn drop(&mut self) {
        // Cleanup
        let _ = self.db_pool.close();  // Ignore errors in Drop
    }
}

// Or use scopeguard
use scopeguard::defer;

#[tokio::test]
async fn test_with_cleanup() {
    let pool = create_pool().await;
    defer! {
        let _ = pool.close();
    }
    // Test code
}
```

---

## 2. Database State Inspection

### Check Order State

```sql
-- View all orders
SELECT * FROM orders ORDER BY created_at DESC LIMIT 10;

-- Check failed orders
SELECT * FROM orders WHERE status = 'FAILED';

-- Check order fills
SELECT o.order_id, o.symbol, o.quantity,
       SUM(f.quantity) as filled_quantity
FROM orders o
LEFT JOIN order_fills f ON o.order_id = f.order_id
GROUP BY o.order_id, o.symbol, o.quantity;

-- Check positions
SELECT * FROM positions WHERE symbol = 'ES.FUT';

-- Check regime state (Wave D)
SELECT * FROM regime_states ORDER BY timestamp DESC LIMIT 1;
SELECT * FROM regime_transitions ORDER BY timestamp DESC LIMIT 10;
```

### Check Database Locks

```sql
-- View active locks
SELECT pid, usename, pg_blocking_pids(pid) as blocked_by, query
FROM pg_stat_activity
WHERE cardinality(pg_blocking_pids(pid)) > 0;

-- Kill blocking query
SELECT pg_terminate_backend(pid) FROM pg_stat_activity WHERE pid = 12345;
```

### Reset Test Database

```bash
# Drop and recreate
psql postgresql://foxhunt:foxhunt_dev_password@localhost:5432/postgres
DROP DATABASE IF EXISTS foxhunt_test;
CREATE DATABASE foxhunt_test;
\c foxhunt_test
# Run migrations
cargo sqlx migrate run --database-url postgresql://foxhunt:foxhunt_dev_password@localhost:5432/foxhunt_test
```

---

## 3. gRPC Request/Response Debugging

### Enable gRPC Logging

```bash
# Enable tonic logs
RUST_LOG=tonic=debug,tower=debug cargo test test_grpc_streaming
```

### Inspect gRPC Messages

```rust
use tonic::{Request, Response, Status};
use tracing::info;

#[tonic::async_trait]
impl TradingService for MyTradingService {
    async fn submit_order(
        &self,
        request: Request<SubmitOrderRequest>,
    ) -> Result<Response<SubmitOrderResponse>, Status> {
        // Log incoming request
        info!("Received request: {:?}", request.get_ref());

        let result = self.process_order(request.into_inner()).await;

        // Log outgoing response
        info!("Sending response: {:?}", result);

        result.map(Response::new)
    }
}
```

### Test gRPC Client Directly

```rust
#[tokio::test]
async fn test_grpc_client_connection() {
    let channel = Channel::from_static("http://localhost:50052")
        .connect()
        .await
        .expect("Failed to connect");

    let mut client = TradingServiceClient::new(channel);

    let request = Request::new(SubmitOrderRequest {
        symbol: "ES.FUT".to_string(),
        side: "BUY".to_string(),
        quantity: 10,
        price: 4500.0,
    });

    match client.submit_order(request).await {
        Ok(response) => println!("Response: {:?}", response.into_inner()),
        Err(e) => panic!("gRPC error: {:?}", e),
    }
}
```

---

## 4. Async Test Debugging

### Common Async Issues

**Issue**: Test hangs indefinitely

**Diagnosis**:
```rust
// Add timeout to all async operations
use tokio::time::{timeout, Duration};

#[tokio::test]
async fn test_async_operation() {
    let result = timeout(Duration::from_secs(5), async {
        // Async operation that might hang
        some_async_function().await
    }).await;

    match result {
        Ok(value) => assert_eq!(value, expected),
        Err(_) => panic!("Operation timed out after 5 seconds"),
    }
}
```

**Issue**: Tokio runtime not available

**Fix**:
```rust
// Use #[tokio::test] instead of #[test]
#[tokio::test]
async fn test_async_function() {
    // Async test code
}

// Or explicitly create runtime
#[test]
fn test_with_runtime() {
    let rt = tokio::runtime::Runtime::new().unwrap();
    rt.block_on(async {
        // Async test code
    });
}
```

**Issue**: Task spawned but never awaited

**Fix**:
```rust
// Bad: Task spawned but result ignored
tokio::spawn(async {
    some_async_operation().await;
});

// Good: Await task completion
let handle = tokio::spawn(async {
    some_async_operation().await
});
handle.await.unwrap();
```

---

## 5. Race Condition Debugging

### Detect Race Conditions

```bash
# Run test repeatedly to trigger race
for i in {1..100}; do
    cargo test test_concurrent_access || break
done

# Use thread sanitizer (nightly Rust)
RUSTFLAGS="-Z sanitizer=thread" cargo +nightly test test_concurrent_access
```

### Common Race Patterns

**Race in Shared State**:
```rust
// Bad: Race condition
use std::sync::Arc;

struct Counter {
    value: usize,  // Not atomic!
}

// Good: Use atomic or mutex
use std::sync::atomic::{AtomicUsize, Ordering};

struct Counter {
    value: AtomicUsize,
}

impl Counter {
    fn increment(&self) {
        self.value.fetch_add(1, Ordering::SeqCst);
    }
}
```

**Race in Test Cleanup**:
```rust
// Bad: Cleanup happens before test finishes
#[tokio::test]
async fn test_cleanup_race() {
    let resource = setup_resource().await;
    tokio::spawn(async move {
        use_resource(resource).await;
    });
    // Test ends, resource dropped before spawn completes
}

// Good: Await task completion
#[tokio::test]
async fn test_cleanup_safe() {
    let resource = Arc::new(setup_resource().await);
    let handle = tokio::spawn({
        let resource = resource.clone();
        async move {
            use_resource(resource).await
        }
    });
    handle.await.unwrap();
}
```

---

## 6. Memory Leak Investigation

### Detect Memory Leaks

```bash
# Use valgrind (Linux)
cargo build --bin trading_service
valgrind --leak-check=full target/debug/trading_service

# Use heaptrack (Linux)
heaptrack target/debug/trading_service

# Use instruments (macOS)
instruments -t Leaks target/debug/trading_service
```

### Common Leak Patterns

**Reference Cycles**:
```rust
// Bad: Reference cycle prevents cleanup
struct Node {
    next: Option<Rc<Node>>,
    prev: Option<Rc<Node>>,  // Cycle!
}

// Good: Use Weak for back-references
struct Node {
    next: Option<Rc<Node>>,
    prev: Option<Weak<Node>>,  // No cycle
}
```

**Async Tasks Not Awaited**:
```rust
// Bad: Spawned task never completes
tokio::spawn(async {
    loop {
        tokio::time::sleep(Duration::from_secs(1)).await;
    }
});

// Good: Use timeout or cancellation
let handle = tokio::spawn(async {
    // Task logic
});
tokio::time::timeout(Duration::from_secs(10), handle).await;
```

---

## 7. Test Data Issues

### Stale Test Data

```bash
# Clear test data cache
rm -rf test_data/*.cache
rm -rf test_data/*.db

# Re-download test data
./scripts/download_test_data.sh
```

### Corrupted Test Data

```bash
# Verify Parquet files
parquet-tools meta test_data/ES_FUT_180d.parquet
parquet-tools schema test_data/ES_FUT_180d.parquet

# Verify DBN files
databento inspect test_data/ES.FUT.dbn
```

---

## 8. CI/CD Test Failures

### GitHub Actions Debugging

```yaml
# Add debug logs to workflow
- name: Run tests with debug logs
  run: RUST_LOG=debug cargo test --workspace
  env:
    RUST_BACKTRACE: full
```

### Download CI Artifacts

```bash
# Download test logs from GitHub Actions
gh run download <run-id>
cat test-logs/cargo-test.log
```

---

## 9. Performance Test Failures

### Benchmark Regression

```bash
# Compare benchmarks
cargo bench --bench order_matching_latency -- --save-baseline before
# Make changes
cargo bench --bench order_matching_latency -- --baseline before
```

### Profiling Slow Tests

```bash
# Use flamegraph
cargo install flamegraph
cargo flamegraph --test integration_slow_test

# Use perf (Linux)
perf record --call-graph=dwarf cargo test integration_slow_test
perf report
```

---

**Last Updated**: 2025-10-22