Improve log readability during rpc_tests

[ackintosh]

Issue Addressed

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

Proposed Changes

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

Additional Info

Not all logs during the tests have been addressed, as shown below:

2025-03-20T11:20:03.167963Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59114 id=1 peer=16Uiu2HAm6exJQC8npKsQ8VkzimEx9ri7WSLpVRQLnxTpAog8L6Me}:Connection::poll: yamux::connection: e64101e0: new outbound (Stream e64101e0/1) of (Connection e64101e0 Client (streams 1))
2025-03-20T11:20:03.167978Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59114 id=1 peer=16Uiu2HAm6exJQC8npKsQ8VkzimEx9ri7WSLpVRQLnxTpAog8L6Me}:Connection::poll: multistream_select::dialer_select: Dialer: Proposed protocol: /meshsub/1.2.0
2025-03-20T11:20:03.168040Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59112 id=2 peer=16Uiu2HAkxqJx5v1FSBD5akH7PbZqMfLfQWCeDVry6PHS7TX6D1AA}:Connection::poll: yamux::connection::rtt: received pong 958867671, estimated round-trip-time 585.583µs
2025-03-20T11:20:03.168184Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59114 id=1 peer=16Uiu2HAm6exJQC8npKsQ8VkzimEx9ri7WSLpVRQLnxTpAog8L6Me}:Connection::poll: yamux::connection: e64101e0: new outbound (Stream e64101e0/3) of (Connection e64101e0 Client (streams 3))
2025-03-20T11:20:03.168268Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59112 id=2 peer=16Uiu2HAkxqJx5v1FSBD5akH7PbZqMfLfQWCeDVry6PHS7TX6D1AA}:Connection::poll: multistream_select::listener_select: Listener: confirming protocol: /meshsub/1.2.0
2025-03-20T11:20:03.168386Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59114 id=1 peer=16Uiu2HAm6exJQC8npKsQ8VkzimEx9ri7WSLpVRQLnxTpAog8L6Me}:Connection::poll: multistream_select::dialer_select: Dialer: Proposed protocol: /ipfs/id/1.0.0
2025-03-20T11:20:03.168389Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59112 id=2 peer=16Uiu2HAkxqJx5v1FSBD5akH7PbZqMfLfQWCeDVry6PHS7TX6D1AA}:Connection::poll: multistream_select::listener_select: Listener: sent confirmed protocol: /meshsub/1.2.0
2025-03-20T11:20:03.168421Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59114 id=1 peer=16Uiu2HAm6exJQC8npKsQ8VkzimEx9ri7WSLpVRQLnxTpAog8L6Me}:Connection::poll: yamux::connection::rtt: received pong 2743595386, estimated round-trip-time 509.75µs
2025-03-20T11:20:03.168585Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59114 id=1 peer=16Uiu2HAm6exJQC8npKsQ8VkzimEx9ri7WSLpVRQLnxTpAog8L6Me}:Connection::poll: multistream_select::listener_select: Listener: confirming protocol: /meshsub/1.2.0
2025-03-20T11:20:03.168591Z DEBUG new_established_connection{remote_addr=/ip4/127.0.0.1/tcp/59114 id=1 peer=16Uiu2HAm6exJQC8npKsQ8VkzimEx9ri7WSLpVRQLnxTpAog8L6Me}:Connection::poll: multistream_select::listener_select: Listener: sent confirmed protocol: /meshsub/1.2.0

[macladson]

LGTM!