Add structured operation tracing for state propagation visibility

[sanity]

Problem

Recent debugging of #2010 and #1996 revealed that tracing state propagation across peers is difficult because:

1. Scattered logging - State changes logged at different levels in different modules
2. Missing context - Hard to correlate "peer A has version X" with "peer B has version Y"
3. No timeline view - Can't easily see the sequence of state changes across multiple peers
4. Difficult to query - Can't filter for "show me all state changes for contract K across all peers"

This made debugging feel like "whack-a-mole combined with groundhog day" because it was hard to understand what state each peer had at each point in time.

Proposal

Add structured operation tracing that makes state propagation visible and queryable. This should integrate with the existing tracing infrastructure but add specific span/event patterns for contract operations.

Design

1. Operation Spans with Structured Fields

Wrap each high-level operation in a span with consistent fields:

let span = tracing::info_span!(
    "contract_operation",
    op_type = "put",           // put, update, get
    tx = %transaction_id,
    contract = %key,
    peer = %peer_id,
    role = "initiator",         // initiator, target, forwarder
    initial_version = ?old_version,
    final_version = tracing::field::Empty,  // filled later
);

let _enter = span.enter();
// ... perform operation ...
span.record("final_version", &new_version);

2. State Change Events

Emit structured events at key points:

tracing::info!(
    event = "state_cached",
    contract = %key,
    peer = %peer_id,
    version = version,
    size_bytes = state.len(),
    source = "local_merge",  // local_merge, network_receive, client_put
    "Cached contract state locally"
);

tracing::info!(
    event = "state_forwarded",
    contract = %key,
    from_peer = %source_peer,
    to_peer = %target_peer,
    version = version,
    "Forwarded contract state to target peer"
);

3. Multi-Peer Timeline View

With structured events, we can query logs to build timelines:

# Show all state changes for a specific contract across all peers
cat peer-*.log | grep 'contract="ABC"' | jq -s 'sort_by(.timestamp)'

# Show version progression for a contract
cat peer-*.log | grep 'event="state_cached"' | \
  jq -s 'group_by(.peer) | map({peer: .[0].peer, versions: map(.version)})'

4. Tracing Subscribers

Consider adding a custom tracing subscriber for development that:

• Aggregates events by contract key
• Displays a visual timeline of state propagation
• Highlights version mismatches or unexpected state

// Example output:
// Contract ABC timeline:
// T+0.0s  [Peer1] PUT initiated (v0 -> v1)
// T+0.1s  [Peer1] State cached locally (v1)
// T+0.2s  [Peer1] Forwarded to Peer2 (v1)
// T+0.3s  [Peer2] State received (v1)
// T+0.4s  [Peer2] State cached locally (v1)
// ⚠ T+0.5s  [Peer1] GET returned (v0) ← VERSION MISMATCH!

Suggested Events to Track

PUT Operation

• put_initiated - Client initiates PUT
• state_cached - State cached locally before forwarding
• put_forwarded - Request forwarded to target peer
• put_received - Target peer receives PUT
• put_completed - PUT completes successfully
• put_failed - PUT fails with error

UPDATE Operation

• update_initiated - Client initiates UPDATE
• delta_applied - Delta applied to local state
• state_cached - Updated state cached locally
• update_forwarded - Request forwarded to target peer
• update_received - Target peer receives UPDATE
• update_completed - UPDATE completes successfully
• update_failed - UPDATE fails with error

GET Operation

• get_initiated - Client initiates GET
• state_served - State served from local cache
• get_forwarded - Request forwarded to target peer
• state_received - State received from network
• get_completed - GET completes successfully
• get_failed - GET fails or times out

State Management

• state_merged - Two states merged (include both versions)
• version_incremented - Version incremented (old -> new)
• contract_seeded - Contract added to seed list
• contract_unseeded - Contract removed from seed list

Benefits

1. Easier debugging - See exactly what happened, when, and on which peer
2. Reproduce issues - Timeline view makes it easy to understand failure sequences
3. Performance analysis - Structured timing data for operation latencies
4. Testing validation - Verify state propagation in integration tests
5. Documentation - Events serve as living documentation of the protocol

Implementation Approach

1. Start with PUT/UPDATE/GET operations in crates/core/src/operations/
2. Add structured spans and events at key points
3. Create a test subscriber that validates state propagation in tests
4. Consider a --trace-contracts CLI flag for development builds
5. Document the event schema for external log analysis tools

Related Issues

