Trace Lifecycle

This page covers the complete trace lifecycle, including the race condition problem and the hybrid linking solution.

The Complete Flow

Timeline for Fast Test (< 5 seconds)

T=0ms     Test starts
T=2000ms  Test completes → create test_result
T=2010ms  Linking attempt #1 → Finds 0 traces (not exported yet)
T=5000ms  BatchSpanProcessor exports spans → backend receives
T=5015ms  Spans stored in database
T=5020ms  post_ingest_link dispatched → linking attempt #2 finds test_result
T=5030ms  Enrichment chain dispatched (Celery)
T=5080ms  Enrichment cached
T=5090ms  User queries trace → 10ms (cached)

Total: ~5 seconds from test start to queryable enriched trace

Key Phases

The Race Condition Problem

The Issue

OpenTelemetry’s BatchSpanProcessor batches spans and exports every 5 seconds. This creates unpredictable timing:

Fast Tests (< 5s): Test result created BEFORE spans exported

T=2s: test_result created
T=5s: spans exported ← Too late for linking attempt #1!

Slow Tests (> 5s): Spans exported BEFORE test result created

T=5s: spans exported
T=10s: test_result created ← Too late for linking attempt #2!

The Solution: Hybrid Linking

Link traces at TWO strategic points to handle both scenarios:

Linking Points

Point #1: After Test Result Creation

Location: tasks/execution/executors/results.py → link_traces_for_test_result()

Purpose: Catch traces that arrived BEFORE test result (slow tests)

linking_service = TraceLinkingService(db)
linking_service.link_traces_for_test_result(
    test_run_id=test_run_id,
    test_id=test_id,
    test_configuration_id=test_config_id,
    test_result_id=str(result_id),
    organization_id=organization_id,
)

Point #2: After Span Ingestion

Location: tasks/telemetry/post_ingest.py → link_traces_for_incoming_batch(), run inside the async post_ingest_link task dispatched by the ingestion endpoint

Purpose: Catch traces that arrived AFTER test result (fast tests)

linking_service.link_traces_for_incoming_batch(
    spans=stored_spans,
    organization_id=organization_id,
)
# Extracts test_run_id/test_id/test_configuration_id from the first span's
# attributes, finds the matching test result, then links.

Idempotency

Both linking points call crud.update_traces_with_test_result_id(), which only updates traces that aren’t linked yet:

db.query(models.Trace).filter(
    models.Trace.test_run_id == test_run_uuid,
    models.Trace.test_id == test_id_uuid,
    models.Trace.organization_id == org_uuid,
    models.Trace.attributes["rhesis.test.configuration_id"].astext == str(test_config_uuid),
    models.Trace.test_result_id.is_(None),  # Idempotency check
).update({"test_result_id": test_result_uuid})

Safe to call multiple times:

• First call: Updates N traces
• Second call: Updates 0 traces (already linked)

Result: 100% linking success rate regardless of test duration.

Test Execution Context

Context passed from test executor → SDK → spans:

test_execution_context = {
    "test_run_id": "uuid",              # Which test run
    "test_id": "uuid",                  # Which test definition
    "test_configuration_id": "uuid",    # Which configuration
    # test_result_id added later (after result created)
}

This context is stored as span attributes:

{
  "rhesis.test.run_id": "uuid",
  "rhesis.test.id": "uuid",
  "rhesis.test.configuration_id": "uuid"
}

Timing Summary

Critical Timing Points

Why 5 Seconds?

The 5-second batch delay is a trade-off:

OpenTelemetry’s default of 5 seconds optimizes for production efficiency over real-time visibility.

Error Handling

Broker Unreachable at Dispatch

Detection: post_ingest_link.delay(...) raises a broker error (Redis/kombu unreachable)

Handling: Caught and logged as a warning; ingestion still returns 200

Impact: Linking and enrichment are skipped for that batch — this is fire-and-forget, not retried by the ingestion request itself

Task Failure After Dispatch

Handling: post_ingest_link retries up to 3 times (max_retries=3, 30s delay) on uncaught exceptions

Impact: Transient failures (e.g. a momentarily locked row) self-heal; exhausted retries are logged

Database Failure

Handling: Return 500 error

Impact: Spans lost (SDK retries the export)

Linking Failure

Handling: Log error, don’t fail the task

Impact: Traces stored but not linked

Enrichment Failure

Handling: Skip problematic spans

Impact: Partial enrichment (other spans still enriched)

Debugging Guide

Traces Not Appearing?

1. Check SDK export: Is BatchSpanProcessor configured?
2. Check backend: Is /telemetry/traces receiving requests?
3. Check database: Are spans stored in the trace table?
4. Wait 5 seconds for batching delay

Traces Not Linked to Test Results?

1. Check test context: Are spans created with rhesis.test.* attributes?
2. Check Celery: Is post_ingest_link running (broker reachable)?
3. Check database: Is test_result_id NULL or set?

-- Check if traces have test context but no linking
SELECT trace_id, span_name,
       attributes->>'rhesis.test.run_id' as test_run_id,
       test_result_id
FROM trace
WHERE attributes->>'rhesis.test.run_id' IS NOT NULL
AND test_result_id IS NULL
ORDER BY created_at DESC
LIMIT 10;

Enrichment Not Happening?

1. Check workers: Are Celery workers running?
2. Check logs: Did post_ingest_link dispatch successfully?
3. Check database: Is enriched_data populated and processed_at set?

-- Check enrichment status
SELECT trace_id,
       enriched_data IS NOT NULL as is_enriched,
       processed_at
FROM trace
WHERE created_at > NOW() - INTERVAL '1 hour'
ORDER BY created_at DESC
LIMIT 10;