Skip to content

Format log context only when a line is logged #98

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
WYCLIFF001 wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Format log context only when a line is logged #98

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
34 changes: 24 additions & 10 deletions src/stream/tcp.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -247,7 +247,7 @@ impl IpStackTcpStream {

let sessions = SESSION_COUNTER.fetch_add(1, std::sync::atomic::Ordering::SeqCst).saturating_add(1);
let (seq, ack, state) = { (tcb.get_seq().0, tcb.get_ack().0, tcb.get_state()) };
let l_info = format!("local {{ seq: {seq}, ack: {ack} }}");
let l_info = LocalInfo(seq, ack);
log::debug!("{tuple} {state:?}: {l_info} session begins, total TCP sessions: {sessions}");

stream.spawn_tasks()?;
Expand Down Expand Up @@ -330,7 +330,7 @@ impl AsyncRead for IpStackTcpStream {
{
let mut tcb = self.tcb.lock().unwrap();
let (seq, ack) = (tcb.get_seq().0, tcb.get_ack().0);
let l_info = format!("local {{ seq: {seq}, ack: {ack} }}");
let l_info = LocalInfo(seq, ack);
log::debug!("{network_tuple} {state:?}: [poll_read] {l_info}, session timeout reached, closing forcefully...");
let sender = &self.up_packet_sender;
write_packet_to_device(sender, network_tuple, &tcb, None, ACK | RST, None, None)?;
Expand Down Expand Up @@ -386,8 +386,9 @@ impl AsyncWrite for IpStackTcpStream {

if send_window == 0 || is_full {
self.write_notify.lock().unwrap().replace(cx.waker().clone());
let info = format!("current send window: {send_window}, send buffer full: {is_full}");
log::trace!("{nt} {state:?}: [poll_write] {info}, waiting for the other side to send ACK...");
log::trace!(
"{nt} {state:?}: [poll_write] current send window: {send_window}, send buffer full: {is_full}, waiting for the other side to send ACK..."
);
return Poll::Pending;
}

Expand All @@ -402,7 +403,7 @@ impl AsyncWrite for IpStackTcpStream {
}

let (state, seq, ack) = (tcb.get_state(), tcb.get_seq(), tcb.get_ack());
let l_info = format!("local {{ seq: {seq}, ack: {ack} }}");
let l_info = LocalInfo(seq, ack);
log::trace!("{nt} {state:?}: [poll_write] {l_info} upstream data written to device, len = {payload_len}");

Poll::Ready(Ok(payload_len))
Expand Down Expand Up @@ -569,7 +570,7 @@ async fn tcp_main_logic_loop(

tcb.increase_ack();
let (seq, ack) = (tcb.get_seq().0, tcb.get_ack().0);
let l_info = format!("local {{ seq: {seq}, ack: {ack} }}");
let l_info = LocalInfo(seq, ack);
log::trace!("{network_tuple} {state:?}: {l_info} session begins");
write_packet_to_device(
&up_packet_sender,
Expand Down Expand Up @@ -763,9 +764,12 @@ async fn tcp_main_logic_loop(
let pkt_type = tcb.check_pkt_type(tcp_header, &payload);

let (state, seq, ack) = { (tcb.get_state(), tcb.get_seq(), tcb.get_ack()) };
let (info, len) = (tcp_header_fmt(tcp_header), payload.len());
let l_info = format!("local {{ seq: {seq}, ack: {ack} }}");
log::trace!("{network_tuple} {state:?}: {l_info} {info}, {pkt_type:?}, len = {len}");
let len = payload.len();
let l_info = LocalInfo(seq, ack);
if log::log_enabled!(log::Level::Trace) {
let info = tcp_header_fmt(tcp_header);
log::trace!("{network_tuple} {state:?}: {l_info} {info}, {pkt_type:?}, len = {len}");
}
if pkt_type == PacketType::Invalid {
continue;
}
Expand Down Expand Up @@ -999,7 +1003,7 @@ fn extract_data_n_write_upstream(
read_notify: &std::sync::Arc<std::sync::Mutex<Option<Waker>>>,
) -> std::io::Result<()> {
let (state, seq, ack) = (tcb.get_state(), tcb.get_seq(), tcb.get_ack());
let l_info = format!("local {{ seq: {seq}, ack: {ack} }}");
let l_info = LocalInfo(seq, ack);
if state == TcpState::Closed {
log::debug!("{network_tuple} {state:?}: {l_info} session closed, exiting \"data extraction task\"...");
return Ok(());
Expand Down Expand Up @@ -1030,6 +1034,16 @@ fn extract_data_n_write_upstream(
}

/// Send a TCP packet to the downstream device, with the specified flags, sequence number, and payload.
/// `local { seq, ack }` for log lines, formatted only when a line is actually emitted: the session
/// loop builds one for every packet, whether or not anything is logged.
struct LocalInfo<S, A>(S, A);

impl<S: std::fmt::Display, A: std::fmt::Display> std::fmt::Display for LocalInfo<S, A> {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
write!(f, "local {{ seq: {}, ack: {} }}", self.0, self.1)
}
}

/// The returned value is the length of the `payload` sent, it may be shorter than the length of the incoming parameter `payload`.
pub(crate) fn write_packet_to_device(
up_packet_sender: &PacketSender,
Expand Down