From b59fc2ff0ce7cbccc98084505a4a7ee88238a790 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Marcel=20M=C3=A4rtens?= <marcel.cochem@googlemail.com>
Date: Tue, 18 Aug 2020 13:48:26 +0200
Subject: [PATCH] improve tracing and spans in network crate

---
 network/src/participant.rs  |  2 ++
 network/src/protocols.rs    | 15 +++++++--------
 network/src/scheduler.rs    | 19 ++++++++++++++-----
 server/src/events/player.rs |  5 +++--
 4 files changed, 26 insertions(+), 15 deletions(-)

diff --git a/network/src/participant.rs b/network/src/participant.rs
index 085ddfcb77..0363d08310 100644
--- a/network/src/participant.rs
+++ b/network/src/participant.rs
@@ -25,6 +25,7 @@ use std::{
     time::{Duration, Instant},
 };
 use tracing::*;
+use tracing_futures::Instrument;
 
 pub(crate) type A2bStreamOpen = (Prio, Promises, oneshot::Sender<Stream>);
 pub(crate) type S2bCreateChannel = (Cid, Sid, Protocols, Vec<(Cid, Frame)>, oneshot::Sender<()>);
@@ -477,6 +478,7 @@ impl BParticipant {
                         trace!(?cid, "Running channel in participant");
                         channel
                             .run(protocol, w2b_frames_s, leftover_cid_frame)
+                            .instrument(tracing::info_span!("", ?cid))
                             .await;
                         #[cfg(feature = "metrics")]
                         self.metrics
diff --git a/network/src/protocols.rs b/network/src/protocols.rs
index 687e1d8885..a40e218e2d 100644
--- a/network/src/protocols.rs
+++ b/network/src/protocols.rs
@@ -80,11 +80,10 @@ impl TcpProtocol {
         } {
             Some(Ok(_)) => false,
             Some(Err(e)) => {
-                debug!(
-                    ?cid,
+                info!(
                     ?e,
-                    "Closing tcp protocol due to read error, sending close frame to gracefully \
-                     shutdown"
+                    "Closing tcp protocol due to read error, pushing close frame (to own \
+                     Channel/Participant) to gracefully shutdown"
                 );
                 w2c_cid_frame_s
                     .send((cid, Frame::Shutdown))
@@ -93,7 +92,7 @@ impl TcpProtocol {
                 true
             },
             None => {
-                trace!(?cid, "shutdown requested");
+                trace!("shutdown requested");
                 true
             },
         }
@@ -119,7 +118,7 @@ impl TcpProtocol {
         macro_rules! read_or_close {
             ($x:expr) => {
                 if TcpProtocol::read_or_close(cid, &stream, $x, w2c_cid_frame_s, &mut end_r).await {
-                    info!("Tcp stream closed, shutting down read");
+                    trace!("read_or_close requested a shutdown");
                     break;
                 }
             };
@@ -228,7 +227,7 @@ impl TcpProtocol {
     ) -> bool {
         match stream.write_all(&bytes).await {
             Err(e) => {
-                debug!(
+                info!(
                     ?e,
                     "Got an error writing to tcp, going to close this channel"
                 );
@@ -255,7 +254,7 @@ impl TcpProtocol {
         macro_rules! write_or_close {
             ($x:expr) => {
                 if TcpProtocol::write_or_close(&mut stream, $x, &mut c2w_frame_r).await {
-                    info!("Tcp stream closed, shutting down write");
+                    trace!("write_or_close requested a shutdown");
                     break;
                 }
             };
diff --git a/network/src/scheduler.rs b/network/src/scheduler.rs
index 000ccd92e7..8aa6dcd6e9 100644
--- a/network/src/scheduler.rs
+++ b/network/src/scheduler.rs
@@ -512,7 +512,11 @@ impl Scheduler {
                     metrics.clone(),
                     send_handshake,
                 );
-                match handshake.setup(&protocol).await {
+                match handshake
+                    .setup(&protocol)
+                    .instrument(tracing::info_span!("handshake", ?cid))
+                    .await
+                {
                     Ok((pid, sid, secret, leftover_cid_frame)) => {
                         trace!(
                             ?cid,
@@ -583,14 +587,18 @@ impl Scheduler {
                             }
                         } else {
                             let pi = &participants[&pid];
-                            trace!("2nd+ channel of participant, going to compare security ids");
+                            trace!(
+                                ?cid,
+                                "2nd+ channel of participant, going to compare security ids"
+                            );
                             if pi.secret != secret {
                                 warn!(
+                                    ?cid,
                                     ?pid,
                                     ?secret,
                                     "Detected incompatible Secret!, this is probably an attack!"
                                 );
-                                error!("Just dropping here, TODO handle this correctly!");
+                                error!(?cid, "Just dropping here, TODO handle this correctly!");
                                 //TODO
                                 if let Some(pid_oneshot) = s2a_return_pid_s {
                                     // someone is waiting with `connect`, so give them their Error
@@ -604,6 +612,7 @@ impl Scheduler {
                                 return;
                             }
                             error!(
+                                ?cid,
                                 "Ufff i cant answer the pid_oneshot. as i need to create the SAME \
                                  participant. maybe switch to ARC"
                             );
@@ -614,7 +623,7 @@ impl Scheduler {
                     Err(()) => {
                         if let Some(pid_oneshot) = s2a_return_pid_s {
                             // someone is waiting with `connect`, so give them their Error
-                            trace!("returning the Err to api who requested the connect");
+                            trace!(?cid, "returning the Err to api who requested the connect");
                             pid_oneshot
                                 .send(Err(std::io::Error::new(
                                     std::io::ErrorKind::PermissionDenied,
@@ -625,7 +634,7 @@ impl Scheduler {
                     },
                 }
             }
-            .instrument(tracing::trace_span!("")),
+            .instrument(tracing::info_span!("")),
         ); /*WORKAROUND FOR SPAN NOT TO GET LOST*/
     }
 }
diff --git a/server/src/events/player.rs b/server/src/events/player.rs
index 306300605e..bc05196f66 100644
--- a/server/src/events/player.rs
+++ b/server/src/events/player.rs
@@ -94,15 +94,16 @@ pub fn handle_client_disconnect(server: &mut Server, entity: EcsEntity) -> Event
             if let Err(e) = block_on(participant.disconnect()) {
                 debug!(
                     ?e,
+                    ?pid,
                     "Error when disconnecting client, maybe the pipe already broke"
                 );
             };
             trace!(?pid, "finished disconnect");
             let elapsed = now.elapsed();
             if elapsed.as_millis() > 100 {
-                warn!(?elapsed, "disconecting took quite long");
+                warn!(?elapsed, ?pid, "disconecting took quite long");
             } else {
-                debug!(?elapsed, "disconecting took");
+                debug!(?elapsed, ?pid, "disconecting took");
             }
         });
     }