PUT operations fail to send over network after target selection

[iduartgomez]

Summary

PUT operations fail to send messages over the network. The operation correctly:

• Receives the client request
• Selects the optimal target peer
• Creates a RequestPut message
• Calls notify_op_change

However, the RequestPut message never reaches process_message, so the SeekNode message is never created and the PUT operation never goes out over the network, resulting in a timeout.

Reproduction

Run the ubertest with River:

UBERTEST_PEER_COUNT=2 cargo test --test ubertest -- --nocapture

The test will fail with:

Error: Room creation failed: Error: Timeout waiting for PUT response after 10 seconds

Root Cause

In crates/core/src/operations/put.rs:1047-1066, the request_put function creates a RequestPut message and calls notify_op_change, expecting the notification to trigger message processing. However, the notification is not being picked up by the event loop to invoke process_message on the RequestPut message.

Log Evidence

[2025-10-13T09:03:06.567293Z DEBUG] Requesting put with existing transaction ID
[2025-10-13T09:03:06.567351Z DEBUG] Determined PUT routing target, target_peer: Some("v6MWKgqJtu7MJ9jv")
[2025-10-13T09:03:06.567360Z DEBUG] Forwarding PUT to target peer
[2025-10-13T09:03:06.567378Z DEBUG] Calling notify_op_change to send PUT message to network

Note: No subsequent log showing "Requesting put for contract" (which would appear in process_message when handling RequestPut), and no SeekNode message is created.

Expected Behavior

Similar to GET operations (which work correctly), when notify_op_change is called with a RequestPut message, it should:

1. Be picked up by the event loop
2. Trigger process_message with the RequestPut message
3. Create a SeekNode message (as implemented in lines 237-245 of put.rs)
4. Send the SeekNode message over the network

Impact

• Critical: All PUT operations fail to propagate over the network
• Blocks River chat application functionality
• Prevents the ubertest from passing in CI

Investigation Branch

fix/put-operation-network-send

Related

• PR test: enable ubertest in CI to debug issues #1934 (enable ubertest in CI)
• The ubertest was created specifically to catch issues like this

Next Steps

Need to investigate:

1. How the event loop processes notifications from notify_op_change
2. Why GET operations work but PUT operations don't (both use the same pattern)
3. Whether the issue is in the notification routing or message processing

[iduartgomez]

Investigation Update: Event Loop Stops After PUT Notification

I've added extensive debug logging and discovered a critical issue:

Key Finding

The event loop for the peer sending the PUT operation completely stops running after notify_op_change completes.

Evidence from Logs

1. PUT notification sent successfully at 15:57:49.694547Z:

   notify_op_change: Notification sent successfully, tx: 01K7F4NMQY9QVNH80QKBNRFWG1, peer: v6MWKgqHt8zrA7Sg
   

2. Event loop was active BEFORE the PUT (many wait_for_event traces at 15:57:39.x)

3. Event loop completely stops AFTER the PUT:

   • No more wait_for_event logs for peer v6MWKgqHt8zrA7Sg after 15:57:49.694547Z
   • No activity at all for this peer after the PUT
   • The notification is sent from client_event_handling task
   • But the network_event_listener task never runs again

Working Theory

The issue appears to be that when notify_op_change is called from the client_event_handling task:

1. It successfully sends the notification via channel.send().await
2. The .await completes successfully
3. But then the event loop task (network_event_listener) never gets scheduled again by the tokio runtime

This suggests either:

• A tokio runtime scheduling issue
• A deadlock or blocking issue preventing the event loop from running
• The event loop task exiting/panicking silently

Next Steps

Currently testing if TRACE-level logging overhead is contributing to the issue by running with DEBUG-only logging.

Commit with enhanced logging: 5994b27

[iduartgomez]

Deep Investigation Complete - Root Cause Identified

After extensive debugging with detailed logging, I've identified the root cause:

The Problem

The event loop task for the peer initiating the PUT operation stops running immediately after notify_op_change completes, but BEFORE the notification can be received.

Timeline from Logs

18:12:37.143806Z - Event loop starts for peer v6MWKgqJ85hiKtE4
18:12:46.810648Z - PUT notification sent successfully
18:12:46.810648Z - LAST log entry for this peer (event loop stops)
18:12:56.809890Z - Timeout occurs (10 seconds later)

Critical Observations

1. Event loop WAS running: Multiple wait_for_event logs before the PUT
2. Notification send succeeds: .send().await? completes without error
3. Event loop STOPS: Zero activity after notification send
4. No exit message: Event loop doesn't log "exited unexpectedly"
5. No panic: No panic messages in logs
6. Not logging overhead: Issue occurs with both TRACE and DEBUG levels

Hypothesis

The event loop task is either:

• Silently panicking (tokio might be catching the panic)
• Getting cancelled/dropped by tokio runtime
• Hitting a deadlock in the select! poll
• Being blocked by some synchronous code

Recommended Next Steps

