rerail status: the hook failure count resets when the log moves aside, and hooks failing at once lose failures (build of #503)

Aperta
  • Qualcosa non va?
#577 0 commenti 0 reazioni 0 assegnatari Vedi su GitHub

I maintainer di solito rispondono entro 1 giorno

Nessuno ha ancora preso questa issue.

Valutazione

Difficoltà
4/5
Tempo stimato
3-5 giorni
Idoneità per principianti
45/100
Tipo di issue
Bug
Chiarezza
Specificata chiaramente
Stato di attività
Attiva
Stack tecnologico
rust
Ambito
backend

Direzione di ricerca

Start with src/harness/hook-failures.ts and trace recordHookFailure plus the code used by rerail status to read the failure log. Reproduce the rollover and concurrent-write cases from the issue, then check that the count and its reported time period agree and that concurrent failures are retained across log moves. The issue also asks maintainers to decide the status wording and changelog entry.

Scritto dal modello di indicizzazione a partire dal testo della issue.

Descrizione

bug
Rerail version

0.1.3, built from pull request #503's branch, which adds the hook failure log. No release has it yet.

Is it a documented feature?

Documented

Coding agent

Claude Code

Coding agent version

2.1.322

Operating system

Windows x64

What happened

rerail status reports hook events Rerail could not record: Hooks: N hook events could not be recorded in the last 24 hours; the last, .... Hooks write one line per such event to hook-failures.jsonl in the Rerail home. On a Windows 11
machine whose daemon was too busy to answer, hooks failed about 50 times a minute, and the count fell without any quiet
period: 1382 at 16:04:53, 115 at 16:09:24, 201 at 16:10:24; then 1345 at 16:33:15 and 44 at 16:38:37; 1092 at 16:58:55
and 6 at 17:04:07.

Two things cause it:

  1. Past 256 KB, the next hook moves hook-failures.jsonl to hook-failures.jsonl.1, replacing the one there, and
    rerail status reads only hook-failures.jsonl. The count drops to the failures since the move, every 1,100 to
    1,300 failures. Even reading both files, they hold about 2,200 failures, 45 minutes at that rate, while the line says
    24 hours.
  2. 25 to 37 hooks ran at once. Each that finds the log full renames it to .1. After the first rename, a later hook
    fails on a file already gone and never writes its own line, or renames the new log another hook has just begun over
    the full .1, which loses up to 256 KB of failures.

Expected: the count covers the period the line names, and every failure a hook writes is kept until the log moves it
out on purpose.

Steps to reproduce
  1. In a Rerail home, have hooks fail until hook-failures.jsonl passes 256 KB: run a coding agent while the daemon is
    too busy to answer, or record failures through recordHookFailure from src/harness/hook-failures.ts, 50 a minute
    with a time 1.2 s apart, as the script behind the Output below does.
  2. Run rerail status before and after the next failure moves the log to hook-failures.jsonl.1: the count falls to
    the failures written since the move.
  3. For the second cause: start 8 or more processes that each call recordHookFailure once, at the same moment, into a
    home whose hook-failures.jsonl already holds more than 256 KB of failures. Count the lines in
    hook-failures.jsonl and .1 afterwards: some of the processes' lines are missing, and now and then .1 holds a
    few lines in place of the full log.
Output
rerail status on the machine above, every few minutes:
16:04:53  Hooks: 1382 hook events could not be recorded in the last 24 hours; ...
16:09:24  Hooks: 115 hook events could not be recorded in the last 24 hours; ...
16:10:24  Hooks: 201 hook events could not be recorded in the last 24 hours; ...

recordHookFailure 50 times a minute (one process), counted as rerail status reads the log:
minute  20  recorded  1000  status shows  1000
minute  25  recorded  1250  status shows   129
minute  45  recorded  2250  status shows     8
minute 120  recorded  6000  status shows   395

8 processes recording one failure each, at once, into a log past 256 KB (240 lines), 4 rounds:
Windows 11: 244 to 247 of 248 lines kept (3 runs of 3 lost lines)
Linux x64:  247, 247, and once 5 of 248 (the full .1 replaced by the new log)
Support bundle

Not attached. The counts above are rerail status output and the output of the scripts in the steps.

A change in your fork

Not from a fork: the fix is a branch in this repository, opened as a draft pull request stacked on #503.

Before you send it
  • I searched open and closed issues, including ones labelled known-issue, and this isn't one of them.
Approach

The log stays two append-only files of at most 256 KB each. The fix changes how they are read and how a hook moves one
aside:

  1. Status reads the live log, each log a hook holds mid-move, and .1, and counts a file once under whatever name the
    read meets it (device and file number).
  2. When the log was moved aside and holds nothing as old as 24 hours, the line says since <time>, as far back as the log goes in place of in the last 24 hours, so the number and the period agree. The hook that moves the log aside
    writes that time, {"startedAt": <time>}, into the next part, a line with no event that an earlier build's reader
    skips.
  3. A hook takes the full log under a name of its own, hook-failures.jsonl.<pid>.<uuid>.old, and moves it to .1 only
    when what it took is full. A hook that took the new log another hook began gives its lines back. A later move
    removes a log a stopped hook left, once that hook has ended and the file is a day old.
Alternatives
  • A counter that every failing hook updates, so the count covers 24 hours at any rate. Many hook processes would
    update it at once, where the log stays append-only.
  • A larger log or more than two files. The count would still fall at a move, later.
  • A lock file around the move, in place of the take under a hook's own name. A hook stopped while it holds the lock
    leaves it held, so the lock needs a stale-lock age.
  • Counting from the oldest failure the log keeps, with no start line. Hooks read the clock before they write, so
    failures from the moment of a move land on both sides of that time: 14 to 16 of about 450 went missing in each of 3
    rounds of a burst test.
Question for a maintainer

Two things to decide:

  1. With the count reaching into .1, the line leads with Hooks run but nothing was recorded since ... only when
    every failure counted is newer than the last recorded event. When hooks failed earlier in the day and events were
    recorded after that, a later outage now gets the plain count line. Should the line lead with the outage whenever
    any failure is newer than the last recorded event, and add the period's total after it?
  2. If this merges in the same release as #503, nobody upgrading met the bug. Should its .changelog/ entry be dropped
    then?
Lingua principale
Rust
Stelle
10
Fork
0
Merge medio
23h 1m
PR unite (30g)
290

Preparare l'ambiente

Come iniziare

  1. Leggi tutta la issue e poi la guida ai contributi del progetto.
  2. Commenta sulla issue per dire che te ne occupi tu — evita che due persone facciano lo stesso lavoro.
  3. Fai un fork del repository e lavora su un branch.
  4. Apri una pull request che faccia riferimento al numero della issue.

Altre issue di neralabs/rerail

Tutte le issue di neralabs/rerail

Issue simili

Altre issue su Rust

Ricevi le nuove issue nella tua casella

Un breve riepilogo di issue GitHub adatte ai principianti.