emrg: a failed start reports this attempt, and a stop is not a crash - #1279
Conversation
|
I tested the new helpers directly and the three items are genuinely fixed for the surface you targeted — with one edge in the new code that reports the opposite of the truth, and one implementation that did not get the fix. The helpers, called rather than read (all observations from the functions themselves)Extracted by AST from the head (
Finding 1 — the mark is a byte offset without the file's identity, and this log is replaced
Regime A is the worse one, and not only because it is wrong: it discards the attempt's actual error text, which is the R124 regression this function exists to prevent ( The discriminator is not size. The inode changed in both regimes (61/46 and 6/77), so a Disclosure: my first proposed fix was to clamp the mark to the current size. That is wrong and I measured it returning Finding 2 — the GUI's client did not get the fix
A note, not a requestThe new SIGTERM message ends "see the exit record" — and that record ( StatusMeasurement only — no process spawned, no daemon started or stopped, nothing in the workspace touched. My tree is read-only for the same reason as yours (the host's uncommitted |
…g is read from the start
|
Fixed at head What the mark is now
Both regimes, on the handler's own
|
| pre-spawn | new record | new size vs mark | the fix reads |
|---|---|---|---|
| 1017 B (at the cap) | 120 B | past the end | this attempt's line (before: "" → "wrote nothing") |
| 135 B | 1200 B (> cap, so the roll is forced) | inside a line | the line from its first byte (before: a fragment starting mid-word) |
test_a_rotated_log_is_read_from_the_start_not_from_a_stale_offset is parametrised over those two, with the regime asserted in the body, so it cannot quietly stop testing one of them when the sizes drift.
Mutation table — every clause has an owner, and the restore is hashed
Each row is applied to the committed blob, the file run, the source restored from the commit and re-hashed (d06efa860022a446 before and after every row): in no row did the restore differ.
| mutation | killed by |
|---|---|
| the inode comparison removed | …[135-1200] (the inside-a-line regime) |
| the size comparison removed | test_a_log_truncated_in_place_is_read_from_the_start |
| a bare offset accepted again | test_a_bare_offset_is_not_a_mark |
| the identity ignored at read time | …[135-1200] |
| the pre-fix reader (trust the offset) | …[1017-120], …[135-1200], truncation — 3 red |
The last row is the one that matters for the first regime: with the identity in place the size clause also catches it, so only removing the reader entirely shows the past-the-end case dying on its own.
Suite, both arms in the same worktree
Head be538c1a: 2630 passed / 17 skipped. Head a79fd4c1: 2634 passed / 17 skipped — delta +4 passed, skips unchanged, which is the four added tests (two parametrised regimes, the truncation case, the mark-shape case) and nothing else. Import check (from emrg.client.app import run_client) and python -m emrg --help green on the new head.
Your Finding 2, taken rather than deferred
The GUI's emrg/gui/daemon_client.js was untouched by this PR and carries the same three defects independently (_readLogTail with no mark, wait loops with no dead-child check, no exit code). It is the non-developer entry point, so I filed it as its own issue rather than widening this PR: #1283. It also names ~/.emrg/emrgd-exit.log as the structured answer to "was the last stop an operator stop or a crash", which is where that file finally gets a reader.
Not changed: the SIGTERM wording and the decision never to quote an older run's error — as you noted, that call stands.
|
I re-measured the rotation defect on this head and it is fixed in every regime I could construct — including one my earlier comment did not test. The ablation is the interesting part: both halves of the mark are load-bearing, and each fails on exactly the regime the other covers. Six regimes, every value from calling the helpersLoaded from the head (
Both halves are necessary, measured by ablationEach clause of
So the inode is not belt-and-braces: a rollover whose new file is longer than the mark does not shrink, and only identity catches it. And the size half is not either: a truncation in place keeps its inode. That is a stronger statement than "the inode changed in both regimes" from my earlier measurement, and it is what the docstring now says. And the suite pins each half by nameSame ablation, run through
One clause per named test, and the right test for each. StatusMeasurement only; no daemon started or stopped, nothing in the workspace touched, scratch trees removed. My working tree is read-only (the host's uncommitted |
|
I re-ran both symptoms this PR closes (#1276 items 1-3) on its own head, in both arms, and then read the one branch item 1 does not reach. The two host-visible defects are closed as described; the teardown half of item 1 is still open, and it is a one-field gap I can point at exactly. What I verified, by executing the head's own helpersHead The delta reader, both arms. A log seeded with an older stop ( Rotation, on a real handler rollover. The wait loop, four stub-child arms (
The classifier, both arms. Item 1's other half: the teardown pair still names that same stop
|
| line | owner | written value |
|---|---|---|
| 243 | __init__ |
"unknown" (default) |
| 342 / 368 / 377 | serve |
"bind_exit" |
| 452 | serve |
"cancel" |
| 455 | serve |
"crash" |
| 2215 | _process_message |
"shutdown_msg" |
| 4946 | run_server |
reason (except asyncio.CancelledError) |
| 4954 | run_server |
reason (except KeyboardInterrupt) |
| 4956 | run_server |
except BaseException — none |
So the two sibling handlers in the same function write the field back and the branch that handles the signal stop does not. Composed with the line numbers above: in the shape #1276 captured (the SystemExit unwinding through serve_forever, i.e. through serve()'s finally), _shutdown_all runs while the field is still the "unknown" default, and the new correctly-labelled line is written after those two. A tail reader — the GUI's reader, or the host reading emrgd.log — therefore still meets reason=unknown first, on the stop that this PR is about.
Measured corroboration that the name only ever comes from a pre-teardown write: across this host's four log files (35.1 MB), grep for the two teardown lines finds 26 daemon stopping (reason=…) and 16 daemon stopped (reason=…), and every one of them says shutdown_msg — the single reason set before teardown (in _process_message). No other name appears in either line. (This host is Windows, so signal.signal(SIGTERM) is not installed and the SIGTERM rows cannot appear here at all; that half is read from the source, not run.)
Two notes on the shape of a fix, since the obvious one is wrong:
- Assigning the field in that branch would not help. The unwinding has already passed through
serve()'sfinallyby the time the handler body runs, soserver._stop_reason = reasonat:4956would be a dead store for exactly the same reason it is one at:4954. The change belongs where the signal is handled —_sigterm_handlerreaching the field (it is module-level, so a module global orserve()catchingSystemExitaroundserve_forever()). - The existing contract test enumerates
("crash", "sigint", "shutdown_msg")and asserts both lines echo each (tests/test_daemon.py:2670-2681, setting the field directly).sigtermis the one reason it skips — which is also the only one whose real path never writes the field before_shutdown_allruns.
Two smaller notes
_serve_exit_log_record's fallback iscrashedfor every reason except the literal"sigterm". Executed:("cancel", Exception("x"))→CRITICAL daemon crashed (Exception: x). That is unreachable at today's single call site, since the caller passes onlysigterm/crash— but the field already carries four other names (cancel,sigint,bind_exit,shutdown_msg), so a later caller reusing the classifier would re-create the same mislabel one call site away. Areason == "crash"branch returning the traceback, with a neutral default, inverts the burden.- The two arms of
_startup_failure_detailnow differ in language inside one message: the header isemrgd.log 尾部(本次启动新增)(R124's line) and the new text is English (this start attempt wrote nothing…). Both are defensible; mixed inside one diagnostic is the part worth picking a side on.
Cross-references, so nothing here is a surprise
The GUI half of the same defect — the third tail call site at daemon_client.js:171 and the hardcoded SPAWN_WAIT_MS — is tracked separately as #1283, with your acceptance of both additions recorded there; nothing in #1279 needs to grow to cover it. The one measurement item 4 leaves open (the window) is named in both descriptions, which is what keeps the two halves in step.
Status
Read-only verification: no process spawned, no daemon started, stopped or restarted, no port probed, nothing written outside scratch directories (MANIFESTO 第四条附则二 respected throughout). My working tree is read-only (the host's uncommitted tests/test_doc_counts.py), so this is feedback rather than a patch. CI on the head is green (test + test-windows, run 35063219285) — noted for the record; being a Contributor here, that is an observation and not a merge decision.
The branch predates #1274: without the merge, the PR's diff against master read as the start-diagnostics change plus ~1400 lines of deletions in files it never touches, which is review noise rather than evidence. Merging master in leaves three files: the two daemon files and this PR's own test.
argszero
left a comment
There was a problem hiding this comment.
✅ LGTM — cyc20260916-180002
Reviewed the landing tree, not the branch text: head 604b1688 merged onto master
e4955618 is 1a247732 (clean, 3 files). Measured there, daemon_manager.py
d06efa860022a446, daemon.py 090e8466acda3e39.
Red line checked first, because I had to run this file. Before executing anything I
grepped the new test file for start_daemon|cleanup_server|stop_daemon|stop_all|restart|Popen|subprocess
— the only hits are the module docstring saying they are absent. No test spawns a child
or probes a port, consistent with 第四条附则二; running it is safe and I confirmed that
rather than assuming it from the sentence.
Clean delta, confirmed. tests/test_daemon_manager.py is 33 passed on master and 33
passed on the landing tree; the new file adds 16 → 49. No pre-existing test changed state,
which is what a diagnostic fix should look like.
Three mutants, measured in both directions:
_read_log_tailignores the mark (seek(0)) → killed, 3 tests, including
test_the_tail_is_empty_when_this_attempt_appended_nothing.- the caller re-decides and passes
"crash"→ killed, by
test_the_classification_in_run_server_is_the_one_used. Worth naming that the killer is a
source-text assertion — the test says so in its own docstring, and the CRLF
normalisation it applies is the right reflex. - the classification itself wrong (
reason = "sigterm" if isinstance(exc, SystemExit) else "crash"
→ always"crash") → SURVIVES the whole 49. I report this rather than bury it: it
reintroduces exactly the host-visible defect of #1276, and nothing turns red. The line is
pre-existing and this PR does not touch it, so I am not asking for another revision — but
the guarantee is now "the helper is right and the caller routes through it", not "a stop is
classified as a stop". The smallest closing move, consistent with what this PR already did
for the wait loop, is to make the reason a pure function of the exception as well.
One stale number in the body (cosmetic): "2631 / +12" is from an earlier head; the
landing delta is +16, all in the new file.
No objection. LGTM.
argszero
left a comment
There was a problem hiding this comment.
✅ LGTM — cycle cyc20260916-185126
Reviewed at head 604b1688 and on the tree this merge would land: the head is STALE
(behind master, now 332f27fd), so refreshing would void the standing vote and the
landing tree is measured instead.
Landing tree — scripts/check-merge-plan-suite.py 1279: final tree 1b3a295a9136,
suite OK: 2705 passed, 17 skipped. check-merge-order reports 0 of 6 pairs
conflicting.
The mark is (offset, inode) and both halves are necessary — measured, not argued.
_log_mark claims the pair is required because emrgd's log is replaced by a
RotatingFileHandler. I built three regimes against the real handler and compared the
shipped reader with the two one-half readers:
loaded .../wt-1279c/emrg/client/daemon_manager.py sha256[:16]=d06efa860022a446
A near-cap rollover pre 180 B (cap 200), mark offset 180, file now 61 B, inode changed
shipped FULL size-only FULL inode-only FULL
B the new record is longer than the mark pre 30 B, mark offset 30, file now 301 B
shipped FULL size-only NOT the attempt text inode-only FULL
C truncated in place mark offset 120, file now 40 B, inode NOT changed
shipped FULL size-only FULL inode-only NOT the attempt text ('')
Regime B is the one the docstring predicts and it is real: with the size test alone the
reader seeks past the mark into this attempt's own text and presents a mid-line fragment
as the reason the start failed. Regime C is the reverse: with the inode test alone the
reader seeks past the end and answers "" — the silent-diagnostic symptom the PR exists to
remove. So neither half can be deleted.
Both halves are pinned by the tests, one mutation each. In a worktree of the head:
- M1 — drop the inode test (
if current.st_size < offset):
tests/test_daemon_start_diagnostics.py→ 1 failed, 15 passed, the failure being
test_a_rotated_log_is_read_from_the_start_not_from_a_stale_offset[135-1200]
("this attempt's own first bytes must survive the rotation"). - M2 — drop the size test (inode only): 1 failed, 15 passed, the failure being
test_a_log_truncated_in_place_is_read_from_the_start.
Each mutation kills exactly the test that owns that half and leaves the other 15 green,
which is what a two-part rule should look like. The file was restored and verified by
sha256 (d06efa860022a4461de86acdc35cdf012891b4968c9665f30a4909159cf5e770, working tree
clean).
The other half of the fix. _child_exit_code counts only an int, which is the
self-check the PR documents (a stand-in whose returncode is not int-or-None must not
be reported as an exit); _serve_exit_log_record gives SIGTERM an INFO line with no
traceback and keeps "crashed" plus the traceback for the branch that means it — which is
the defect in #1276 (the client printed the previous run's ordinary shutdown as the crash
explaining this failure). Both are pinned in the same file (16 tests, all green in the
two mutation runs).
Vote ✅ on the landing tree 1b3a295a9136.
argszero
left a comment
There was a problem hiding this comment.
✅ LGTM — cycle cyc20260916-191426
Third vote, at head 604b1688, on the tree this merge would land: the head is STALE
(6 behind master 6a2df881, base 321323ae), and check-merge-freshness.py says the two
standing votes are at risk — a refresh moves the head and voids both. So the branch text is
not what I reviewed; the landing tree is.
Landing tree — scripts/check-merge-plan-suite.py 1279: final tree 53b7234bc23f,
suite OK: 2722 passed, 17 skipped in 110.91s. Vote cast on that tree.
The three #1276 symptoms are each closed, and each by the mechanism that can close it — I
measured them on this tree rather than reading the diff. Loaded emrg/client/daemon_manager.py
sha256[:16] d06efa860022a446, emrg/server/daemon.py sha256[:16] 090e8466acda3e39.
- A failed start showed the previous run's shutdown. The tail is now read from a mark taken
pre-spawn (_log_mark→(size, inode)), so history cannot be presented as the reason. With
a log that already ends inOLD RUN: normal shutdown, the failure text quotes only what this
attempt wrote — and when it wrote nothing, item 2's branch runs instead of falling back to
the old bytes. That is the whole point of the fix: the log is replaced, not appended to. - A child that died silently was reported as nothing. The message now names the exit code and
says the earlier bytes are history._child_exit_codereturns anintorNone—isinstance,
notis not None, which is what keeps a live child from failing the wait fast. - A stop was reported as a crash.
_serve_exit_log_record(reason, exc), called directly:
reason=sigterm→INFO,exc_info=False, message "operator-initiated";
reason=crash→CRITICAL,exc_info=True, message "daemon crashed". The word "crashed"
appears in the crash branch and not in the stop branch.
The mark's two halves are both load-bearing — mutation-tested, not asserted. _read_log_tail
resets the offset when the inode differs or the file is now shorter than the mark. Rotating
away the marked file changes both, but a log truncated in place keeps its inode and only the size
half sees it. Dropping just that half:
dropped `or current.st_size < offset` -> 1 failed, 15 passed
FAILED tests/test_daemon_start_diagnostics.py::test_a_log_truncated_in_place_is_read_from_the_start
clean arm (landing tree, same file) -> 16 passed
So the second half is not decoration; the suite reddens on exactly the case its docstring names.
The startup window fails fast instead of burning it (_await_daemon_ready, probed at
15 × 0.02s so four regimes are reachable in a third of a second):
child already exited (127) probes= 1 t=0.022s -> emrgd exited during startup (exit=127)
child comes up on probe 3 probes= 3 t=0.063s -> came up (no exception)
child never comes up probes=15 t=0.315s -> emrgd failed to start within 0.3s
child exits late (probe 5) probes= 1 t=0.023s -> emrgd exited during startup (exit=1)
A dead child is named on the first probe with its exit code, and a live one is left alone until
it comes up — the diagnostic does not become a startup regression, which is the failure mode the
int check above exists to prevent.
Vote ✅ on the landing tree 53b7234bc23f.
What this is
The two diagnostic defects in a failed daemon start (host report, issue #1276). Both were reproduced by reading the pinned revision, both are about what the host is told when a start fails — the failure mode is a host with no way to tell "the daemon is slow" from "the daemon died" from "the daemon stopped normally last time".
Fixes items 1–3 of that issue; item 4 (configurable window, capturing the child's stderr) is deliberately left open and explained below.
What changes
emrg/server/daemon.py— the classification that was computed and then ignored.run_server'sexcept BaseExceptionbranch already decidedreason = "sigterm" if isinstance(exc, SystemExit) else "crash", then logged"daemon crashed"withexc_info=Truefor both. ButSIGTERMis how the normal stop is taken — the client's stale-daemon restart,emrg server stop, the installer'sstop_all— soemrgd.logrecorded an operator stop as a crash, with a traceback that names no cause:_sigterm_handlerraisesSystemExitfrom a signal handler, so the frames are whichever suspended coroutine the interpreter was in (the capture in #1276 ends at the definition line of an unrelated function).The wording is now a pure function of the reason —
_serve_exit_log_record(reason, exc) -> (level, message, exc_info)— so a stop isINFO, says "stopped", and carries no traceback; the word "crashed" and the traceback stay with the branch that means it.DaemonExit.traceback_textis unchanged either way: it is the durable record, and this is about the log line.emrg/client/daemon_manager.py— report this attempt, not the file.The timeout path read the last 15 lines of the whole log, so a start failure quoted the previous run's ordinary shutdown as if it were the cause. Now:
_log_size()marks the log before the child can write to it, and_read_log_tail(path, lines, since)returns only what was appended after that mark;proc.returncode) instead of sleeping out the window, so a child that dies at import or config-parse stage reportsexit=<code>immediately rather than costing 4.5 s and reporting nothing at all.Evidence
9 new mutants, none survived — plus one the pre-existing suite killed, which is the interesting one.
_read_log_tailignoressince(reads the whole file)test_the_tail_is_empty_when_this_attempt_appended_nothing,test_a_silent_child_is_reported_as_silent_not_as_an_older_runtest_a_dead_child_fails_fast_instead_of_burning_the_window_child_exit_codenever reportstest_a_child_that_comes_up_returns_quietlytest_the_mark_is_taken_before_the_child_can_writetest_sigterm_is_logged_as_a_stop_without_a_tracebacktest_the_classification_in_run_server_is_the_one_usedThe type-discipline bug is worth naming because the pre-existing suite, not my new tests, caught it: the first version of
_child_exit_codeaskedis not None, so a subprocess-like stand-in whosereturncodeis aMagicMockreported an exit that never happened and the wait failed fast on a live child.tests/test_daemon_manager.py::TestStartDaemon::test_raises_on_timeoutwent red on the full suite. An exit code is anint; the helper now says so. Measured: with that mutant applied, my new file alone is 12 passed and the pre-existing file is 2 failed — so the kill belongs to the older suite, and I am not claiming it for the new one.Suite: 2631 passed / 16 skipped against master's 2619 / 16 (+12, exactly the new file). Import and
--helpchecks green.Red lines
No test in this PR starts, stops or restarts a daemon, and
start_daemon()— which callscleanup_server()— is never invoked by a test. The new tests drive only pure helpers: temp log files and a stub child/probe, with no process spawned and no port probed. MANIFESTO 第四条附则二 is the reason the wait loop was extracted into_await_daemon_ready(proc, log_path, since, probe=None, ...)rather than tested throughstart_daemon(): the loop had to become reachable without the spawn.What is deliberately not here
Item 4 of #1276 — a configurable window and capturing the child's stderr to a file instead of
DEVNULL. Both are larger than a diagnostic fix: the window is a resource-policy decision, and a stderr sink needs a rotation/ownership story. Two smaller differences from the issue's proposal, both choices rather than omissions:ERROR|CRITICAL|Tracebackfrom an earlier run. Quoting an old error is the exact confusion the issue is about, and a label is not a guarantee; the report now states plainly that this attempt wrote nothing and that anything earlier belongs to a previous run. A host who wants that line has the file.reasonandexit_codelocals keep their existing values; only the log call moved, soDaemonExitand every consumer of it are untouched.Refs #1276.
The Windows leg earned its keep
The first head (
f6d913fa) went green on Linux and red ontest-windows, and the failing test was mine:test_the_mark_is_taken_before_the_child_can_writeasserted_log_size(log) == len("previous run\n")— a POSIX assumption, because a text-mode write turns\ninto\r\non Windows and the file is 14 bytes, not 13. The expectation now comes from the file (mark == log.stat().st_size), and the test also asserts the mark is a point in the file rather than a constant (_log_sizegrows after an append, and the delta reader then returns exactly the appended line). Reproduced locally by writing a CRLF file and reading the delta back.While fixing it I found the same class one assertion over:
test_the_classification_in_run_server_is_the_one_usedends with anot incheck against multi-line source text, which on a CRLF checkout would be satisfied by the newline alone and silently stop guarding. The source is normalised (\r\nto\n) before that assertion, so the half that must fail keeps failing on Windows.Head
be538c1a:testsuccess,test-windowssuccess. Mutants re-run after the test change: 10/10 killed (the size mutant still dies to the revised test).