Skip to content

Fix the collector bugs a retroactive review found - #52

Merged
baz8080 merged 27 commits into
mainfrom
claude/eager-sagan-wn68lr
Sep 24, 2026
Merged

baz8080 merged 27 commits into
mainfrom
claude/eager-sagan-wn68lr

Conversation

@baz8080

@baz8080 baz8080 commented Sep 24, 2026 •

Copy link
Copy Markdown
Owner

Slice 2 of the retroactive review, following #48 and #51: a whole-file review of esb_outages/store.py, poll.py, parse.py and client.py, then three reviews of this PR itself. Each commit holds one fix, and each fix's test was checked to fail without it.

The fixes

  1. A run's final status was never logged. The raw run line is written before the details start, so it could only say ok. rebuild restored every cut_short, partial, schema_drift or mid-run auth_error run as ok. In esb-data the raw runs say ok 2,470 times and nothing else.
    • Store.finish_run now appends an "event": "end" line before writing the run row, carrying only what can't be derived.
    • Start lines say an end line follows ("ends_logged": true). A flagged start with no end line replays as unfinished, or as in_progress if it is the newest run, because the backup commits raw/ mid-run. A failure the start line already logged (auth_error, unreachable) is kept either way.
    • An end line whose start line was lost replays as a run with no list, counting its own fetches.
    • Older runs replay as before.
    • This reverses a gap notes/storms.md had accepted. The owner approved the reversal, and the note records it.
  2. compact could wipe an archived month. Late lines now join the archive as a further gzip member, starting on a fresh line, streamed into a staged file, fsynced and renamed into place before the source is removed. An interrupted compact is safe to repeat, because iter_raw reads a line identical to one already read in the same month (keyed by the month in the file name) once.
  3. rebuild and compact ignored the poll lock. Both now take it.
  4. A cut-off response, or a 404 on the list, killed the whole run. These are now transient or unreachable. The client has its first tests.
  5. Malformed input crashed the run and every rebuild after it. That covers a non-object list item or body, and a non-string timestamp; both are now contained. The logs are read as bytes and each line decoded strictly, so a line torn or corrupted mid-character is one malformed line: never a crash, and never a silently different record. Appends start on a fresh line after a torn one.
  6. The storm fetch order:
    • never-captured Restored outages first;
    • then captured ones still waiting for a restore time, including a captured fault that has just flipped to Restored;
    • then everything live;
    • an id listed twice is fetched once.
  7. An unreadable restore time marked an outage final. Final now needs the parsed time.
  8. Observations that lost their run replayed after all of history. They now replay at their own place in time.
  9. The October clock-change docstring pointed the wrong way.
  10. Counts:
    • A key rejected mid-run now keeps the errors that came before it.
    • rebuild counts listed and fetched outages the way the live run does, which the site's horizon depends on.

Reviews of this PR

  • First review, 10 findings, all fixed. They led to the second half of 1, 2, 5, 6 and 10 above, plus streaming in compact and the orphan-before-run tie.

  • Second review of those nine commits, 10 findings. It found my original unfinished rule unsafe. That rule keyed on the earliest end line in the log, so a merged host or a wrong-clock boot would relabel healthy runs. It was replaced by the start-line flag. The same review led to the repeated-id and per-month dedupe fixes, the torn-mid-character and torn-archive fixes, and the flipped-fault rank.

  • Third review of the next five commits, 9 findings, all fixed except the limits below. Two were real bugs:

    • errors="replace", added to survive a torn fada, turned a line corrupted on the card into a different valid record ("Dún" read back as "D�n"). It's now a strict per-line decode.
    • A start line's auth_error/unreachable was overridden by the unfinished label.

    Also fixed: the dedupe month key, a lost-start run's fetched count (found by the test the review asked for), and redundancy in the tidy-up.

Known limits, not fixed. The in_progress label goes on the newest start line, and a log snapshot holds nothing better:

  • a newest run that really died reads in_progress until the next run logs;
  • runs tied on the newest second all read in_progress;
  • a later-sorting run from a wrong clock or a merged host pushes the real one to unfinished.

Also not taken: the direction of a same-second orphan tie, which the log can't decide, and making compact itself idempotent, since repeats are already read once.

Effect on the data

Rebuilding esb-data with main and with this branch gives identical outage, outage_change and run tables: 4,954 / 7,121 / 2,556 rows, none differing. Nothing the site publishes moves.

