Skip to content

Commit 72e2d67

Browse files
authored
status: show the per-path latency the daemon already measures (#45)
The daemon has measured a round trip and a path class on every liveness probe since the connection telemetry landed, and there was no way to read any of it without parsing telemetry.json by hand. That is the exact grepping these counters exist to end. I built the collection and never built the display. fabric status now reports, per peer and per path, the share of probes, the sample count, and the exact mean and maximum. Busiest path first, because which path a peer spends its time on is usually the finding. On the live mesh this makes the roaming signature readable at a glance. hetz holds a direct path 99 percent of the time at 64.8 ms. droppy sits on the relay 78 percent of the time, and its direct path is no better on average and more than twice as bad at the tail, 680.8 ms against 316.0 ms. A PEER IS LISTED ON PROBE EVIDENCE ALONE. The sessions block is keyed off losses, so a peer that has never dropped prints nothing there. Healthy is the normal state, so keying this block the same way would have blanked exactly the peers an operator looks at most and hidden the path evidence on all of them. A test covers the healthy peer specifically. MEAN AND MAX ARE EXACT, AND PERCENTILES ARE DELIBERATELY ABSENT. This first rendered p50 and p90 from the histogram. On live data direct and relay both printed p50 100.0 ms and p90 200.0 ms while their means differed and their maxima differed by more than twice, because the bucket bounds double and both distributions landed in one bucket. The display hid the difference it exists to show. A test pins the exact values and asserts the percentiles stay out. This reports facts and reaches no verdict. Nothing labels a path degraded and nothing changes routing. No classifier, no demotion. 201 lib and 12 bin tests green, 5 new.
1 parent 229cb64 commit 72e2d67

3 files changed

Lines changed: 255 additions & 0 deletions

File tree

CHANGELOG.md

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,31 @@ EXPERIMENTAL, so on-disk formats and the CLI may change without notice.
88

99
### Added
1010

11+
- **`fabric status` reports per-path probe latency.** The daemon had measured a
12+
round trip and a path class on every liveness probe since the connection
13+
telemetry landed, and there was no way to read it but to parse
14+
`telemetry.json` by hand — the exact grepping those counters exist to end.
15+
16+
A new `paths` block reports, per peer and per path, the share of probes, the
17+
sample count, and the exact mean and maximum. The busiest path is listed
18+
first, because which path a peer spends its time on is usually the finding.
19+
On a real mesh this makes the roaming signature legible at a glance: a peer
20+
with a stable address holds a direct path 99% of the time, while a peer behind
21+
a moving address sits on the relay 78% of the time and its direct path is no
22+
better on average and more than twice as bad at the tail.
23+
24+
A peer is listed on probe evidence alone, so a healthy peer that has never
25+
dropped a session still shows its paths — unlike the `sessions` block, which
26+
is keyed off losses.
27+
28+
`mean` and `max` are exact rather than bucketed, and percentiles are
29+
deliberately not reported: the latency buckets double in width, so around
30+
50–200ms two genuinely different paths fall in the same bucket and print
31+
identical percentiles, hiding the difference the table exists to show.
32+
33+
This reports facts and reaches no verdict. Nothing labels a path degraded and
34+
nothing changes routing.
35+
1136
- **Fabric deletes its own old logs.** The daemon wrote one validation log per
1237
day and never removed any of them, so the directory grew without limit for as
1338
long as the daemon ran. One machine had accumulated **2.4 GB across 20 daily

README.md

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -512,6 +512,42 @@ still reports reachable.
512512
A peer with no recorded loss is omitted, and `sessions no losses recorded`
513513
means nothing has dropped since the counters were last reset.
514514

515+
### Which path is this peer actually using?
516+
517+
The peer table above shows one instantaneous ping. `fabric status` also reports
518+
what every probe since daemon start has measured, split by path:
519+
520+
```text
521+
paths
522+
droppy reachable 252/252
523+
relay 78% n=196 mean=83.0ms max=316.0ms
524+
direct 22% n=56 mean=84.7ms max=680.8ms
525+
hetz reachable 252/252
526+
direct 99% n=250 mean=64.8ms max=335.3ms
527+
relay 1% n=2 mean=74.6ms max=76.6ms
528+
```
529+
530+
The busiest path is listed first, because which path a peer spends its time on
531+
is usually the finding. Compare the two rows for one peer, not one peer against
532+
another.
533+
534+
Read the example: `hetz` holds a direct path 99% of the time at 64.8ms — a
535+
stable address. `droppy` sits on the **relay** 78% of the time, and when it does
536+
get a direct path that path is no better on average and far worse at the tail,
537+
680.8ms against 316.0ms. That is what a peer behind a moving address looks like.
538+
539+
Unlike the reconnect percentiles above, these are **exact**: `mean` and `max`
540+
are stored precisely rather than bucketed. Percentiles are deliberately not
541+
reported here — the latency buckets double in width, so around 50–200ms two
542+
genuinely different paths fall into the same bucket and print identical
543+
percentiles, hiding the difference this table exists to show.
544+
545+
This reports facts and reaches no verdict. Nothing here labels a path degraded,
546+
and nothing changes routing based on it.
547+
548+
A peer is listed on probe evidence alone, so a healthy peer that has never
549+
dropped a session still shows its paths.
550+
515551
### Fabric deletes its own old logs
516552

517553
The daemon writes one validation log per day to `<home>/logs/` and **keeps the

src/main.rs

Lines changed: 194 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -935,6 +935,119 @@ mod connection_telemetry_tests {
935935
}
936936
}
937937