• fix: client-initiated PUT requests not cached locally when forwarded to target peer #2010 - Client-initiated PUT not cached locally
• fix: persist contract state after PUT merge in upsert_contract_state #1996 - Incoming PUT not cached locally
• Add invariant assertions for contract operation state consistency #2013 - Add invariant assertions (complementary approach)

Example Use Cases

Use case 1: Debug why a peer serves stale state

# Find when peer last cached this contract
grep 'peer="ABC" event="state_cached"' peer.log | tail -1

Use case 2: Verify state propagated correctly in test

assert_event_sequence(&logs, &[
    ("put_initiated", peer1),
    ("state_cached", peer1),
    ("put_forwarded", peer1),
    ("state_received", peer2),
    ("state_cached", peer2),
]);

Use case 3: Find version inconsistencies

# Show all peers with their latest cached version for contract K
grep 'contract="K" event="state_cached"' *.log | \
  jq -s 'group_by(.peer) | map({peer: .[0].peer, version: (map(.version) | max)})'

[AI-assisted debugging and comment]

[iduartgomez]

I am working on improving all this.

[iduartgomez]

Progress Update: Event Log Aggregation Layer (PR #2032)

I've implemented the aggregation and analysis infrastructure that complements the structured event tracing described in this issue.

✅ What's Done

PR #2032 adds a complete event log aggregator that solves the multi-peer correlation problems described here:

Core Capabilities

• Multi-peer event collection: Aggregates events from all nodes' AOF files
• Transaction correlation: get_transaction_flow(&tx) - traces operations across the distributed network
• Timeline reconstruction: Events sorted by timestamp showing sequential state changes
• Routing path analysis: get_routing_path(&tx) - shows which peers handled the transaction
• Visualization: export_mermaid_graph(&tx) - generates flowcharts of transaction paths

Architecture

Each node maintains separated event logs (identical to production):

let aggregator = TestAggregatorBuilder::new()
    .add_node("gateway", gateway_log_path)
    .add_node("node-a", node_a_log_path)  
    .add_node("node-b", node_b_log_path)
    .build().await?;

// Query multi-peer timeline
let flow = aggregator.get_transaction_flow(&transaction_id).await?;
// Returns: chronological list of events across all nodes

// Visualize the path
let graph = aggregator.export_mermaid_graph(&transaction_id).await?;

Technical Highlights

• Zero-overhead generics with native async fn (no async-trait dependency)
• Multiple collection modes: AOF files, WebSocket, in-memory
• Test utilities for easy integration test setup
• Comprehensive documentation in docs/EVENT_AGGREGATOR.md

🔄 What's Left To Do

The aggregator infrastructure is ready, but it needs richer event data from the structured tracing this issue proposes:

Event Structure Enhancements

Currently we work with basic NetLogMessage events. To fully solve the "whack-a-mole" problem, we need:

1. Consistent operation fields (as proposed in this issue):

   • op_type (PUT/UPDATE/GET)
   • contract_key
   • peer_role (requester, relay, cache)
   • state_version

2. Structured state events:

   • state_cached, state_forwarded, state_merged
   • Version increments
   • Contract seeding/unseeding

3. Performance metrics:

   • Operation durations
   • Network hop timing
   • Cache hit rates

Query Enhancements

Once events have richer structure, the aggregator could add:

• get_events_by_contract_key(key) - all events for a specific contract
• get_state_timeline(contract_key) - state version changes over time
• get_performance_metrics(tx) - timing breakdown across hops
• detect_anomalies() - find unusual propagation patterns

🎯 Integration Plan

The aggregator provides the analysis layer for structured events:

┌─────────────────────────────────────────────┐
│ This Issue (#2014): Event Capture Layer    │
│ - Structured spans with consistent fields  │
│ - Operation events at key points           │
│ - Written to AOF files per node            │
└─────────────────┬───────────────────────────┘
                  ↓
┌─────────────────────────────────────────────┐
│ PR #2032: Aggregation & Analysis Layer     │
│ - Collect events from all nodes            │
│ - Correlate by transaction ID               │
│ - Build multi-peer timelines                │
│ - Query, filter, visualize                 │
└─────────────────────────────────────────────┘

📝 Next Steps

1. Merge PR feat: add event log aggregation for multi-node debugging #2032 - Get the aggregation infrastructure in place
2. Enhance EventKind variants - Add the structured fields proposed in this issue
3. Add query methods - Leverage the new event structure for better filtering
4. Improve visualizations - Timeline charts, state transition diagrams

The foundation is ready - we just need to feed it the rich structured events this issue describes! Let me know if you'd like help with any of the next steps.

Related: PR #2032 - #2032