Each scpcap invocation now starts its log fresh. Appending meant a re-run
after a failed attempt mixed new output in with (or could be mistaken for)
stale output from the previous run -- confusing when diagnosing exactly
this kind of issue in production.
Root cause of the production hang reported after the previous fix:
refresh_tail unconditionally replaced the chunker's entire `pending` buffer
with the fresh read, discarding pending[..complete_len] -- content already
confirmed real but not yet drained (anything under the 256KiB emit target).
Since a fresh read always starts exactly at confirmed_len (past that
already-confirmed prefix), the next rescan() started from complete_len=0
within a buffer that no longer contained the records needed to reprove it,
silently regressing confirmed_len. In a small buffer this just caused
wasteful oscillation (each poll's full remaining read happened to
re-derive the same progress); at production scale, once a poll's window
failed to independently re-establish the same high-water mark (e.g. capped
by READ_WINDOW, or landing on an unlucky boundary), confirmed_len could
regress and then get permanently wedged well behind the real write cursor,
manifesting as a "torn/corrupt" bail with confirmed_len frozen at a value
far below the real content size, despite the source visibly still growing.
Fix: refresh_tail now truncates pending to complete_len (keeping the
confirmed-but-undrained prefix intact) before appending the fresh bytes,
instead of replacing pending wholesale. Added a regression test
(refresh_tail_never_discards_already_confirmed_undrained_content) that
fails against the old behavior and passes against the fix -- verified by
temporarily reverting the fix and confirming the test catches it.
Also add verbose (deliberately noisy for now) tail.rs diagnostics: a log
line on every confirmed_len advance, and a throttled "stuck" line
(including a byte preview of what's at the confirmed boundary and whether
it changed since the last check) whenever there's more to read but nothing
validates -- both before and after rename, where previously there was no
progress visibility at all before rename was observed. This is what
surfaced the bug: real production logs showed confirmed_len permanently
frozen at a fixed byte count for 4+ minutes while the source kept growing,
which is inconsistent with the "held back by one record" design and
pointed straight at a state-management bug rather than a writer-side or
filesystem-caching issue.
scripts/regression_test.sh exercises both writer behaviors -- normal
append-only growth (the original, must-keep-working case) and preallocated
growth (ftruncate-extend then shrink-and-rename, the case that caused the
hang/corruption fixed in the previous commit) -- in both transfer
directions, against a real ssh test host with a real capture file sliced to
a record-aligned prefix. scripts/pcap_offsets.py computes record-boundary
cut points for staging realistic growth.
Bump FINALIZE_GRACE_PERIOD from 500ms to 1s: a comfortable margin even for
a writer whose header and payload writes aren't atomic -- if the header
landed, the body should follow shortly.
A preallocating capture writer (ftruncate-extend, zero-filled) reports the
full reserved file size immediately and fills real data into it in place,
without file length ever reflecting real progress until a final truncate at
rotation. The tailer trusted raw file length for both "is there new data"
and "are we done", so it read (and, in raw mode, forwarded) preallocated
zero padding as real packet data, then could never satisfy pos == file_len
once the file was truncated down at rotation -- a permanent hang, and worse,
a corrupted destination even when the hang didn't bite.
Replace file-length-based tracking with confirmed_len(), derived from
actually walking pcap records (RecordAlignedChunker), for any partial
(still-growing) source -- non-compress non-partial transfers are untouched,
preserving today's "arbitrary content" guarantee there. Growth detection now
re-reads from the last confirmed boundary every poll rather than only ever
reading forward past what's already been read, since a preallocating writer
can flip a byte from zero to real content without file length ever changing.
Two correctness properties enforced by the new record scanner, both gated to
partial sources only:
- A record's header being fully present and plausible is not proof its
payload is real (header and payload aren't necessarily written
atomically) -- a candidate record is only confirmed once the *next*
record's header has also been observed and looks real, proof the writer
moved past it. This holds complete_len one record behind by construction.
- That rule alone would starve the true last record of any capture forever,
so a narrow escape hatch trusts the trailing record on its own
plausibility once the rename has been observed and the file's length has
been stable across continuous re-checks for a grace period -- backed by
the writer's own "I'm done" signal (the rename), not a timing guess alone.
Also: an all-zero global header on a partial source is now treated as "not
written yet" rather than a hard error, for the same preallocation reason.
Verified against a live preallocation simulation over ssh (locl.sh): a
source truncated to a padded size well beyond its real content, with a
writer catch-up (in-place record write with no length change) before the
final truncate-and-rename, transfers with no hang and a byte-exact
destination -- confirmed_len stalls precisely at the real/padding boundary
and only advances once content, not file length, proves growth.
Adds an optional timestamped trace of transfer-relevant events (tail
position vs. file length, rename detection, finalize, protocol
send/recv) to both the client and server sides, so a stalled transfer
can be diagnosed from correlated local/remote logs instead of guessing.
Notably logs when a source's final size ends up smaller than what was
already read (pos > current_len after rename) -- this can never
satisfy the pos == current_len finalize condition, which is a real
deadlock risk for writers that preallocate a fixed-size file and
truncate down to the actual capture length before renaming.
--log <path> on either the client or `--server` process traces that
process's own events. --log on ClientCli is local-only; --remote-log
<path> is forwarded as the spawned --server process's --log so both
sides of a remote transfer leave a trace, tied together by timestamp.
ServerCli has no --extension field -- run_send_server already gets
fully-resolved --partial and --final-source from the client, so the
extension is never needed remotely. Passing it made every remote-source
pull fail with "unexpected argument '--extension' found".
scp's "host:" (no path after the colon) means the remote home
directory, reusing the source's basename. resolve_dest_paths only
recognized a directory target via a trailing '/', so an empty path
fell through and was used literally as the filename, producing an
empty --dest-final and hanging the remote --server --recv.
eric