fix(spammer): timestamp catch-up blocks individually - #229
Conversation
`catch_up_scan` propagated the `received_at` of the notification that triggered the scan to every block it fetched, so all N blocks recovered after a subscriber reconnect shared one observation time. The latency tracker uses `BlockEvent::received_at` as the finalization observation time for every transaction in the block, so a gap covering N blocks reported N identical latencies anchored at the reconnect moment. That both flattens the latency distribution and skews it: blocks fetched late in the scan are credited with an observation time from before they were fetched. Capture `timestamp_now()` per block inside the scan loop instead. The notification path is unchanged and still uses the header-arrival time. Fixes circlefin#128 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
osr21
left a comment
There was a problem hiding this comment.
Read the full diff and the surrounding block_stream.rs at cfe96be0 against #128. The fix is exactly the issue's suggested shape, and the details are right in ways that are easy to get wrong:
- Timestamp placement is correct.
timestamp_now()is captured afterfetch_blockreturns, not before the fetch — so retry/backoff time insidefetch_blockis included in the observation moment. That's the truthful semantics: the block genuinely wasn't observed until the fetch succeeded. - Dropping the
received_atparameter (not just ignoring it) is the right call — it makes the "one notification timestamp fans out to N blocks" mistake unrepresentable at the call site rather than merely avoided. - The
BlockEvent::received_atdoc update matters as much as the code change — the field now has two provenance modes (header arrival vs. fetch time), and documenting that at the struct is what keeps downstream consumers honest about it. - Leaving the on-chain-timestamp TODO in place is correct scoping. Switching to block timestamps changes what the metric measures (network-wide propagation vs. this-observer latency); this PR only fixes the collapsing bug within the current definition.
One interpretation note worth recording for whoever consumes this data (not a change request): with this fix, catch-up blocks report honest observation latency — but that is now recovery latency, not propagation latency. The Nth block in a gap scan carries the serial fetch cost of the N−1 blocks before it, so a reconnect after a long gap will produce a run of high-latency samples that reflect the scan, not the network. That's strictly better than the old behavior (which fabricated identically-low latencies anchored before the blocks were even fetched), but the two failure directions are opposite: before the fix gap scans flattened and understated; after it they legitimately inflate. If the latency pipeline ever needs to separate the two populations, a catch_up: bool on BlockEvent (or an event-source tag) would let the tracker segregate or drop scan samples — cheap to add later and only if the data shows it matters; the TODO about block timestamps is the other road to the same destination.
On the missing unit test — agree with the reasoning, and the flakiness caution is half right. "Timestamps differ" would indeed be flaky at millisecond resolution, but the property actually worth pinning is monotonic non-decrease within a scan plus each timestamp ≥ its fetch completion, which is not flaky. That said, it still requires the trait seam over the block-fetch call to exercise, and bolting a mock WebSocket layer onto a crate whose test style is pure-function units is a bigger change than this two-line fix warrants. Deferring is the right call; if the seam ever gets introduced for other reasons, the monotonicity assertion is the test to write.
Approving — minimal diff, correct semantics, honest about its own limits.
Summary
catch_up_scanpropagated thereceived_atof the notification that triggered the scan to every block it fetched, so all N blocks recovered after a subscriber reconnect shared a single observation time.Fixes #128.
Why it matters
BlockEvent::received_atis whatLatencyTrackeruses as the finalization observation time for every transaction in the block (tracker.rs,scan_and_record_block(&evt.block, evt.received_at)). So a reconnect gap covering N blocks did not just flatten the latency distribution — it skewed it:Since the whole point of the spammer's latency pipeline is to measure when blocks were observed, a gap scan silently degrades exactly the data the tool exists to produce.
Change
Capture
timestamp_now()per block inside the scan loop, and drop the now-unusedreceived_atparameter fromcatch_up_scan. This is the fix suggested in the issue.The notification path is unchanged and still uses the header-arrival time from
HeaderNotification::received_at— that timestamp is genuinely the arrival moment for those blocks, so it remains the more accurate source there.The pre-existing
TODO: should we use the blocks' timestamps?is left in place: switching to on-chain block timestamps is a separate question about what the metric should measure, and this PR only removes the collapsing behaviour.Testing
cargo fmt --all --check,cargo clippy -p spammer --all-targets --all-features -- -D warnings, andcargo test -p spammerall pass locally.I did not add a unit test, and wanted to flag the reasoning rather than leave it unexplained:
catch_up_scantakes a concrete&mut WsClient, so exercising it needs a mock WebSocket server, which is a larger change than this fix and does not match the existing test style incrates/spammer(unit tests over pure functions). Asserting "timestamps differ" would also be flaky, sincetimestamp_now()has millisecond resolution and a fast scan can legitimately produce equal values.Happy to add a test if you would like one — introducing a small trait seam over the block-fetch call would make the loop testable without a live client. Let me know which direction you prefer.