1. Add panic handler: Wrap event loop in std::panic::catch_unwind to catch silent panics
2. Add task cancellation detection: Use tokio's cancelled() to detect if task is being dropped
3. Simplify test: Create minimal unit test that just sends notification and verifies receipt
4. Check tokio runtime: Verify runtime isn't shutting down tasks prematurely

The issue is definitely in the event loop task lifecycle, not in the channel or notification mechanism itself.

Commits with diagnostic logging:

• 5994b27: Add extensive debug logging
• Latest investigation documented here

[iduartgomez]

Progress Update: Diagnostic Tools Added

I've completed adding comprehensive debugging capabilities to diagnose the event loop issue:

1. Enhanced Error Logging ✅

Added error logging to run_node select! statement to catch task exits:

tokio::select!(
    r = f => {
       let Err(e) = r;
       tracing::error!("Network event listener exited: {}", e);
       Err(e)
    }
    e = self.client_events_task => {
        tracing::error!("Client events task exited: {:?}", e);
        Err(e)
    }
    // ... etc
)

2. Unit Tests for Notification Channel ✅

Created 3 comprehensive unit tests that all pass:

• test_notification_channel_with_biased_select: Simulates event loop with biased select - PASSES
• test_multiple_notifications: Verifies multiple sends/receives - PASSES
• test_send_fails_when_receiver_dropped: Validates error handling - PASSES

Key finding: The notification channel mechanism works perfectly in isolation. The issue is specific to the full node environment.

3. Tokio-Console Support ✅

Added tokio-console for real-time task monitoring:

• Added console-subscriber optional dependency
• Enabled tokio's tracing feature
• Created console-subscriber feature flag

How to Use Tokio-Console

To debug the task lifecycle issue:

# Terminal 1: Start tokio-console
cargo install tokio-console
tokio-console

# Terminal 2: Run freenet with console support
cd crates/core
RUSTFLAGS="--cfg tokio_unstable" cargo build --features console-subscriber --test ubertest
RUSTFLAGS="--cfg tokio_unstable" RUST_LOG=tokio=trace,runtime=trace cargo test --features console-subscriber --test ubertest test_basic_room_creation -- --nocapture

This will show:

• All running tasks in real-time
• Which tasks are blocked/sleeping/running
• Task state transitions
• Resource usage per task
• Why the event loop task stops

Next Steps

1. Run the ubertest with tokio-console attached
2. Observe event loop task state when PUT notification is sent
3. Identify if task is:
   • Exiting normally
   • Panicking silently
   • Deadlocked/blocked
   • Being cancelled by tokio runtime

Commits:

• 1894b47: Error handling + unit tests
• cc247a7: Tokio-console support

@nacho You can now use tokio-console to see exactly what's happening to the event loop task when the PUT is sent!

[iduartgomez]

CRITICAL Finding: Event Loop is NOT Exiting!

Just ran the test with tokio-console support and discovered something crucial:

Test Results

The event loop task is NOT exiting, crashing, or being cancelled!

Evidence:

• Added error logging to catch task exits in run_node select!
• Ran test with console subscriber enabled
• ZERO exit messages logged:
  • ❌ "Network event listener exited" - NOT logged
  • ❌ "Client events task exited" - NOT logged
  • ❌ "Contract executor task exited" - NOT logged

What This Means

My earlier hypothesis that "the event loop stops running" was incorrect. The event loop IS still running when the timeout occurs!

The Real Problem

The issue is NOT:

• ❌ Event loop exiting
• ❌ Task panicking
• ❌ Runtime cancelling the task

The issue IS:

• ✅ Event loop is running but not receiving notifications from the channel

Next Investigation

Since:

1. Unit tests prove the channel works in isolation ✅
2. Event loop task is still running ✅
3. Notification send completes successfully ✅
4. But notification never received ❌

The problem must be one of:

1. Wrong channel instance - OpManager sending to different channel than event loop is receiving from
2. Channel state issue - Something corrupting the channel or preventing recv()
3. Select! polling issue - Biased select not actually polling notifications_receiver
4. Sender/Receiver mismatch - Channel created twice or cloned incorrectly

Let me investigate the channel setup more carefully to find where the mismatch occurs.

Commit: 483fab0

[iduartgomez]

Major Discovery: Channels Match - Not a Mismatch Issue!

Just verified with channel ID tracking:

Channel Verification Results

Channel 1 created for peer v6MWKgqHXDwYuTGc
↓
Event loop opens, receiving from channel 1
↓  
PUT notification sent to channel 1

✅ THE CHANNELS MATCH PERFECTLY!

What We've Eliminated

1. ❌ Event loop exiting - Event loop is still running
2. ❌ Channel mismatch - Sender and receiver use same channel
3. ❌ Task panicking - No panic messages
4. ❌ Runtime cancellation - Tasks don't exit

The Remaining Mystery

We have a situation where:

