improve tracing and spans in network crate

This commit is contained in:
Marcel Märtens 2020-08-18 13:48:26 +02:00
parent fc10c16fa1
commit b59fc2ff0c
4 changed files with 26 additions and 15 deletions

View File

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

View File

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

View File

@ -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*/
}
}

View File

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