Improve log readability during rpc_tests (#7180)

ackintosh · web-flow · commit cf0f95985540 · 2025-05-22T02:51:25.000Z
It is unclear from the logs during rpc_tests whether the output comes from the sender or the receiver.

```
2025-03-20T11:21:50.038868Z DEBUG rpc_tests: Sending message 2
2025-03-20T11:21:50.041129Z DEBUG rpc_tests: Sender received a response
2025-03-20T11:21:50.041242Z DEBUG rpc_tests: Chunk received
2025-03-20T11:21:51.040837Z DEBUG rpc_tests: Sending message 3
2025-03-20T11:21:51.043635Z DEBUG rpc_tests: Sender received a response
2025-03-20T11:21:51.043855Z DEBUG rpc_tests: Chunk received
2025-03-20T11:21:52.043427Z DEBUG rpc_tests: Sending message 4
2025-03-20T11:21:52.052831Z DEBUG rpc_tests: Sender received a response
2025-03-20T11:21:52.052953Z DEBUG rpc_tests: Chunk received
2025-03-20T11:21:53.045589Z DEBUG rpc_tests: Sending message 5
2025-03-20T11:21:53.052718Z DEBUG rpc_tests: Sender received a response
2025-03-20T11:21:53.052825Z DEBUG rpc_tests: Chunk received
2025-03-20T11:21:54.049157Z DEBUG rpc_tests: Sending message 6
2025-03-20T11:21:54.058072Z DEBUG rpc_tests: Sender received a response
2025-03-20T11:21:54.058603Z DEBUG rpc_tests: Chunk received
2025-03-20T11:21:55.018822Z DEBUG Swarm::poll: libp2p_gossipsub::behaviour: Starting heartbeat
2025-03-20T11:21:55.018953Z DEBUG Swarm::poll: libp2p_gossipsub::behaviour: Completed Heartbeat
2025-03-20T11:21:55.027100Z DEBUG Swarm::poll: libp2p_gossipsub::behaviour: Starting heartbeat
2025-03-20T11:21:55.027199Z DEBUG Swarm::poll: libp2p_gossipsub::behaviour: Completed Heartbeat
```


  Added `info_span` to both the sender and receiver in each test.

```
2025-03-20T11:20:04.172699Z DEBUG Receiver: rpc_tests: Sending message 2
2025-03-20T11:20:04.179147Z DEBUG Sender: rpc_tests: Sender received a response
2025-03-20T11:20:04.179281Z DEBUG Sender: rpc_tests: Chunk received
2025-03-20T11:20:05.175300Z DEBUG Receiver: rpc_tests: Sending message 3
2025-03-20T11:20:05.177202Z DEBUG Sender: rpc_tests: Sender received a response
2025-03-20T11:20:05.177292Z DEBUG Sender: rpc_tests: Chunk received
2025-03-20T11:20:06.176868Z DEBUG Receiver: rpc_tests: Sending message 4
2025-03-20T11:20:06.179379Z DEBUG Sender: rpc_tests: Sender received a response
2025-03-20T11:20:06.179460Z DEBUG Sender: rpc_tests: Chunk received
2025-03-20T11:20:07.179257Z DEBUG Receiver: rpc_tests: Sending message 5
2025-03-20T11:20:07.181386Z DEBUG Sender: rpc_tests: Sender received a response
2025-03-20T11:20:07.181503Z DEBUG Sender: rpc_tests: Chunk received
2025-03-20T11:20:08.181428Z DEBUG Receiver: rpc_tests: Sending message 6
2025-03-20T11:20:08.190231Z DEBUG Sender: rpc_tests: Sender received a response
2025-03-20T11:20:08.190358Z DEBUG Sender: rpc_tests: Chunk received
2025-03-20T11:20:09.151699Z DEBUG Sender:Swarm::poll: libp2p_gossipsub::behaviour: Starting heartbeat
2025-03-20T11:20:09.151748Z DEBUG Sender:Swarm::poll: libp2p_gossipsub::behaviour: Completed Heartbeat
2025-03-20T11:20:09.160244Z DEBUG Receiver:Swarm::poll: libp2p_gossipsub::behaviour: Starting heartbeat
2025-03-20T11:20:09.160288Z DEBUG Receiver:Swarm::poll: libp2p_gossipsub::behaviour: Completed Heartbeat
```
diff --git a/beacon_node/lighthouse_network/tests/rpc_tests.rs b/beacon_node/lighthouse_network/tests/rpc_tests.rs
@@ -12,7 +12,7 @@ use std::sync::Arc;
 use std::time::{Duration, Instant};
 use tokio::runtime::Runtime;
 use tokio::time::sleep;
-use tracing::{debug, error, warn};
+use tracing::{debug, error, info_span, warn, Instrument};
 use types::{
     BeaconBlock, BeaconBlockAltair, BeaconBlockBase, BeaconBlockBellatrix, BlobSidecar, ChainSpec,
     EmptyBlock, Epoch, EthSpec, FixedBytesExtended, ForkName, Hash256, MinimalEthSpec,
@@ -117,7 +117,8 @@ fn test_tcp_status_rpc() {
                     _ => {}
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // build the receiver future
         let receiver_future = async {
@@ -141,7 +142,8 @@ fn test_tcp_status_rpc() {
                     _ => {} // Ignore other events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
 
         tokio::select! {
             _ = sender_future => {}
@@ -245,7 +247,8 @@ fn test_tcp_blocks_by_range_chunked_rpc() {
                     _ => {} // Ignore other behaviour events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // build the receiver future
         let receiver_future = async {
@@ -286,7 +289,8 @@ fn test_tcp_blocks_by_range_chunked_rpc() {
                     _ => {} // Ignore other events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
 
         tokio::select! {
             _ = sender_future => {}
@@ -373,7 +377,8 @@ fn test_blobs_by_range_chunked_rpc() {
                     _ => {} // Ignore other behaviour events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // build the receiver future
         let receiver_future = async {
@@ -407,7 +412,8 @@ fn test_blobs_by_range_chunked_rpc() {
                     _ => {} // Ignore other events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
 
         tokio::select! {
             _ = sender_future => {}
@@ -479,7 +485,8 @@ fn test_tcp_blocks_by_range_over_limit() {
                     _ => {} // Ignore other behaviour events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // build the receiver future
         let receiver_future = async {
@@ -512,7 +519,8 @@ fn test_tcp_blocks_by_range_over_limit() {
                     _ => {} // Ignore other events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
 
         tokio::select! {
             _ = sender_future => {}
@@ -601,7 +609,8 @@ fn test_tcp_blocks_by_range_chunked_rpc_terminates_correctly() {
                     _ => {} // Ignore other behaviour events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // determine messages to send (PeerId, RequestId). If some, indicates we still need to send
         // messages
@@ -648,7 +657,8 @@ fn test_tcp_blocks_by_range_chunked_rpc_terminates_correctly() {
                     }
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
 
         tokio::select! {
             _ = sender_future => {}
@@ -734,7 +744,8 @@ fn test_tcp_blocks_by_range_single_empty_rpc() {
                     _ => {} // Ignore other behaviour events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // build the receiver future
         let receiver_future = async {
@@ -767,7 +778,8 @@ fn test_tcp_blocks_by_range_single_empty_rpc() {
                     _ => {} // Ignore other events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
         tokio::select! {
             _ = sender_future => {}
             _ = receiver_future => {}
@@ -877,7 +889,8 @@ fn test_tcp_blocks_by_root_chunked_rpc() {
                     _ => {} // Ignore other behaviour events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // build the receiver future
         let receiver_future = async {
@@ -916,7 +929,8 @@ fn test_tcp_blocks_by_root_chunked_rpc() {
                     _ => {} // Ignore other events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
         tokio::select! {
             _ = sender_future => {}
             _ = receiver_future => {}
@@ -1015,7 +1029,8 @@ fn test_tcp_blocks_by_root_chunked_rpc_terminates_correctly() {
                     _ => {} // Ignore other behaviour events
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // determine messages to send (PeerId, RequestId). If some, indicates we still need to send
         // messages
@@ -1062,7 +1077,8 @@ fn test_tcp_blocks_by_root_chunked_rpc_terminates_correctly() {
                     }
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
 
         tokio::select! {
             _ = sender_future => {}
@@ -1115,7 +1131,8 @@ fn goodbye_test(log_level: &str, enable_logging: bool, protocol: Protocol) {
                     _ => {} // Ignore other RPC messages
                 }
             }
-        };
+        }
+        .instrument(info_span!("Sender"));
 
         // build the receiver future
         let receiver_future = async {
@@ -1125,7 +1142,8 @@ fn goodbye_test(log_level: &str, enable_logging: bool, protocol: Protocol) {
                     return;
                 }
             }
-        };
+        }
+        .instrument(info_span!("Receiver"));
 
         let total_future = futures::future::join(sender_future, receiver_future);
 

Original file line number	Diff line number	Diff line change
`@@ -12,7 +12,7 @@ use std::sync::Arc;`
`12`	`12`	`use std::time::{Duration, Instant};`
`13`	`13`	`use tokio::runtime::Runtime;`
`14`	`14`	`use tokio::time::sleep;`
`15`		`-use tracing::{debug, error, warn};`
	`15`	`+use tracing::{debug, error, info_span, warn, Instrument};`
`16`	`16`	`use types::{`
`17`	`17`	`BeaconBlock, BeaconBlockAltair, BeaconBlockBase, BeaconBlockBellatrix, BlobSidecar, ChainSpec,`
`18`	`18`	`EmptyBlock, Epoch, EthSpec, FixedBytesExtended, ForkName, Hash256, MinimalEthSpec,`
`@@ -117,7 +117,8 @@ fn test_tcp_status_rpc() {`
`117`	`117`	`_ => {}`
`118`	`118`	`}`
`119`	`119`	`}`
`120`		`- };`
	`120`	`+ }`
	`121`	`+ .instrument(info_span!("Sender"));`
`121`	`122`
`122`	`123`	`// build the receiver future`
`123`	`124`	`let receiver_future = async {`
`@@ -141,7 +142,8 @@ fn test_tcp_status_rpc() {`
`141`	`142`	`_ => {} // Ignore other events`
`142`	`143`	`}`
`143`	`144`	`}`
`144`		`- };`
	`145`	`+ }`
	`146`	`+ .instrument(info_span!("Receiver"));`
`145`	`147`
`146`	`148`	`tokio::select! {`
`147`	`149`	`_ = sender_future => {}`
`@@ -245,7 +247,8 @@ fn test_tcp_blocks_by_range_chunked_rpc() {`
`245`	`247`	`_ => {} // Ignore other behaviour events`
`246`	`248`	`}`
`247`	`249`	`}`
`248`		`- };`
	`250`	`+ }`
	`251`	`+ .instrument(info_span!("Sender"));`
`249`	`252`
`250`	`253`	`// build the receiver future`
`251`	`254`	`let receiver_future = async {`
`@@ -286,7 +289,8 @@ fn test_tcp_blocks_by_range_chunked_rpc() {`
`286`	`289`	`_ => {} // Ignore other events`
`287`	`290`	`}`
`288`	`291`	`}`
`289`		`- };`
	`292`	`+ }`
	`293`	`+ .instrument(info_span!("Receiver"));`
`290`	`294`
`291`	`295`	`tokio::select! {`
`292`	`296`	`_ = sender_future => {}`
`@@ -373,7 +377,8 @@ fn test_blobs_by_range_chunked_rpc() {`
`373`	`377`	`_ => {} // Ignore other behaviour events`
`374`	`378`	`}`
`375`	`379`	`}`
`376`		`- };`
	`380`	`+ }`
	`381`	`+ .instrument(info_span!("Sender"));`
`377`	`382`
`378`	`383`	`// build the receiver future`
`379`	`384`	`let receiver_future = async {`
`@@ -407,7 +412,8 @@ fn test_blobs_by_range_chunked_rpc() {`
`407`	`412`	`_ => {} // Ignore other events`
`408`	`413`	`}`
`409`	`414`	`}`
`410`		`- };`
	`415`	`+ }`
	`416`	`+ .instrument(info_span!("Receiver"));`
`411`	`417`
`412`	`418`	`tokio::select! {`
`413`	`419`	`_ = sender_future => {}`
`@@ -479,7 +485,8 @@ fn test_tcp_blocks_by_range_over_limit() {`
`479`	`485`	`_ => {} // Ignore other behaviour events`
`480`	`486`	`}`
`481`	`487`	`}`
`482`		`- };`
	`488`	`+ }`
	`489`	`+ .instrument(info_span!("Sender"));`
`483`	`490`
`484`	`491`	`// build the receiver future`
`485`	`492`	`let receiver_future = async {`
`@@ -512,7 +519,8 @@ fn test_tcp_blocks_by_range_over_limit() {`
`512`	`519`	`_ => {} // Ignore other events`
`513`	`520`	`}`
`514`	`521`	`}`
`515`		`- };`
	`522`	`+ }`
	`523`	`+ .instrument(info_span!("Receiver"));`
`516`	`524`
`517`	`525`	`tokio::select! {`
`518`	`526`	`_ = sender_future => {}`
`@@ -601,7 +609,8 @@ fn test_tcp_blocks_by_range_chunked_rpc_terminates_correctly() {`
`601`	`609`	`_ => {} // Ignore other behaviour events`
`602`	`610`	`}`
`603`	`611`	`}`
`604`		`- };`
	`612`	`+ }`
	`613`	`+ .instrument(info_span!("Sender"));`
`605`	`614`
`606`	`615`	`// determine messages to send (PeerId, RequestId). If some, indicates we still need to send`
`607`	`616`	`// messages`
`@@ -648,7 +657,8 @@ fn test_tcp_blocks_by_range_chunked_rpc_terminates_correctly() {`
`648`	`657`	`}`
`649`	`658`	`}`
`650`	`659`	`}`
`651`		`- };`
	`660`	`+ }`
	`661`	`+ .instrument(info_span!("Receiver"));`
`652`	`662`
`653`	`663`	`tokio::select! {`
`654`	`664`	`_ = sender_future => {}`
`@@ -734,7 +744,8 @@ fn test_tcp_blocks_by_range_single_empty_rpc() {`
`734`	`744`	`_ => {} // Ignore other behaviour events`
`735`	`745`	`}`
`736`	`746`	`}`
`737`		`- };`
	`747`	`+ }`
	`748`	`+ .instrument(info_span!("Sender"));`
`738`	`749`
`739`	`750`	`// build the receiver future`
`740`	`751`	`let receiver_future = async {`
`@@ -767,7 +778,8 @@ fn test_tcp_blocks_by_range_single_empty_rpc() {`
`767`	`778`	`_ => {} // Ignore other events`
`768`	`779`	`}`
`769`	`780`	`}`
`770`		`- };`
	`781`	`+ }`
	`782`	`+ .instrument(info_span!("Receiver"));`
`771`	`783`	`tokio::select! {`
`772`	`784`	`_ = sender_future => {}`
`773`	`785`	`_ = receiver_future => {}`
`@@ -877,7 +889,8 @@ fn test_tcp_blocks_by_root_chunked_rpc() {`
`877`	`889`	`_ => {} // Ignore other behaviour events`
`878`	`890`	`}`
`879`	`891`	`}`
`880`		`- };`
	`892`	`+ }`
	`893`	`+ .instrument(info_span!("Sender"));`
`881`	`894`
`882`	`895`	`// build the receiver future`
`883`	`896`	`let receiver_future = async {`
`@@ -916,7 +929,8 @@ fn test_tcp_blocks_by_root_chunked_rpc() {`
`916`	`929`	`_ => {} // Ignore other events`
`917`	`930`	`}`
`918`	`931`	`}`
`919`		`- };`
	`932`	`+ }`
	`933`	`+ .instrument(info_span!("Receiver"));`
`920`	`934`	`tokio::select! {`
`921`	`935`	`_ = sender_future => {}`
`922`	`936`	`_ = receiver_future => {}`
`@@ -1015,7 +1029,8 @@ fn test_tcp_blocks_by_root_chunked_rpc_terminates_correctly() {`
`1015`	`1029`	`_ => {} // Ignore other behaviour events`
`1016`	`1030`	`}`
`1017`	`1031`	`}`
`1018`		`- };`
	`1032`	`+ }`
	`1033`	`+ .instrument(info_span!("Sender"));`
`1019`	`1034`
`1020`	`1035`	`// determine messages to send (PeerId, RequestId). If some, indicates we still need to send`
`1021`	`1036`	`// messages`
`@@ -1062,7 +1077,8 @@ fn test_tcp_blocks_by_root_chunked_rpc_terminates_correctly() {`
`1062`	`1077`	`}`
`1063`	`1078`	`}`
`1064`	`1079`	`}`
`1065`		`- };`
	`1080`	`+ }`
	`1081`	`+ .instrument(info_span!("Receiver"));`
`1066`	`1082`
`1067`	`1083`	`tokio::select! {`
`1068`	`1084`	`_ = sender_future => {}`
`@@ -1115,7 +1131,8 @@ fn goodbye_test(log_level: &str, enable_logging: bool, protocol: Protocol) {`
`1115`	`1131`	`_ => {} // Ignore other RPC messages`
`1116`	`1132`	`}`
`1117`	`1133`	`}`
`1118`		`- };`
	`1134`	`+ }`
	`1135`	`+ .instrument(info_span!("Sender"));`
`1119`	`1136`
`1120`	`1137`	`// build the receiver future`
`1121`	`1138`	`let receiver_future = async {`
`@@ -1125,7 +1142,8 @@ fn goodbye_test(log_level: &str, enable_logging: bool, protocol: Protocol) {`
`1125`	`1142`	`return;`
`1126`	`1143`	`}`
`1127`	`1144`	`}`
`1128`		`- };`
	`1145`	`+ }`
	`1146`	`+ .instrument(info_span!("Receiver"));`
`1129`	`1147`
`1130`	`1148`	`let total_future = futures::future::join(sender_future, receiver_future);`
`1131`	`1149`