diff --git a/crates/irtt-cli/src/cmd/client/mod.rs b/crates/irtt-cli/src/cmd/client/mod.rs index 70e1e5c..33c7abf 100644 --- a/crates/irtt-cli/src/cmd/client/mod.rs +++ b/crates/irtt-cli/src/cmd/client/mod.rs @@ -6,7 +6,7 @@ pub mod summary; pub use args::{ClientArgs, OutputMode}; pub use output::{ - format_event, format_event_with_context, format_human_event, format_human_event_with_options, - HumanEventStats, HumanIpdvPair, HumanOutputOptions, RenderContext, + format_event, format_human_event, format_human_event_with_options, HumanEventStats, + HumanIpdvPair, HumanOutputOptions, }; pub use run::run_stream; diff --git a/crates/irtt-cli/src/cmd/client/output.rs b/crates/irtt-cli/src/cmd/client/output.rs index bbaf497..bcd0a9f 100644 --- a/crates/irtt-cli/src/cmd/client/output.rs +++ b/crates/irtt-cli/src/cmd/client/output.rs @@ -15,7 +15,7 @@ pub fn format_event(event: &ClientEvent, mode: OutputMode) -> Option { format_event_with_context(event, RenderContext::new(mode)) } -pub fn format_event_with_context( +pub(super) fn format_event_with_context( event: &ClientEvent, context: RenderContext<'_>, ) -> Option { @@ -30,14 +30,14 @@ pub fn format_event_with_context( } #[derive(Debug, Clone, Copy, PartialEq, Eq)] -pub struct RenderContext<'a> { - pub mode: OutputMode, - pub human_stats: Option<&'a HumanEventStats>, - pub human_options: HumanOutputOptions, +pub(super) struct RenderContext<'a> { + pub(super) mode: OutputMode, + pub(super) human_stats: Option<&'a HumanEventStats>, + pub(super) human_options: HumanOutputOptions, } impl RenderContext<'_> { - pub fn new(mode: OutputMode) -> Self { + pub(super) fn new(mode: OutputMode) -> Self { Self { mode, human_stats: None, @@ -298,7 +298,7 @@ fn format_machine_event(event: &ClientEvent) -> Option { } ClientEvent::Warning { kind, message, at } => { write_common(&mut out, "warning"); - write_wall(&mut out, "at", at.wall); + write_wall(&mut out, "event_wall_ns", at.wall); write!( out, " warning_kind={} message={}", @@ -577,440 +577,3 @@ fn escape_value(value: &str) -> String { .replace('\r', "\\r") .replace('\t', "\\t") } - -#[cfg(test)] -mod tests { - use super::*; - use irtt_client::{ClientTimestamp, OneWayDelaySample, PacketMeta, ReceivedStatsSample}; - use irtt_proto::Params; - use std::{ - net::{IpAddr, Ipv4Addr, SocketAddr}, - time::{Instant, UNIX_EPOCH}, - }; - - fn test_timestamp(offset: Duration) -> ClientTimestamp { - ClientTimestamp { - wall: UNIX_EPOCH + offset, - mono: Instant::now() + offset, - } - } - - fn test_remote() -> SocketAddr { - SocketAddr::new(IpAddr::V4(Ipv4Addr::LOCALHOST), 2112) - } - - fn negotiated() -> NegotiatedParams { - let mut params = Params::with_protocol_defaults(); - params.duration_ns = 10_000_000_000; - params.interval_ns = 250_000_000; - params.length = 64; - NegotiatedParams { - params, - restrictions: Vec::new(), - } - } - - fn sent_event() -> ClientEvent { - let ts = test_timestamp(Duration::from_secs(1)); - ClientEvent::EchoSent { - seq: 7, - remote: test_remote(), - scheduled_at: ts.mono, - sent_at: ts, - bytes: 64, - send_call: Duration::from_micros(10), - timer_error: Duration::from_micros(2), - } - } - - fn reply_event() -> ClientEvent { - ClientEvent::EchoReply { - seq: 7, - remote: test_remote(), - sent_at: test_timestamp(Duration::from_secs(1)), - received_at: test_timestamp(Duration::from_secs(1) + Duration::from_micros(1500)), - rtt: RttSample { - raw: Duration::from_micros(1500), - adjusted: Some(SignedDuration::from_nanos(1_200_000)), - effective: SignedDuration::from_nanos(1_200_000), - }, - server_timing: Some(ServerTiming { - receive_wall_ns: Some(1_000), - receive_mono_ns: Some(2_000), - send_wall_ns: Some(301_000), - send_mono_ns: Some(302_000), - midpoint_wall_ns: None, - midpoint_mono_ns: None, - processing: Some(Duration::from_micros(300)), - }), - one_way: Some(OneWayDelaySample { - client_to_server: Some(SignedDuration::from_nanos(400_000)), - server_to_client: Some(SignedDuration::from_nanos(500_000)), - }), - received_stats: Some(ReceivedStatsSample { - count: Some(9), - window: Some(0x7), - }), - bytes: 64, - packet_meta: PacketMeta::default(), - } - } - - fn negative_reply_event() -> ClientEvent { - ClientEvent::EchoReply { - seq: 8, - remote: test_remote(), - sent_at: test_timestamp(Duration::from_secs(2)), - received_at: test_timestamp(Duration::from_secs(2) + Duration::from_micros(900)), - rtt: RttSample { - raw: Duration::from_micros(900), - adjusted: Some(SignedDuration::from_nanos(-200_000)), - effective: SignedDuration::from_nanos(-200_000), - }, - server_timing: Some(ServerTiming { - receive_wall_ns: Some(-1_000), - receive_mono_ns: None, - send_wall_ns: Some(1_100_000), - send_mono_ns: None, - midpoint_wall_ns: Some(500_000), - midpoint_mono_ns: None, - processing: Some(Duration::from_micros(1100)), - }), - one_way: Some(OneWayDelaySample { - client_to_server: Some(SignedDuration::from_nanos(-300_000)), - server_to_client: Some(SignedDuration::from_nanos(100_000)), - }), - received_stats: None, - bytes: 64, - packet_meta: PacketMeta { - traffic_class: Some(1), - dscp: Some(0), - ecn: Some(1), - kernel_rx_timestamp: Some(UNIX_EPOCH + Duration::from_secs(3)), - }, - } - } - - fn late_event_with_rtt() -> ClientEvent { - ClientEvent::LateReply { - seq: 3, - highest_seen: 5, - remote: test_remote(), - sent_at: Some(test_timestamp(Duration::from_secs(1))), - received_at: test_timestamp(Duration::from_secs(1) + Duration::from_micros(1700)), - rtt: Some(RttSample { - raw: Duration::from_micros(1700), - adjusted: None, - effective: SignedDuration::from_nanos(1_700_000), - }), - server_timing: None, - one_way: Some(OneWayDelaySample { - client_to_server: None, - server_to_client: Some(SignedDuration::from_nanos(800_000)), - }), - received_stats: Some(ReceivedStatsSample { - count: Some(11), - window: Some(0xb), - }), - bytes: 64, - packet_meta: PacketMeta::default(), - } - } - - fn late_event_without_rtt() -> ClientEvent { - ClientEvent::LateReply { - seq: 2, - highest_seen: 5, - remote: test_remote(), - sent_at: None, - received_at: test_timestamp(Duration::from_secs(1) + Duration::from_micros(1700)), - rtt: None, - server_timing: None, - one_way: None, - received_stats: None, - bytes: 64, - packet_meta: PacketMeta::default(), - } - } - - fn warning_event(message: &str) -> ClientEvent { - ClientEvent::Warning { - kind: WarningKind::WrongToken, - message: message.to_owned(), - at: test_timestamp(Duration::from_secs(4)), - } - } - - fn assert_line(event: &ClientEvent, mode: OutputMode, expected: &str) { - assert_eq!(format_event(event, mode), Some(expected.to_owned())); - } - - #[test] - fn human_formats_rendered_events() { - assert_line( - &ClientEvent::SessionStarted { - remote: test_remote(), - token: 0xabc, - negotiated: negotiated(), - at: test_timestamp(Duration::from_secs(1)), - }, - OutputMode::Human, - "session started remote=127.0.0.1:2112 token=0xabc", - ); - assert_line( - &ClientEvent::NoTestCompleted { - remote: test_remote(), - negotiated: negotiated(), - at: test_timestamp(Duration::from_secs(1)), - }, - OutputMode::Human, - "no-test completed remote=127.0.0.1:2112", - ); - assert_line( - &ClientEvent::SessionClosed { - remote: test_remote(), - token: 0xabc, - at: test_timestamp(Duration::from_secs(1)), - }, - OutputMode::Human, - "session closed remote=127.0.0.1:2112 token=0xabc", - ); - assert_line( - &reply_event(), - OutputMode::Human, - "seq=7 rtt=1.2ms rd=500.0µs sd=400.0µs ipdv=n/a proc=300.0µs", - ); - assert_line( - &ClientEvent::EchoLoss { - seq: 9, - sent_at: test_timestamp(Duration::from_secs(1)), - timeout_at: Instant::now(), - }, - OutputMode::Human, - "loss seq=9", - ); - assert_line( - &ClientEvent::DuplicateReply { - seq: 7, - remote: test_remote(), - received_at: test_timestamp(Duration::from_secs(2)), - bytes: 64, - }, - OutputMode::Human, - "duplicate seq=7 remote=127.0.0.1:2112", - ); - assert_line( - &late_event_with_rtt(), - OutputMode::Human, - "late seq=3 highest_seen=5 remote=127.0.0.1:2112 rtt=1.7ms rd=800.0µs sd=n/a ipdv=n/a server_received=11 server_window=0xb", - ); - assert_line( - &late_event_without_rtt(), - OutputMode::Human, - "late seq=2 highest_seen=5 remote=127.0.0.1:2112", - ); - assert_line( - &warning_event("token mismatch"), - OutputMode::Human, - "warning kind=wrong_token message=token mismatch", - ); - assert_eq!(format_event(&sent_event(), OutputMode::Human), None); - } - - #[test] - fn human_uses_stats_ipdv_decoration_and_verbose_stats() { - let stats = HumanEventStats { - contributed_sample: true, - ipdv_pairs: vec![HumanIpdvPair { - previous_seq: 6, - current_seq: 7, - rtt_ipdv: Duration::from_micros(50), - send_ipdv: None, - receive_ipdv: None, - }], - }; - assert_eq!( - format_event_with_context( - &reply_event(), - RenderContext { - mode: OutputMode::Human, - human_stats: Some(&stats), - human_options: HumanOutputOptions { verbose: true }, - }, - ), - Some( - "seq=7 rtt=1.2ms rd=500.0µs sd=400.0µs ipdv=50.0µs proc=300.0µs server_received=9 server_window=0x7" - .to_owned() - ) - ); - } - - #[test] - fn simple_formats_rendered_events() { - assert_line( - &reply_event(), - OutputMode::Simple, - "reply seq=7 remote=127.0.0.1:2112 rtt_us=1200 raw_rtt_us=1500 server_processing_us=300", - ); - assert_line( - &ClientEvent::EchoLoss { - seq: 9, - sent_at: test_timestamp(Duration::from_secs(1)), - timeout_at: Instant::now(), - }, - OutputMode::Simple, - "loss seq=9", - ); - assert_line( - &ClientEvent::DuplicateReply { - seq: 7, - remote: test_remote(), - received_at: test_timestamp(Duration::from_secs(2)), - bytes: 64, - }, - OutputMode::Simple, - "duplicate seq=7 remote=127.0.0.1:2112", - ); - assert_line( - &late_event_with_rtt(), - OutputMode::Simple, - "late seq=3 highest_seen=5 remote=127.0.0.1:2112 rtt_us=1700", - ); - assert_line( - &late_event_without_rtt(), - OutputMode::Simple, - "late seq=2 highest_seen=5 remote=127.0.0.1:2112", - ); - assert_line( - &warning_event("token mismatch"), - OutputMode::Simple, - "warning kind=wrong_token message=token mismatch", - ); - assert_eq!(format_event(&sent_event(), OutputMode::Simple), None); - } - - #[test] - fn rtt_us_prints_only_effective_reply_rtt() { - assert_eq!( - format_event(&reply_event(), OutputMode::RttUs), - Some("1200".to_owned()) - ); - assert_eq!( - format_event( - &ClientEvent::Warning { - kind: WarningKind::WrongToken, - message: "bad".to_owned(), - at: ClientTimestamp::now() - }, - OutputMode::RttUs - ), - None - ); - assert_eq!( - format_event(&negative_reply_event(), OutputMode::RttUs), - Some("-200".to_owned()) - ); - } - - #[test] - fn machine_formats_lifecycle_events() { - assert_line( - &ClientEvent::SessionStarted { - remote: test_remote(), - token: 0xabc, - negotiated: negotiated(), - at: test_timestamp(Duration::from_secs(1)), - }, - OutputMode::Machine, - "event=session_started remote=127.0.0.1:2112 token=0xabc event_wall_ns=1000000000 duration_ns=10000000000 interval_ns=250000000 payload_length=64", - ); - assert_line( - &ClientEvent::NoTestCompleted { - remote: test_remote(), - negotiated: negotiated(), - at: test_timestamp(Duration::from_secs(1)), - }, - OutputMode::Machine, - "event=no_test_completed remote=127.0.0.1:2112 event_wall_ns=1000000000 duration_ns=10000000000 interval_ns=250000000 payload_length=64", - ); - assert_line( - &ClientEvent::SessionClosed { - remote: test_remote(), - token: 0xabc, - at: test_timestamp(Duration::from_secs(1)), - }, - OutputMode::Machine, - "event=session_closed remote=127.0.0.1:2112 token=0xabc event_wall_ns=1000000000", - ); - } - - #[test] - fn machine_formats_reply_and_diagnostic_events() { - assert_line( - &sent_event(), - OutputMode::Machine, - "event=echo_sent seq=7 remote=127.0.0.1:2112 client_send_wall_ns=1000000000 bytes=64 send_call_us=10 timer_error_us=2", - ); - assert_line( - &reply_event(), - OutputMode::Machine, - "event=echo_reply seq=7 remote=127.0.0.1:2112 client_send_wall_ns=1000000000 client_receive_wall_ns=1001500000 raw_rtt_us=1500 effective_rtt_us=1200 adjusted_rtt_us=1200 server_receive_wall_ns=1000 server_receive_mono_ns=2000 server_send_wall_ns=301000 server_send_mono_ns=302000 server_processing_us=300 client_to_server_us=400 server_to_client_us=500 server_received_count=9 server_received_window=0x7 traffic_class=none dscp=none ecn=none kernel_rx_ns=none", - ); - assert_line( - &ClientEvent::EchoLoss { - seq: 9, - sent_at: test_timestamp(Duration::from_secs(1)), - timeout_at: Instant::now(), - }, - OutputMode::Machine, - "event=loss seq=9 client_send_wall_ns=1000000000 warning=loss", - ); - assert_line( - &ClientEvent::DuplicateReply { - seq: 7, - remote: test_remote(), - received_at: test_timestamp(Duration::from_secs(2)), - bytes: 64, - }, - OutputMode::Machine, - "event=duplicate seq=7 remote=127.0.0.1:2112 client_receive_wall_ns=2000000000 warning=duplicate", - ); - assert_line( - &late_event_with_rtt(), - OutputMode::Machine, - "event=late seq=3 remote=127.0.0.1:2112 highest_seen=5 client_send_wall_ns=1000000000 client_receive_wall_ns=1001700000 raw_rtt_us=1700 effective_rtt_us=1700 server_to_client_us=800 server_received_count=11 server_received_window=0xb traffic_class=none dscp=none ecn=none kernel_rx_ns=none warning=late", - ); - assert_line( - &late_event_without_rtt(), - OutputMode::Machine, - "event=late seq=2 remote=127.0.0.1:2112 highest_seen=5 client_receive_wall_ns=1001700000 traffic_class=none dscp=none ecn=none kernel_rx_ns=none warning=late", - ); - } - - #[test] - fn machine_escapes_warning_messages() { - assert_line( - &warning_event("bad token\tline one\nline two\\tail"), - OutputMode::Machine, - "event=warning at=4000000000 warning_kind=wrong_token message=bad\\stoken\\tline\\sone\\nline\\stwo\\\\tail", - ); - } - - #[test] - fn machine_preserves_negative_signed_timing_values() { - assert_line( - &negative_reply_event(), - OutputMode::Machine, - "event=echo_reply seq=8 remote=127.0.0.1:2112 client_send_wall_ns=2000000000 client_receive_wall_ns=2000900000 raw_rtt_us=900 effective_rtt_us=-200 adjusted_rtt_us=-200 server_receive_wall_ns=-1000 server_send_wall_ns=1100000 server_midpoint_wall_ns=500000 server_processing_us=1100 client_to_server_us=-300 server_to_client_us=100 traffic_class=1 dscp=0 ecn=1 kernel_rx_ns=3000000000", - ); - } - - #[test] - fn echo_sent_is_suppressed_except_machine_output() { - let event = sent_event(); - assert!(format_event(&event, OutputMode::RttUs).is_none()); - assert!(format_event(&event, OutputMode::Human).is_none()); - assert!(format_event(&event, OutputMode::Simple).is_none()); - assert!(format_event(&event, OutputMode::Machine).is_some()); - } -}