From cf0f95985540696bde727b3bd54ba379891e10a2 Mon Sep 17 00:00:00 2001 From: Akihito Nakano Date: Thu, 22 May 2025 11:51:25 +0900 Subject: [PATCH] Improve log readability during rpc_tests (#7180) 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 ``` --- .../lighthouse_network/tests/rpc_tests.rs | 56 ++++++++++++------- 1 file changed, 37 insertions(+), 19 deletions(-) diff --git a/beacon_node/lighthouse_network/tests/rpc_tests.rs b/beacon_node/lighthouse_network/tests/rpc_tests.rs index e644020fe4..72d7aa0074 100644 --- 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);