Skip to content

Streaming book-diff writer intermittently stalls across the UTC day rollover (00:00) #154

Description

@Mr-Moonsilver

Summary

When run with --write-raw-book-diffs, the node's streaming per-hour book-diff
writer occasionally goes silent starting shortly after 00:00 UTC and does not
resume until at or just before the next hour rotation (01:00), at which point
the new file appears already containing only the tail of the buffered writes.
This is intermittent (2 of 4 observed midnights hit) and produces no error,
warning, or log line of any kind — it is silent on both the node's own journal
and at the OS level. Everything else about the node (chain sync, other capture
streams, the batch/bronze block pipeline) continues normally throughout.

Environment

  • Non-validator node (run-non-validator), mainnet.
  • Flags of interest: --write-raw-book-diffs (plus --write-fills,
    --write-misc-events, --write-order-statuses, --write-hip3-oracle-updates
    — all healthy throughout every incident).
  • Same binary build and same long-running process (no restart) across both a
    clean night and a hit night in one case — rules out a fresh-start or
    version-specific trigger.

Observed behavior (two independent incidents)

2026-07-01 (hit #1): the hour-00 file did not appear until ~00:59:05 (our
consumer's 0.5s-cadence directory scan found nothing newer for the entire hour;
the raw file was age-pruned before we could do direct post-hoc inspection of
it). Our consumer first read data spanning the final ~52s of the hour
(00:59:05–00:59:57).

2026-07-02 (hit #2): the prior hour's file received its final writes
normally (fully drained by our consumer by ~00:00:33), then went completely
silent. The hour-00 file was not created until 00:59:59.7, and direct
post-hoc inspection of it shows it contained only 1,808 rows across 170 coins
spanning 00:59:59.688–00:59:59.947 (~260ms) — i.e. genuinely no backlog in the
file, just the tail of whatever was sitting in a write buffer at the moment the
next hour's rotation forced a flush.

2026-06-30 and 2026-07-03 (clean, for contrast): normal continuous writing
straight across the boundary — e.g. on 07-03 the hour-23 file sealed at
00:00:00.000Z (5,150,401,307 bytes) and the hour-00 file was already
358,129,081 bytes and growing by 00:02:05, continuing at a normal ~250MB/min.

What we ruled out (and how)

  1. Not a process restart / redeploy. Same PID and same binary index served
    both a clean night (2026-06-30) and both hit nights — process freshness is
    not protective, and nothing changed at either the onset or recovery
    boundary of either incident.
  2. Not a full-node hang or crash. Chain sync, RPC, and every other
    streaming capture output (fills, misc-events, TWAP statuses, HIP-3 oracle
    updates) created their own hour-00 files on time on both hit nights,
    confirmed via filesystem birth-time (stat), not just log absence.
  3. Not a downstream/consumer artifact. Our consumer's continuous 0.5s
    directory scan (mtime-based newest-file selection) found no newer file to
    switch to for the entire stall hour — continuous indirect sampling — and
    post-hoc inspection of the Jul-02 hour-00 file confirms it was created at
    00:59:59.7 containing only the final ~260ms. Separately, lsof on the open
    file (same evening) showed the node process holding the fd directly with no
    intermediary process — this is not a shipping, transport, or ingestion-side
    effect.
  4. Not related to the batch/replay-based export path. The separate
    block-file batch pipeline that independently re-derives the same data was
    unaffected both nights — this is isolated to the streaming writer only.
  5. Silent at every observable layer. The node's own journal logged nothing
    writer-related at either incident (no restart, resubscribe, error, or
    buffer-warning lines) — only routine, unrelated per-midnight bookkeeping
    (an EVM-checkpoint prune) at 00:00:00.04 both nights.

Working hypothesis

Something in the streaming writer's day-rollover handling (new date directory
creation + opening the new hour's file) has an intermittent race. The two
different recovery shapes we observed (a large replay-like burst vs. a tiny
buffer-tail flush with no replay) suggest this may not be a single deterministic
bug but a class of related rollover-timing issues, possibly interacting with
how/when the writer's internal buffer gets flushed relative to the new file
being opened.

Questions for the node team

  1. Is this a known issue with the streaming raw-book-diff writer (or the
    day-rollover/file-rotation logic it shares with other writers)?
  2. Is there a way to detect this condition from inside the node process
    (e.g. an internal metric or log line we could opt into) rather than only
    externally via write-silence?
  3. Are there configuration knobs that affect buffer-flush timing around file
    rotation that might make this less likely?

Impact on our side (informational, not asking for a workaround)

Impact is confined to our live/streaming consumption band only — our durable
batch/bronze record is unaffected (see "ruled out" #4). We've deployed
detection (a write-silence watchdog that pages within ~6 minutes of onset) and
consumer-side exclusion windows around the affected minutes; we're not asking
for a workaround, just visibility into whether this is known/tracked.

Raw per-night evidence (byte counts, timestamps, lsof output) is attached as a
follow-up comment below.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions