From a8035d7395ea862a33373729f40d7630888db9f2 Mon Sep 17 00:00:00 2001
From: Akihito Nakano <sora.akatsuki@gmail.com>
Date: Thu, 22 May 2025 11:14:48 +0900
Subject: [PATCH] Enable stdout logging in rpc_tests (#7506)

Currently `test_delayed_rpc_response` is flaky (possibly specific to Windows?), but I'm not sure why.


  Enabled stdout logging in rpc_tests. Note that in nextest, std output is only displayed when a test fails.
---
 .../lighthouse_network/tests/rpc_tests.rs     | 26 +++++++++++--------
 1 file changed, 15 insertions(+), 11 deletions(-)

diff --git a/beacon_node/lighthouse_network/tests/rpc_tests.rs b/beacon_node/lighthouse_network/tests/rpc_tests.rs
index 9b43e8b581..e644020fe4 100644
--- a/beacon_node/lighthouse_network/tests/rpc_tests.rs
+++ b/beacon_node/lighthouse_network/tests/rpc_tests.rs
@@ -55,7 +55,7 @@ fn bellatrix_block_large(spec: &ChainSpec) -> BeaconBlock<E> {
 fn test_tcp_status_rpc() {
     // Set up the logging.
     let log_level = "debug";
-    let enable_logging = false;
+    let enable_logging = true;
     build_tracing_subscriber(log_level, enable_logging);
 
     let rt = Arc::new(Runtime::new().unwrap());
@@ -159,7 +159,7 @@ fn test_tcp_status_rpc() {
 fn test_tcp_blocks_by_range_chunked_rpc() {
     // Set up the logging.
     let log_level = "debug";
-    let enable_logging = false;
+    let enable_logging = true;
     build_tracing_subscriber(log_level, enable_logging);
 
     let messages_to_send = 6;
@@ -304,7 +304,7 @@ fn test_tcp_blocks_by_range_chunked_rpc() {
 fn test_blobs_by_range_chunked_rpc() {
     // Set up the logging.
     let log_level = "debug";
-    let enable_logging = false;
+    let enable_logging = true;
     build_tracing_subscriber(log_level, enable_logging);
 
     let slot_count = 32;
@@ -425,7 +425,7 @@ fn test_blobs_by_range_chunked_rpc() {
 fn test_tcp_blocks_by_range_over_limit() {
     // Set up the logging.
     let log_level = "debug";
-    let enable_logging = false;
+    let enable_logging = true;
     build_tracing_subscriber(log_level, enable_logging);
 
     let messages_to_send = 5;
@@ -529,7 +529,7 @@ fn test_tcp_blocks_by_range_over_limit() {
 fn test_tcp_blocks_by_range_chunked_rpc_terminates_correctly() {
     // Set up the logging.
     let log_level = "debug";
-    let enable_logging = false;
+    let enable_logging = true;
     build_tracing_subscriber(log_level, enable_logging);
 
     let messages_to_send = 10;
@@ -666,7 +666,7 @@ fn test_tcp_blocks_by_range_chunked_rpc_terminates_correctly() {
 fn test_tcp_blocks_by_range_single_empty_rpc() {
     // Set up the logging.
     let log_level = "trace";
-    let enable_logging = false;
+    let enable_logging = true;
     build_tracing_subscriber(log_level, enable_logging);
 
     let rt = Arc::new(Runtime::new().unwrap());
@@ -787,7 +787,7 @@ fn test_tcp_blocks_by_range_single_empty_rpc() {
 fn test_tcp_blocks_by_root_chunked_rpc() {
     // Set up the logging.
     let log_level = "debug";
-    let enable_logging = false;
+    let enable_logging = true;
     build_tracing_subscriber(log_level, enable_logging);
 
     let messages_to_send = 6;
@@ -932,7 +932,7 @@ fn test_tcp_blocks_by_root_chunked_rpc() {
 fn test_tcp_blocks_by_root_chunked_rpc_terminates_correctly() {
     // Set up the logging.
     let log_level = "debug";
-    let enable_logging = false;
+    let enable_logging = true;
     build_tracing_subscriber(log_level, enable_logging);
 
     let messages_to_send: u64 = 10;
@@ -1143,7 +1143,7 @@ fn goodbye_test(log_level: &str, enable_logging: bool, protocol: Protocol) {
 #[allow(clippy::single_match)]
 fn tcp_test_goodbye_rpc() {
     let log_level = "debug";
-    let enabled_logging = false;
+    let enabled_logging = true;
     goodbye_test(log_level, enabled_logging, Protocol::Tcp);
 }
 
@@ -1152,13 +1152,15 @@ fn tcp_test_goodbye_rpc() {
 #[allow(clippy::single_match)]
 fn quic_test_goodbye_rpc() {
     let log_level = "debug";
-    let enabled_logging = false;
+    let enabled_logging = true;
     goodbye_test(log_level, enabled_logging, Protocol::Quic);
 }
 
 // Test that the receiver delays the responses during response rate-limiting.
 #[test]
 fn test_delayed_rpc_response() {
+    // Set up the logging.
+    build_tracing_subscriber("debug", true);
     let rt = Arc::new(Runtime::new().unwrap());
     let spec = Arc::new(E::default_spec());
 
@@ -1214,7 +1216,7 @@ fn test_delayed_rpc_response() {
                         app_request_id: _,
                         response,
                     } => {
-                        debug!(%request_id, "Sender received");
+                        debug!(%request_id, elapsed = ?request_sent_at.elapsed(), "Sender received response");
                         assert_eq!(response, rpc_response);
 
                         match request_id {
@@ -1289,6 +1291,8 @@ fn test_delayed_rpc_response() {
 // once, thanks to the self-limiter on the sender side.
 #[test]
 fn test_active_requests() {
+    // Set up the logging.
+    build_tracing_subscriber("debug", true);
     let rt = Arc::new(Runtime::new().unwrap());
     let spec = Arc::new(E::default_spec());