gnosis/lighthouse
1
0
Fork 0
mirror of https://github.com/sigp/lighthouse.git synced 2026-03-02 16:21:42 +00:00
Code Issues Packages Projects Releases Wiki Activity

Improve log readability during rpc_tests (#7180)

Browse Source 
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
```
This commit is contained in:
Akihito Nakano
2025-05-22 11:51:25 +09:00
committed by GitHub
parent 537fc5bde8
commit cf0f959855
1 changed files with 37 additions and 19 deletions
Download Patch File Download Diff File Expand all files Collapse all files

56
beacon_node/lighthouse_network/tests/rpc_tests.rs
View File

@@ -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);