Lochnair-Labs/irtt-rs
2
0 Fork 0
Code Issues 1 Pull Requests 4 Actions 4 Packages Projects Releases 6 Wiki Activity

refactor(cli): harden client output formatter

Browse Source
This commit is contained in:
Nils Andreas Svee committed 2026-06-21 00:10:56 +07:00
1 parent c7d03c0358
commit f72f8fda5a
4 files changed
+446 -86
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

README.md
+8 -6
View File
@@ -116,16 +116,18 @@ irtt-cli <server> --duration 0 --interval 250ms --output machine
Each line represents one client event and starts with an `event` field, for example:
```text
event=echo_sent seq=4 remote=203.0.113.10:2112 client_send_wall_ns=1760000000000000000 bytes=64 send_call_us=10 timer_error_us=2
event=echo_reply seq=4 remote=203.0.113.10:2112 client_send_wall_ns=1760000000000000000 client_receive_wall_ns=1760000000012400000 raw_rtt_us=12400 effective_rtt_us=12100 adjusted_rtt_us=12100 server_receive_wall_ns=1760000000006100000 server_receive_mono_ns=5000006100000 server_send_wall_ns=1760000000006400000 server_send_mono_ns=5000006400000 server_processing_us=300 client_to_server_us=6100 server_to_client_us=6000 server_received_count=5 server_received_window=0x1f dscp=0 ecn=0 kernel_rx_ns=none
```
Consumers should match on `event=...` and read the fields they need. Unknown fields should be ignored.
RTT fields are reported in microseconds. `raw_rtt_us` is the measured client
send-to-receive RTT. `effective_rtt_us` and `adjusted_rtt_us` are signed and may
be negative when server processing exceeds the raw RTT or timing correction
produces a negative adjusted value. When one-way delay fields are present,
`client_to_server_us` and `server_to_client_us` are also signed microseconds and
may be negative due to wall-clock skew.
RTT, send-call, and timer-error fields are reported in microseconds.
`raw_rtt_us` is the measured client send-to-receive RTT. `effective_rtt_us` and
`adjusted_rtt_us` are signed and may be negative when server processing exceeds
the raw RTT or timing correction produces a negative adjusted value. When
one-way delay fields are present, `client_to_server_us` and
`server_to_client_us` are also signed microseconds and may be negative due to
wall-clock skew.
For consumers that only need RTT values, use:
crates/irtt-cli/src/cmd/client/mod.rs
+2 -2
View File
@@ -6,7 +6,7 @@ pub mod summary;
pub use args::{ClientArgs, OutputMode};
pub use output::{
format_event, format_human_event, format_human_event_with_options, HumanEventStats,
HumanIpdvPair, HumanOutputOptions,
format_event, format_event_with_context, format_human_event, format_human_event_with_options,
HumanEventStats, HumanIpdvPair, HumanOutputOptions, RenderContext,
};
pub use run::run_stream;
crates/irtt-cli/src/cmd/client/output.rs
+422 -62
View File
@@ -12,14 +12,37 @@ use irtt_client::{
use super::args::OutputMode;
pub fn format_event(event: &ClientEvent, mode: OutputMode) -> Option<String> {
if matches!(event, ClientEvent::EchoSent { .. }) {
return None;
format_event_with_context(event, RenderContext::new(mode))
}
pub fn format_event_with_context(
event: &ClientEvent,
context: RenderContext<'_>,
) -> Option<String> {
match context.mode {
OutputMode::Human => {
format_human_event_line(event, context.human_stats.cloned(), context.human_options)
}
OutputMode::Simple => format_simple_event(event),
OutputMode::Machine => format_machine_event(event),
OutputMode::RttUs => format_rtt_us_event(event),
}
match mode {
OutputMode::RttUs => format_rtt_us(event),
OutputMode::Human => Some(format_human_event(event, None)),
OutputMode::Machine => Some(format_machine(event)),
OutputMode::Simple => Some(format_simple(event)),
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub struct RenderContext<'a> {
pub mode: OutputMode,
pub human_stats: Option<&'a HumanEventStats>,
pub human_options: HumanOutputOptions,
}
impl RenderContext<'_> {
pub fn new(mode: OutputMode) -> Self {
Self {
mode,
human_stats: None,
human_options: HumanOutputOptions::default(),
}
}
}
@@ -75,9 +98,17 @@ pub fn format_human_event_with_options(
stats: Option<HumanEventStats>,
options: HumanOutputOptions,
) -> String {
format_human_event_line(event, stats, options).unwrap_or_default()
}
fn format_human_event_line(
event: &ClientEvent,
stats: Option<HumanEventStats>,
options: HumanOutputOptions,
) -> Option<String> {
let stats = stats.as_ref();
match event {
let line = match event {
ClientEvent::SessionStarted { remote, token, .. } => {
format!("session started remote={remote} token={token:#x}")
}
@@ -87,7 +118,7 @@ pub fn format_human_event_with_options(
ClientEvent::SessionClosed { remote, token, .. } => {
format!("session closed remote={remote} token={token:#x}")
}
ClientEvent::EchoSent { .. } => String::new(),
ClientEvent::EchoSent { .. } => return None,
ClientEvent::EchoReply {
seq,
rtt,
@@ -135,17 +166,18 @@ pub fn format_human_event_with_options(
ClientEvent::Warning { kind, message, .. } => {
format!("warning kind={} message={message}", warning_kind(*kind))
}
}
};
Some(line)
}
fn format_rtt_us(event: &ClientEvent) -> Option<String> {
fn format_rtt_us_event(event: &ClientEvent) -> Option<String> {
match event {
ClientEvent::EchoReply { rtt, .. } => Some(signed_duration_us(rtt.effective).to_string()),
_ => None,
}
}
fn format_machine(event: &ClientEvent) -> String {
fn format_machine_event(event: &ClientEvent) -> Option<String> {
let mut out = String::new();
match event {
ClientEvent::SessionStarted {
@@ -176,7 +208,23 @@ fn format_machine(event: &ClientEvent) -> String {
write_token(&mut out, *token);
write_wall(&mut out, "event_wall_ns", at.wall);
}
ClientEvent::EchoSent { .. } => {}
ClientEvent::EchoSent {
seq,
remote,
sent_at,
bytes,
send_call,
timer_error,
..
} => {
write_common(&mut out, "echo_sent");
write_seq(&mut out, *seq);
write_remote(&mut out, *remote);
write_wall(&mut out, "client_send_wall_ns", sent_at.wall);
write!(out, " bytes={bytes}").unwrap();
write!(out, " send_call_us={}", duration_us(*send_call)).unwrap();
write!(out, " timer_error_us={}", duration_us(*timer_error)).unwrap();
}
ClientEvent::EchoReply {
seq,
remote,
@@ -260,11 +308,11 @@ fn format_machine(event: &ClientEvent) -> String {
.unwrap();
}
}
out
Some(out)
}
fn format_simple(event: &ClientEvent) -> String {
match event {
fn format_simple_event(event: &ClientEvent) -> Option<String> {
let line = match event {
ClientEvent::SessionStarted { remote, token, .. } => {
format!("session started remote={remote} token={token:#x}")
}
@@ -274,7 +322,7 @@ fn format_simple(event: &ClientEvent) -> String {
ClientEvent::SessionClosed { remote, token, .. } => {
format!("session closed remote={remote} token={token:#x}")
}
ClientEvent::EchoSent { .. } => String::new(),
ClientEvent::EchoSent { .. } => return None,
ClientEvent::EchoReply {
seq,
remote,
@@ -317,7 +365,8 @@ fn format_simple(event: &ClientEvent) -> String {
ClientEvent::Warning { kind, message, .. } => {
format!("warning kind={} message={message}", warning_kind(*kind))
}
}
};
Some(line)
}
fn write_common(out: &mut String, event: &str) {
@@ -533,6 +582,7 @@ fn escape_value(value: &str) -> String {
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},
@@ -549,6 +599,30 @@ mod tests {
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,
@@ -582,6 +656,239 @@ mod tests {
}
}
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!(
@@ -599,58 +906,111 @@ mod tests {
),
None
);
}
#[test]
fn machine_prints_stable_key_value_fields() {
let line = format_event(&reply_event(), OutputMode::Machine).unwrap();
assert!(line.starts_with("event=echo_reply "));
assert!(line.contains("seq=7"));
assert!(line.contains("remote=127.0.0.1:2112"));
assert!(line.contains("client_send_wall_ns=1000000000"));
assert!(line.contains("client_receive_wall_ns=1001500000"));
assert!(line.contains("raw_rtt_us=1500"));
assert!(line.contains("adjusted_rtt_us=1200"));
assert!(line.contains("effective_rtt_us=1200"));
assert!(line.contains("server_processing_us=300"));
assert!(line.contains("server_received_count=9"));
}
#[test]
fn simple_and_human_use_readable_reply_lines() {
assert_eq!(
format_event(&reply_event(), OutputMode::Simple),
Some(
"reply seq=7 remote=127.0.0.1:2112 rtt_us=1200 raw_rtt_us=1500 server_processing_us=300"
.to_owned()
)
format_event(&negative_reply_event(), OutputMode::RttUs),
Some("-200".to_owned())
);
let human = format_event(&reply_event(), OutputMode::Human).unwrap();
assert!(human.starts_with("seq=7 rtt=1.2ms"));
assert!(human.contains("rd=500.0µs"));
assert!(human.contains("sd=400.0µs"));
assert!(human.contains("ipdv=n/a"));
assert!(human.contains("proc=300.0µs"));
assert!(!human.contains("rtt_us="));
}
#[test]
fn echo_sent_is_not_formatted_for_stream_outputs() {
let ts = test_timestamp(Duration::from_secs(1));
let event = ClientEvent::EchoSent {
seq: 1,
remote: test_remote(),
scheduled_at: ts.mono,
sent_at: ts,
bytes: 64,
send_call: Duration::from_micros(10),
timer_error: Duration::ZERO,
};
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::Machine).is_none());
assert!(format_event(&event, OutputMode::Simple).is_none());
assert!(format_event(&event, OutputMode::Machine).is_some());
}
}
crates/irtt-cli/src/cmd/client/run.rs
+14 -16
View File
@@ -9,7 +9,7 @@ use irtt_client::{ClientTimestamp, PacketMeta, RttSample, SignedDuration};
use super::{
args::{ClientArgs, OutputMode},
output::{format_event, format_human_event_with_options, HumanOutputOptions},
output::{format_event_with_context, HumanEventStats, HumanOutputOptions, RenderContext},
};
#[cfg(feature = "stats")]
use crate::shared::client::expected_probe_count;
@@ -132,23 +132,21 @@ impl<W: Write> StreamOutput<'_, W> {
let stats_update = self.stats.process(event);
#[cfg(not(feature = "stats"))]
let stats_update = crate::cmd::client::HumanEventStats::default();
let stats_update = HumanEventStats::default();
let line =
if self.mode == OutputMode::Human && !matches!(event, ClientEvent::EchoSent { .. }) {
#[cfg(feature = "stats")]
let human_stats = stats_update.into();
#[cfg(not(feature = "stats"))]
let human_stats = stats_update;
#[cfg(feature = "stats")]
let human_stats = HumanEventStats::from(stats_update);
#[cfg(not(feature = "stats"))]
let human_stats = stats_update;
Some(format_human_event_with_options(
event,
Some(human_stats),
self.human_options,
))
} else {
format_event(event, self.mode)
};
let line = format_event_with_context(
event,
RenderContext {
mode: self.mode,
human_stats: Some(&human_stats),
human_options: self.human_options,
},
);
if let Some(line) = line {
writeln!(self.out, "{line}")?;