• ✅ Channel pair is correctly created
• ✅ OpManager has correct sender
• ✅ Event loop has correct receiver
• ✅ .send().await completes successfully
• ✅ Event loop task is running
• ❌ But .recv() in select! never fires

This is extremely unusual behavior for tokio mpsc channels.

Possible Remaining Causes

1. Select! polling bug - Biased select somehow not polling notifications_receiver
2. Channel buffer issue - Something preventing the message from being readable
3. Tokio bug - Edge case in mpsc channel implementation
4. Race condition - Timing issue between send and select! polling

Next steps: Add detailed logging INSIDE the select! to see which futures are being polled.

Commit: d06ee93

[iduartgomez]

🔍 Comprehensive Investigation Summary - Updated 2025-10-14

After extensive debugging with detailed logging, tokio-console, and systematic hypothesis testing, we've identified the root causes and implemented a partial fix.

---

✅ Issue #1: Complete Deadlock - FIXED in PR #1950

Root Cause

The handshake handler's wait_for_events() contains a nested loop { select! { ... } } that blocks indefinitely when there are no pending handshake operations, causing the main event loop to deadlock.

How It Manifests

22:44:35.563735Z - Event loop enters wait_for_event (last call)
22:44:44.720347Z - PUT notification sent (9 seconds later)
NO MORE wait_for_event calls - Event loop NEVER returns from select!

The Fix (PR #1950)

Wrapped handshake branch with 100ms timeout:

handshake_event_res = timeout(Duration::from_millis(100), handshake_handler.wait_for_events()) => {
    match handshake_event_res {
        Ok(Ok(event)) => { /* handle event */ }
        Ok(Err(e)) => { /* handle error */ }
        Err(_timeout) => Ok(EventResult::Continue)  // Continue loop
    }
}

Impact: Event loop no longer freezes completely ✅

---

❌ Issue #2: Waker Registration Failure - UNSOLVED

The Problem

Even with the timeout fix preventing complete deadlock, PUT operations still timeout because ALL select! branches stop becoming ready after initial handshakes complete.

Evidence

After ~9 initial events (handshakes), the event loop continues running BUT:

• 249 "ENTERING select!" logs - loop is running ✅
• Only 9 "SELECTED" logs - no branches become ready after handshakes ❌
• PUT notification sent successfully at 22:49:41.490418Z
• Last branch selected at 22:49:32.313322Z (9 seconds BEFORE PUT!)
• 240 more loop iterations with ZERO branches ready

What We've Tested and Eliminated

❌ NOT Event Loop Exiting

• Added error logging to catch task exits
• NO exit messages logged
• Event loop task still running when timeout occurs

❌ NOT Channel Mismatch

• Added unique channel IDs to track sender/receiver pairs
• Channels match perfectly (channel 1 → channel 1)

❌ NOT biased Select Issue

• Tested without biased
• IDENTICAL behavior: 249 ENTERING, 9 SELECTED, same timeout
• biased is NOT the cause

❌ NOT Channel Mechanism Bug

• Created 3 comprehensive unit tests
• ALL PASS - channel + biased select work perfectly in isolation

The Mystery

After handshakes complete, ALL select! branches return Poll::Pending forever:

• ❌ notifications_receiver.recv() never ready (even when PUT sent)
• ❌ op_execution_receiver.recv() never ready
• ❌ peer_connections.next() never ready
• ❌ conn_bridge_rx.recv() never ready
• ✅ Only handshake timeout fires (every 100ms)

This affects ALL channels simultaneously, suggesting a systemic issue rather than individual channel problems.

---

🔬 Possible Root Causes

1. Channel Senders Dropped: All senders dropped after handshakes, closing channels
2. Tokio Runtime Issue: Bug in multi-threaded runtime with mpsc + nested select
3. Timeout Wrapper Side Effect: Timeout corrupts select! future state, breaking waker registration
4. Race Condition: Timing issue between handshake completion and notification sending

---

📋 Next Steps

Immediate (High Priority)

1. Use tokio-console in real-time

   • Watch event loop task state when PUT is sent
   • Identify if task is blocked/sleeping/cancelled

2. Add channel state inspection

   • Check if senders are dropped (sender.is_closed())
   • Verify receiver validity

3. Test without timeout wrapper

   • See if timeout causes waker corruption
   • Try different anti-deadlock approach

Short-Term (Proper Fix)

4. Refactor wait_for_events()
   • Remove internal loop
   • Return after one event
   • Let outer loop control iteration
   • Addresses root cause properly

---

📚 Full Investigation Details

Complete 543-line investigation document with all findings, tests, and analysis:
COMPREHENSIVE_INVESTIGATION_1944.md

---

🎯 Current Status

Partial Fix Merged: PR #1950 prevents complete deadlock
Remaining Issue: PUT operations still timeout due to waker registration failure
Investigation Branch: fix/put-operation-network-send
Priority: High - Blocks River chat functionality and CI

---

Investigation by @iduartgomez with Claude Code assistance