938+
fn probed_peer(direct: &[u64], relay: &[u64]) -> PeerTelemetry {
939+
let mut probe_latency = BTreeMap::new();
940+
for (path, samples) in [("direct", direct), ("relay", relay)] {
941+
if samples.is_empty() {
942+
continue;
943+
}
944+
let mut latency = LatencySummary::default();
945+
for micros in samples {
946+
latency.record(*micros);
947+
}
948+
probe_latency.insert(path.to_string(), latency);
949+
}
950+
PeerTelemetry {
951+
probes_reachable: (direct.len() + relay.len()) as u64,
952+
probe_latency,
953+
..PeerTelemetry::default()
954+
}
955+
}
956+
957+
/// A healthy peer must show its paths. This is the whole point.
958+
///
959+
/// The sessions block keys off losses, so a peer that has never dropped
960+
/// prints nothing there. Healthy is the NORMAL state, so keying this block
961+
/// the same way would blank exactly the peers an operator looks at most, and
962+
/// hide the path evidence on every one of them.
963+
#[test]
964+
fn a_peer_with_probes_and_no_losses_still_shows_its_paths() {
965+
let peer = probed_peer(&[80_000, 90_000], &[60_000, 64_000, 66_000]);
966+
assert_eq!(peer.losses, 0, "this fixture must be the healthy case");
967+
let lines = path_latency_lines(&BTreeMap::from([("droppy".to_string(), peer)]));
968+
969+
assert_eq!(lines[0], "paths");
970+
assert!(
971+
lines.iter().any(|line| line.contains("droppy")),
972+
"a peer with no losses must not vanish: {lines:?}"
973+
);
974+
assert!(
975+
lines.iter().any(|line| line.contains("direct")),
976+
"its direct path must be reported: {lines:?}"
977+
);
978+
assert!(
979+
lines.iter().any(|line| line.contains("relay")),
980+
"its relay path must be reported: {lines:?}"
981+
);
982+
}
983+
984+
/// The busiest path comes first, because which path a peer actually spends
985+
/// its time on is the finding rather than a detail.
986+
#[test]
987+
fn the_busiest_path_is_listed_first() {
988+
let peer = probed_peer(&[80_000], &[60_000, 61_000, 62_000]);
989+
let lines = path_latency_lines(&BTreeMap::from([("droppy".to_string(), peer)]));
990+
let relay = lines.iter().position(|l| l.contains("relay")).unwrap();
991+
let direct = lines.iter().position(|l| l.contains("direct")).unwrap();
992+
assert!(relay < direct, "relay carried 3 of 4 probes: {lines:?}");
993+
assert!(lines[relay].contains("75%"), "{}", lines[relay]);
994+
assert!(lines[direct].contains("25%"), "{}", lines[direct]);
995+
}
996+
997+
/// Mean and max are exact; bucketed percentiles are not.
998+
///
999+
/// This shipped briefly reporting p50/p90 from the histogram. On live data
1000+
/// direct and relay both printed `p50=100.0ms p90=200.0ms` while their means
1001+
/// differed and their maxima differed by more than 2x, because the bucket
1002+
/// bounds double and both distributions fell in the same bucket. The display
1003+
/// hid the very difference it exists to show. Pin the exact values so nobody
1004+
/// swaps them back for percentiles that look more precise.
1005+
#[test]
1006+
fn the_reported_latency_is_exact_not_bucketed() {
1007+
// 40ms and 680ms sit in different buckets; their mean, 360ms, sits in
1008+
// neither, so a bucketed statistic could not produce this number.
1009+
let peer = probed_peer(&[40_000, 680_000], &[]);
1010+
let lines = path_latency_lines(&BTreeMap::from([("droppy".to_string(), peer)]));
1011+
let direct = lines.iter().find(|l| l.contains("direct")).unwrap();
1012+
assert!(
1013+
direct.contains("mean=360.0ms"),
1014+
"mean must be the exact average, got {direct}"
1015+
);
1016+
assert!(
1017+
direct.contains("max=680.0ms"),
1018+
"max must be the exact largest sample, got {direct}"
1019+
);
1020+
assert!(
1021+
!direct.contains("p50") && !direct.contains("p90"),
1022+
"bucketed percentiles collapse distinct paths together: {direct}"
1023+
);
1024+
}
1025+
1026+
/// A peer that never answered still has something worth reporting.
1027+
#[test]
1028+
fn an_unreachable_peer_reports_its_reachability_rather_than_vanishing() {
1029+
let peer = PeerTelemetry {
1030+
probes_reachable: 9,
1031+
probes_unreachable: 243,
1032+
..PeerTelemetry::default()
1033+
};
1034+
let lines = path_latency_lines(&BTreeMap::from([("bluey".to_string(), peer)]));
1035+
assert!(
1036+
lines
1037+
.iter()
1038+
.any(|l| l.contains("bluey") && l.contains("reachable 9/252")),
1039+
"an unreachable peer must still be listed: {lines:?}"
1040+
);
1041+
}
1042+
1043+
#[test]
1044+
fn no_probes_at_all_says_so_rather_than_printing_an_empty_heading() {
1045+
assert_eq!(
1046+
path_latency_lines(&BTreeMap::new()),
1047+
vec!["paths\tno probes recorded".to_string()]
1048+
);
1049+
}
1050+
9381051
/// The README shows this shape and tells an operator how to read it, so a
9391052
/// silent rename here would make the documentation wrong.
9401053
#[test]
@@ -1142,6 +1255,7 @@ fn print_status(
11421255
println!("exec\t{}", if allow_exec { "allowed" } else { "disabled" });
11431256
print_peer_reachability(peers);
11441257
print_connection_telemetry(connection_telemetry);
1258+
print_path_latency(connection_telemetry);
11451259
Ok(())
11461260
}
11471261

@@ -1157,6 +1271,86 @@ fn print_connection_telemetry(telemetry: &BTreeMap<String, PeerTelemetry>) {
11571271
}
11581272
}
11591273

1274+
/// Report the accumulated probe latency for each peer, split by path.
1275+
///
1276+
/// The peer table above shows one instantaneous ping. That single sample cannot
1277+
/// answer the question that matters for a machine that moves networks: is the
1278+
/// direct path to this peer actually better than the relay, and which one is it
1279+
/// spending its time on? The daemon has measured that on every probe since it
1280+
/// started, and until now the only way to read it was to parse `telemetry.json`
1281+
/// by hand — the exact grepping these counters exist to end.
1282+
///
1283+
/// This reports facts and reaches no verdict. It does not label a path degraded
1284+
/// and it changes no routing.
1285+
fn print_path_latency(telemetry: &BTreeMap<String, PeerTelemetry>) {
1286+
for line in path_latency_lines(telemetry) {
1287+
println!("{line}");
1288+
}
1289+
}
1290+
1291+
fn path_latency_lines(telemetry: &BTreeMap<String, PeerTelemetry>) -> Vec<String> {
1292+
// A peer is included on probe evidence alone. Keying this off losses, the
1293+
// way the sessions block does, would blank the healthy peer — and healthy is
1294+
// the normal state, so it is the one that must never be empty.
1295+
let measured: Vec<_> = telemetry
1296+
.iter()
1297+
.filter(|(_, stats)| stats.probes_reachable > 0 || stats.probes_unreachable > 0)
1298+
.collect();
1299+
if measured.is_empty() {
1300+
return vec!["paths\tno probes recorded".to_string()];
1301+
}
1302+
1303+
let mut lines = vec!["paths".to_string()];
1304+
for (peer, stats) in measured {
1305+
let total = stats.probes_reachable + stats.probes_unreachable;
1306+
lines.push(format!(
1307+
" {peer}\treachable {}/{}",
1308+
stats.probes_reachable, total
1309+
));
1310+
1311+
// Busiest path first: which path a peer actually spends its time on is
1312+
// the finding, not an afterthought.
1313+
let mut paths: Vec<_> = stats
1314+
.probe_latency
1315+
.iter()
1316+
.filter(|(_, latency)| latency.samples > 0)
1317+
.collect();
1318+
paths.sort_by(|a, b| b.1.samples.cmp(&a.1.samples).then(a.0.cmp(b.0)));
1319+
1320+
let answered: u64 = paths.iter().map(|(_, latency)| latency.samples).sum();
1321+
for (path, latency) in paths {
1322+
let share = if answered > 0 {
1323+
format!("{:.0}%", 100.0 * latency.samples as f64 / answered as f64)
1324+
} else {
1325+
"-".to_string()
1326+
};
1327+
// Mean and max, not percentiles, and that is deliberate. Latency is
1328+
// stored in buckets whose bounds double, so around 50–200ms two
1329+
// paths that genuinely differ land in the same bucket and print
1330+
// identical percentiles. Live data showed exactly that: direct and
1331+
// relay both reported p50 100.0ms and p90 200.0ms while their means
1332+
// differed and their maxima differed by more than 2x. A number that
1333+
// hides the difference it exists to show is worse than none.
1334+
//
1335+
// Mean and max are both stored exactly, so they are reported exactly.
1336+
lines.push(format!(
1337+
" {path}\t{share}\tn={}\tmean={}\tmax={}",
1338+
latency.samples,
1339+
format_micros(latency.mean_micros()),
1340+
format_micros(Some(latency.max_micros)),
1341+
));
1342+
}
1343+
}
1344+
lines
1345+
}
1346+
1347+
fn format_micros(micros: Option<u64>) -> String {
1348+
match micros {
1349+
Some(micros) => format!("{:.1}ms", micros as f64 / 1000.0),
1350+
None => "-".to_string(),
1351+
}
1352+
}
1353+
11601354
fn connection_telemetry_lines(telemetry: &BTreeMap<String, PeerTelemetry>) -> Vec<String> {
11611355
let recorded: Vec<_> = telemetry
11621356
.iter()

0 commit comments

Comments
 (0)