Anchor-pair audit fires on every client: radiod's (gps_time, rtp_timesnap) self-disagrees by ~ms routinely, hundreds of ms at worst

[mijahauan]

Summary

The anchor-pair self-consistency audit added in c5bf01e (status_listener.py:432-467,
written as an instrument for HamSCI/hf-timestd#7) has now accumulated 24 h of data on
AC0G-B4, and it is reporting a real, host-wide inconsistency rather than the 20 ms
quantisation it was built to look for.

Every sigmond client on the box sees it independently: wspr-recorder, psk-recorder,
meteor-scatter and timestd-core-recorder each log their own audit against their own
channels, and all four show the same shape. This is radiod's published
(gps_time, rtp_timesnap) pair disagreeing with itself, surfaced through four unrelated
consumers — not a defect in any one recorder.

Evidence (AC0G-B4, 2026-08-15 → 08-16)

Max disagreement observed per process lifetime:

client	max disagreement
timestd-core-recorder	−72 689.666 ms (Aug 15 11:08)
psk-recorder	+357.758 ms / +203.874 ms / −165.401 ms
wspr-recorder	+292.911 ms / +219.286 ms / +141.621 ms / −111.217 ms / +85.367 ms
meteor-scatter	+171.919 ms / +166.094 ms / −120.700 ms

The bulk distribution is consistent across all four clients and all lifetimes — here
wspr-recorder at n=224 758 updates:

delta_ms histogram = [(0, 83909), (-1, 62946), (1, 34200), (2, 21008),
                      (-2, 11814), (3, 4572), (-3, 1672), (4, 933)]

Two things stand out:

1. The typical disagreement is ±1–4 ms, not 0. The audit's own docstring argues it
   should be nanoseconds — the ADC is GPSDO-disciplined, so advancing rtp_timesnap by
   n samples must advance gps_time by n/sample_rate. Milliseconds of routine
   disagreement is 6 orders of magnitude off that expectation. Whether that is real
   epoch noise or an artefact of when radiod snapshots the two halves of the pair is
   exactly the open question.
2. The distribution is asymmetric — 0 > −1 > +1 > +2 > −2 > +3 > −3 > +4, reproduced
   independently on all four clients. Noise about a correct anchor should be symmetric.
   A skew toward negative-then-positive-tail looks like a sampling-phase effect.
3. It is NOT 20 ms-quantised. The hypothesis the audit was built to test — that
   consecutive pairs disagree in whole radiod blocks — is not what the data shows. Worth
   recording as a negative result for hf-timestd#7.

The −72.7 s excursion on timestd-core-recorder at Aug 15 11:08 correlates with a
disturbed window on that host: wspr-recorder logged two gross timing faults at 11:04 and
11:24 (slot ... finished 87.7s BEFORE its nominal end) and the dt-guard re-anchored
17 band recorders. Something re-dated the timeline in that window and the audit caught it.

Why it matters here

rtp_to_utc() and every sub-second timestamp downstream of it rest on this pair. hf-timestd
additionally feeds it into the BPSK chain delay and the chrony SHM reference time. If the
pair is routinely inconsistent at the ms level, that is a floor under every timing claim the
suite makes, and it is invisible to consumers today because nothing but this audit checks it.

Defect in the instrument itself

_anchor_audit['max_ns'] is a running max that never resets and never ages out, and the
logger emits at WARNING every 60 s for the life of the process. The practical effect is that
a single excursion 20 h ago is re-reported 1 200 times as though it were current — the B4
journal shows max_disagreement=+292.911 ms repeated identically across every sample I took
between 09:23 and 09:49, long after the event.

So the audit cannot answer "is this happening now", which is the question an operator
actually has. Suggested: keep a windowed max (or log the delta that triggered a new max,
with its timestamp) and drop the steady-state line to INFO/DEBUG, reserving WARNING for a
fresh excursion above threshold.

Asks

1. Decide whether ms-scale routine disagreement is genuine or an artefact of radiod's status
   snapshot — i.e. are gps_time and rtp_timesnap captured atomically on the radiod side?
   That determines whether this is a ka9q-radio report or a ka9q-python interpretation fix.
2. Explain the asymmetry in the histogram; it is reproducible and should be diagnostic.
3. Fix the running-max/WARNING behaviour above so the instrument can distinguish live from
   historical.

Related

• T6 MF deterministically acquires a displaced correlation peak (~0.6 s, non-integer) — disambiguation cannot rescue it hf-timestd#7 — the audit was added for it; that issue remains open with a live
  +98 ms HPPS displacement on B4 as of 2026-08-16.
• WSPR/FT8 dt walks ~0.2 s/hr (recorder RTP→UTC anchor slide) — radiod output proven clean wspr-recorder#6 (closed 2026-08-16) — the 0.2 s/hr walk is gone, but dt still
  sits at a nonzero mean (~+0.3 s) with ±0.5 s cycle-to-cycle jitter. Whether that residual
  is downstream of this anchor-pair inconsistency is untested; ms-scale pair noise does not
  obviously account for hundreds of ms of dt jitter, so treat them as separate until linked.

[mijahauan]

Chased the −72.7 s excursion through the B4 journal. There are two separate phenomena
here and the issue body conflates them. Splitting them, because only one is a real signal.

(A) The multi-second excursions are audit false positives across a radiod restart — confirmed

radiod restarted three times on B4 on 2026-08-15: 11:02:41, 11:23:20, 11:39:05
(the last one is the 7fca458a merge; the first two log an empty Git commit hash:, i.e.
the archive-built binary).

Watch timestd-core-recorder pid 2074469 walk straight through the first one:

11:02:17  ANCHOR PAIR AUDIT: updates=415585 max_disagreement=+162515284 ns  (+162.5 ms)
11:02:41  systemd: Started radiod@AC0G-B4.service
11:02:53  WARNING SHARED_2500: No data for 13s - attempting channel recreation (radiod may have restarted)
11:02:55  WARNING SHARED_15000: RTP counter space CHANGED (likely radiod restart)
11:03:17  ANCHOR PAIR AUDIT: updates=416273 max_disagreement=+60637012070891 ns  (+60637 s ≈ 16.8 h)

Same story on wspr-recorder across the 11:39:05 restart: max=+970431192002 (+970 s).

The mechanism is in status_listener.py:432-467: _anchor_audit['prev'][ssrc] is written
unconditionally on every update and never invalidated. register_channel() /
unregister_channel() (lines 234, 246) don't touch it, and nothing subscribes to a restart
signal. SSRCs are deterministic — ensure_channel: computed SSRC 1255670770 for 2.500 MHz
resolves to the same value before and after — so the post-restart pair is compared against a
pre-restart pair under an identical key, and the audit reports the wall-clock gap as a
"disagreement".

Note the irony: the recorder already detects this correctly one layer up
(RTP counter space CHANGED (likely radiod restart)), 22 s before the audit reports 16.8
hours of disagreement. The information exists; the audit just isn't wired to it.

⇒ Every multi-second/minute figure in the table in the issue body is an artefact. Discard
them. Fix: invalidate prev on unregister_channel/register_channel, or carry radiod's
instance identity in the key.

The −72.7 s specifically

Doesn't fit (A) cleanly and I'm flagging it rather than forcing it. Timeline:

11:03:29  systemd: Stopping timestd-core-recorder.service
11:04:59  systemd: State 'stop-sigterm' timed out. Killing. ... SIGKILL (4.4G memory peak,
          Failed with result 'timeout')
11:05:07  [pid 2216981] SHARED_2500: Channel ready ... ANCHOR PAIR AUDIT: updates=1 max=+49167 ns
11:06:07  [pid 2216981] ANCHOR PAIR AUDIT: updates=811 max_disagreement=-72689666087 ns

Fresh process, fresh audit dict (it starts clean at +0.049 ms), and no radiod restart in
that window — 11:02:41 was before it started, 11:23:20 came later. So this is a ~72 s jump
recorded during the 68 s of channel bring-up. Worth noting that 72.7 s falls inside the 90 s
the predecessor spent hung between SIGTERM and SIGKILL, which would fit a stale queued status
packet being processed after a current one, but I have not proven that.

(B) The 100–350 ms excursions are NOT startup transients — this is the real signal

This is what I got wrong in the issue body by treating the running max as one event. Tracing
a single wspr-recorder process from its first update:

11:41:50  n=1       max=  -3.520 ms
11:43:50  n=3324    max=  +6.451 ms
11:44:50  n=5365    max= +20.628 ms
11:45:50  n=7406    max= +85.367 ms
11:50:50  n=17780   max=+146.994 ms
11:55:51  n=28107   max=+219.286 ms
...
14:19:21  n=162653  max=+277.563 ms
19:39:28  n=824985  max=+336.320 ms

The max keeps growing across nine hours and ~800k updates. New maxima are frequent in the
first 15 minutes and progressively rarer after — exactly the signature of a running max
over a stationary heavy-tailed distribution, not a one-off startup artefact. Other
processes land in the same band independently: +401.703 ms, +182.324 ms, +179.096 ms.

So the ±1–4 ms bulk and a continuously-drawn tail out to ~350 ms are one distribution, and
it is being sampled the whole time the box is running normally.

Leading hypothesis: status-packet reordering, not epoch steps

The audit computes its delta purely from packet contents, so a slow client cannot create
one — a stale packet read late is still self-consistent. But packets processed out of
order would produce exactly this: a negative delta of the reorder distance followed by a
compensating positive one. That also accounts for the asymmetric histogram
(0 > -1 > +1 > +2 > -2 > +3 > -3 > +4) that symmetric noise about a correct anchor cannot.

These are multicast UDP status packets with no ordering guarantee, and B4 has known hourly
stalls that would back up a socket buffer. A 300 ms excursion is then a 300 ms reorder/queue
delay, not a 300 ms timeline step.

This is testable and should be tested before anyone reads these numbers as radiod epoch
error: record the packet's own sequence/timestamp alongside the pair and check whether a
large negative delta is immediately followed by a compensating positive one of the same
magnitude. If yes, (B) is a client-side ordering artefact and the audit needs to drop
out-of-order packets. If no, it is a genuine epoch discontinuity and it matters a great deal
for hf-timestd#7.

Revised asks

1. Invalidate prev on channel register/unregister and on detected radiod restart — closes (A).
2. Add ordering detection before interpreting (B); the reordering hypothesis has to be
   falsified first.
3. Windowed max + WARNING only on a fresh excursion (unchanged from the issue body).
4. Until 1–3 land, no number from this audit should be quoted as evidence of radiod epoch
   error, including in hf-timestd#7.

[mijahauan]

Reordering test: REFUTED. The real mechanism is that the pair is not atomic.

Ran the test on B4 — passive capture (read-only multicast join, nothing restarted):
81 600 status packets, 45 SSRCs, 900 s.

T1 — reordering

gps_time went BACKWARDS in arrival order: 0 of 81555 consecutive pairs

Zero. Not one event in 81 600 packets. The hypothesis is dead — and in hindsight it never
had a route: radiod logs Radiod reporting TTL=0 ... Multicast data restricted to localhost loopback only!, so this traffic never leaves the host and loopback UDP does not reorder.

T3 — is there a genuine epoch discontinuity?

Also no. Summing every delta over the full capture, per SSRC:

ssrc 2017889303   cumulative  -2.729 ms over 1776 updates
ssrc 1102219534   cumulative  -2.273 ms over 1834 updates
ssrc 2038191610   cumulative  -1.799 ms over 1778 updates

≤2.7 ms accumulated across ~1800 updates. radiod's timeline is consistent; nothing is
walking. So the excursions are transient skew that cancels, not steps.

T4 — which half of the pair moves?

gps moved      0
rtp moved      144
both/unclear   0

All 144 excursions, unanimously rtp_timesnap. And the quantisation test on the busiest
SSRC (n=1836, sr=12000) shows why:

                          min      p05      med      p95      max
arrival gap dt (s)     0.0001   0.4976   0.4999   0.5024   0.5592
gps_time advance (s)   0.0000   0.4980   0.4998   0.5022   0.5592
rtp advance/sr (s)     0.0000   0.5000   0.5000   0.5000   0.5000

gps_advance - dt : max |err| = 0.003198 s
rtp_advance - dt : max |err| = 0.059222 s

rtp advance, ms buckets: [(500, 1797), (0, 30), (20, 7), (480, 1)]

rtp_timesnap advances in rigid 500 ms quanta (25 blocks × 20 ms) — identical at p05,
median and p95. gps_time advance instead tracks the actual arrival gap to within 3.2 ms,
jitter and all, out to a 559 ms interval.

Confirmed at source

ka9q-radio/src/radio_status.c, encode_radio_status():

int64_t now = gps_time_ns();
encode_int64(&bp, GPS_TIME, now);          // live, read when the packet is built
...
encode_int32(&bp, RTP_TIMESNAP, chan->output.rtp.timestamp);   // cached field

chan->output.rtp.timestamp is the counter advanced in audio.c by frames emitted
(chan->output.rtp.timestamp += frames;). So GPS_TIME is sampled live at packet
construction while RTP_TIMESNAP is whatever the block pipeline last stored. The two halves
are sampled at different instants by construction.

When status emission runs late — scheduler, load, a stall — gps_time absorbs the lateness
and rtp_timesnap does not, because it is still pinned to the block grid. The audit then
reports that lateness as "disagreement".

What this means for the audit

The docstring's premise is wrong:

the ADC is GPSDO-disciplined, so advancing rtp_timesnap by n samples must advance
gps_time by n/sample_rate seconds, to within GPSDO drift (parts in 1e11 — nanoseconds
over this cadence)

That holds only if both are sampled at the same instant. They are not, so the audit's floor
is radiod's status-emission jitter, not GPSDO drift. Everything it has reported is
consistent with that and with nothing else:

observation	explained by
±1–4 ms bulk	ordinary emit jitter
asymmetric histogram	lateness is one-sided — you can be late against the grid, not early
100–350 ms tail	stalls (B4 has known hourly ones)
cumulative ≈ 0	the grid is correct on average; only the sampling instant moves
always rtp_timesnap	it is the cached half

So no number this audit has produced is evidence of radiod epoch error, which settles
ask #4 from my previous comment empirically rather than by assumption.

Worth keeping the instrument — it is measuring something real — but it should be relabelled
for what it actually measures (emit-path skew), and the fixes from earlier still stand:
invalidate prev on register/unregister and radiod restart (ask 1), windowed max instead of
a permanent running one (ask 3). Ask 2 is now answered and can be dropped.

The part that matters downstream

Averaging to zero is cold comfort for a client that anchors once. A one-shot
(gps_time, rtp_timesnap) capture inherits that packet's skew permanently — bounded by how
late radiod's status emission happened to be at that instant. 59 ms was the worst in this
quiet window; the recorders have logged up to 401 ms under load.

Following that up in HamSCI/hf-timestd#7.

Capture + analysis scripts are three short files if anyone wants to reproduce on another
host; they need only a passive multicast join.