Checks

  • ruff check: clean.
  • unittest discover with ESB_DATA_DIR set: 333 tests OK.

🤖 Generated with Claude Code

https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT

The raw run line is written before the details start, so it can only ever
say "ok". A rebuild therefore restored every cut-short, partial, drifted or
mid-run auth-failed run as ok, with no finish time, exit code or error
summary. Store.finish_run now appends an end line first, carrying only what
cannot be derived, and every exit path in poll goes through it. rebuild
prefers the end line where there is one; older runs replay as before.
The run table now round-trips exactly, which a new test holds.

This reverses the gap notes/storms.md had accepted; the note says why.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
compact wrote each archive with "wb", truncating any existing one. A Pi with
no clock battery boots in the past until NTP syncs, so a poll can append to
a month that was already compacted, and the next compact replaced the whole
archived month with those few late lines. The late lines now join the
archive as a further gzip member, written to a staged file, fsynced and
renamed into place before the source is removed, so a power cut in between
can no longer leave an empty archive and no log.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
rebuild deletes esb.db and its -wal and -shm, and compact unlinks the log a
poll appends to, and neither took the poll lock, so `esb rebuild` during a
24-minute storm run could corrupt the database or lose the details the poll
committed after the replay read the logs. Both now take the same lock and
exit 1 with a message while a poll holds it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
IncompleteRead is an HTTPException, not an OSError, and a truncated gzip
body raises EOFError or zlib.error from decompress, so one connection cut
off mid-read escaped the client's taxonomy and took the whole run with it:
no run record, no heartbeat, a traceback. They are now TransientError, and
an undecodable body is an ApiError. A 404 on the list itself, which the
client raises as NotFound, was not caught either; poll and check now treat
it as unreachable. The client had no tests; it has three.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
A list item or body that was not a dict raised AttributeError after its
raw line was already written: the live run died with no record or
heartbeat, and since rebuild replays through the same apply_list, every
later rebuild died on that line too, with editing the log the only way out.
Non-object items are now skipped where they are applied, a non-object list
or detail body is reported as schema drift, and the run carries on.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
ids_needing_detail put anything listed Restored first only until its first
fetch. A Restored body with restoreTime still "" is not final, so on later
runs it fell to rank 3 or 4, or out of the queue once quiet for six hours,
behind every live outage a storm run could reach: ESB could purge it before
its restore time was ever captured. It now stays at rank 0 until final,
which is the order notes/storms.md already describes.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
is_final was set from the raw restoreTime being non-empty. Final means never
fetched again, so a restoreTime ESB sends in a new or broken format would
freeze the outage with no restore time, and the site would read it as
restored at an unknown time until ESB purged it. It now needs the parsed
time. No outage in the corpus to 24 September has an unparsed one.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
fold=0 is the first 01:xx, still on summer time, so a time that was really
the second is stored an hour early, not late; test_dst_fall_back already
pins the value. Only the docstring was wrong.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
rebuild replayed observations with no run record after every run in
history, and apply_detail overwrites state, so an old orphaned body rolled
a later restore back to live and moved last_seen backwards. They now take
their place in the replay by their earliest observed time.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
The PR made a non-object detail survivable, but an object whose startTime,
estRestoreTime or restoreTime was a number or a list still raised on
.strip(), live and on every rebuild after it. Found by review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
With compact now appending to an existing archive, a crash after the rename
but before the source was removed made the next compact archive the same
lines twice, and every rebuild after that counted those runs twice. iter_raw
now drops a line identical to one already read: every line carries its own
timestamps and run id, so a repeat is the same record, which is also what a
`sort -u` merge assumes. The removal is fsynced, and the existing archive
is streamed into the staged file rather than read whole into memory on the
Pi. Found by review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
The settling outages moved to rank 0 earlier in this PR tied with Restored
outages never captured at all, and list order broke the tie, so a storm
with more of them than a run can fetch re-fetched the same head for a
restore time while the uncaptured tail, whose whole record a purge takes,
was lost. They now have their own rank, just behind. Found by review of
this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
The mid-run AuthError path recorded n_errors=1 and only the 401 as its
summary, dropping the transient failures already collected. With rebuild
now trusting the end line, that undercount would have been fixed into the
log. It now counts and names them too. Found by review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
For the malformed inputs this PR survives, rebuild counted every list item
where poll counts only objects, left n_listed NULL for a 200 whose body was
not an object where poll records 0 (which also moved the site's horizon,
read from n_listed), and counted a non-object detail as fetched. The
malformed-response test now holds the run table across a rebuild too.
Found by review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
Runs were concatenated ahead of orphans before a stable sort, so on a tie
the run replayed first and the orphan, whose own run started no later,
overwrote it: the rollback the orphan fix set out to stop. Found by review
of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
Once runs log their end, a start line without one is a run that died
before closing itself out, and a rebuild restored it as a clean ok. It is
now `unfinished`. The reverse, an end line whose start line was damaged,
was silently dropped though its run id carries the start time; it now gets
a row and the rebuild says so. Found by review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
Each run now ends with a write to runs-*.jsonl, so a power cut that tears
that end line would leave the next run's start line, its only copy of the
list, appended to the torn fragment, and iter_raw would skip the two as one
unreadable line. An append after a file that does not end in a newline now
starts with one, and loses only the torn fragment. Found by review of this
PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
@baz8080 baz8080 changed the title Fix nine collector bugs a retroactive review found Fix the collector bugs a retroactive review found Sep 24, 2026
The rule marking a start line without an end line `unfinished` keyed on the
earliest end line anywhere in the log, so a merged log from a host on the
old code, or one early-dated run from a Pi booted without its clock,
relabelled every older-style run after it. Start lines now say an end line
follows, and only those can be unfinished. The newest one reads
`in_progress`: backup-to-git.sh commits raw/ without the poll lock, so the
Pages rebuild often sees a run still going. A run rebuilt from its end line
now replays as a run with no list, so its observations stop being orphans.
Found by a second review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
iter_raw reads an identical line once, which is wrong only if something
writes the same line twice for real: an id ESB lists twice was fetched
twice, and both observations could land in the same second with the same
body. ids_needing_detail now fetches a repeated id once. The set of lines
seen is cleared at each month, since copies only ever share a month's
files, so a rebuild on the Pi no longer holds a digest for every line of
the whole history. Found by a second review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
Lines are written with ensure_ascii=False, so a power cut inside a fada
left bytes that strict UTF-8 decoding raised on, ending the whole rebuild
rather than counting one bad line; the logs are now read with errors
replaced. And compact appended late lines as a new gzip member straight
after the archive's last byte, so a torn line there swallowed the first
late record; the new member now starts on a fresh line. Found by a second
review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
A type change clears last_detail_utc, and a flip to Restored on an outage
already captured still ranked 0, tied with Restored outages never captured
at all. A purge costs it only its restore time, so it now shares rank 1 with
the settling ones, behind the uncaptured. Found by a second review of this
PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
The previous commit read the logs with errors="replace" so a line torn
inside a fada could not end a rebuild. That also turned a line corrupted on
the card into a different valid record: "Dún" read back as "D�n",
recorded as a change and never counted as malformed. Files are now read as
bytes and each line decoded strictly; a decode error is one malformed line,
like a JSON error. The dedupe digest is taken from the bytes. Found by a
third review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
A run that failed at the list call logs auth_error or unreachable on its
start line and flags that an end line follows; with that end line torn,
the rebuild labelled it unfinished, or in_progress, and lost the failure it
had already recorded. A non-ok start status now wins over the label. Found
by a third review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
The set of lines seen was reset whenever the part of the file name before
the first dot changed, so a same-month copy under another name, such as
runs-2026-01-pi2.jsonl from a second host, got a set of its own and its
duplicates replayed twice. The month is now read from the name. Found by a
third review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
A run rebuilt from its end line has no list, so its fetched count was left
NULL by the rule meant for runs that never got past the list call, though
its observations were there and replayed as its own. It now counts them,
and the test pins that the run replays as a run, not as orphans. Found by
a third review of this PR.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
One set of run ids instead of two; the settling and flipped Restored ranks
reached through one branch with one comment, which is equivalent because
apply_list clears is_final with last_detail_utc; the archive's existence
checked once in compact; and a no-op line and its misleading comment
dropped from the torn-archive test.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqWuH6frirpbQDKnF5rEdT
@baz8080
baz8080 merged commit bc1dae3 into main Sep 24, 2026
3 checks passed
@baz8080
baz8080 deleted the claude/eager-sagan-wn68lr branch September 24, 2026 11:38
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants