From b88bbb9867af678bb2659f83d64c8a1227484f96 Mon Sep 17 00:00:00 2001 From: EMRG Evolution Date: Sat, 19 Sep 2026 04:30:44 +0800 Subject: [PATCH] emrg: the daemon start window is the host's to set (#1276) --- DEVELOPMENT.md | 27 +++++++++ emrg/client/daemon_manager.py | 79 +++++++++++++++++++++++++- tests/test_daemon_start_diagnostics.py | 69 ++++++++++++++++++++++ 3 files changed, 173 insertions(+), 2 deletions(-) diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index 0667667d..bbe58ccd 100644 --- a/DEVELOPMENT.md +++ b/DEVELOPMENT.md @@ -452,6 +452,33 @@ Two gaps get mistaken for a broken fix: Check `emrg -v` and when the daemon started before re-reading the source. +### `emrgd failed to start within N s` + +The client spawns the daemon and waits for it to accept connections. When that +wait runs out, the error carries what is known about the attempt: whether the +child is still running, its exit code if it is not, the daemon log lines **this** +attempt appended, and the contents of `~/.emrg/emrgd-start.err` (the child's own +stderr, which is where a failure before logging starts can be read at all). + +The window defaults to **4.5 s** (15 polls, 0.3 s apart). A start that is merely +slower than that on a cold machine is worth raising it for; set the variable on +the command that starts the client, since the client is what waits: + +```bash +EMRG_START_TIMEOUT=30 emrg +``` + +It takes seconds as a number. A value that is not a positive, finite number is +ignored, with a warning in the client log — a typo in a tuning variable must +never be the reason a start fails, so it falls back to the default rather than +raising. + +Two facts make the window cheap to raise: a child that has **exited** is reported +on the first poll with its exit code, so the window only ever bounds a child that +is alive but not yet listening; and the failure report names the bound it really +waited, not the one you asked for, because the window is quantised to the 0.3 s +poll. + ### Why is a write blocked at `workspace-write`? `workspace-write` is the default tier, and it allows a write only when the diff --git a/emrg/client/daemon_manager.py b/emrg/client/daemon_manager.py index 4c5a3717..3b796633 100644 --- a/emrg/client/daemon_manager.py +++ b/emrg/client/daemon_manager.py @@ -13,6 +13,7 @@ import asyncio import json import logging +import math import os import signal import subprocess @@ -332,14 +333,81 @@ def _startup_failure_detail( ) +# ── the start window (issue #1276 item 5) ─────────────────────────────────── +# How long the client waits for a spawned emrgd to accept connections before it +# reports a failure. This was the literal pair in `_await_daemon_ready`'s +# signature — 15 x 0.3 s = 4.5 s — so a host whose cold start is slower than that +# had no way to raise it: the failure reappeared identically on every retry, and +# nothing distinguished "still starting" from "wedged". +# +# The default is unchanged, deliberately. Raising it is a behaviour change, and +# the premise (a cold start needs more than 4.5 s) did not reproduce here: this +# machine's daemon module imports in 0.14-0.16 s warm, which is the wrong regime +# to argue a cold figure from. What the code *does* establish is that the window +# is now cheap to extend — `_child_exit_code` reports a child that died on the +# first poll, so the window only ever bounds a child that is **alive** — but +# "cheap to extend" is not a measurement of how far to extend it. +_START_WINDOW_ENV = "EMRG_START_TIMEOUT" +_START_WINDOW_DEFAULT_SECONDS = 4.5 +_START_WINDOW_POLL_SECONDS = 0.3 + + +def _start_window_seconds() -> float: + """The wait window in seconds: ``EMRG_START_TIMEOUT`` if set, else the default. + + The host-facing knob for a start that is slower than the default (issue #1276 + item 5) — the same shape as ``EMRG_TASK_DIRTY_OVERRIDE``, and documented for + the same reason: an escape hatch whose effect is "you asked for X and got Y" + has to be findable without reading this file. + + A malformed value falls back to the default instead of raising. The rule is + `_truncate_start_stderr`'s: **a diagnostic must never be able to make a start + fail**, and a typo in a tuning variable would be exactly that. It is logged + once, where a host who is reading the client log can see it. + + Two shapes that parse as a float are rejected anyway, because "float-shaped" + is not the same test as "a duration": a non-positive number would produce a + loop that never waits and then reports a start it never waited for, and a + non-finite one (`inf`, `nan`) raises inside the arithmetic that turns seconds + into polls. Whitespace-only counts as unset — that is how a shell spells it. + """ + raw = (os.environ.get(_START_WINDOW_ENV) or "").strip() + if not raw: + return _START_WINDOW_DEFAULT_SECONDS + try: + seconds = float(raw) + except ValueError: + logger.warning( + "%s=%r is not a number — using %.1fs", + _START_WINDOW_ENV, raw, _START_WINDOW_DEFAULT_SECONDS, + ) + return _START_WINDOW_DEFAULT_SECONDS + if not math.isfinite(seconds) or seconds <= 0: + logger.warning( + "%s=%r is not a positive number of seconds — using %.1fs", + _START_WINDOW_ENV, raw, _START_WINDOW_DEFAULT_SECONDS, + ) + return _START_WINDOW_DEFAULT_SECONDS + return seconds + + +def _start_window_attempts() -> int: + """``_start_window_seconds()`` in polls of ``_START_WINDOW_POLL_SECONDS``. + + Quantised to the poll interval, so the reported window is the bound the loop + really waits and not the number that was asked for. + """ + return max(1, int(round(_start_window_seconds() / _START_WINDOW_POLL_SECONDS))) + + async def _await_daemon_ready( proc, log_path: Path, since: tuple[int, int | None], probe=None, *, - attempts: int = 15, - delay: float = 0.3, + attempts: int | None = None, + delay: float = _START_WINDOW_POLL_SECONDS, stderr_path: Path | None = None, ) -> None: """Wait for the daemon to accept connections; raise with what is known. @@ -353,7 +421,14 @@ async def _await_daemon_ready( *only* there, so without it the failure report had nothing to quote. ``None`` is not a path: it says the capture did not happen, and the report says so instead of claiming the channel was silent. + + ``attempts=None`` means "use the host's window" — ``EMRG_START_TIMEOUT`` if + set, else ``_START_WINDOW_DEFAULT_SECONDS`` (issue #1276 item 5). A caller + that passes a number still overrides it, which is what keeps the tests below + deterministic and independent of the machine's environment. """ + if attempts is None: + attempts = _start_window_attempts() probe = probe or is_running for _ in range(attempts): await asyncio.sleep(delay) diff --git a/tests/test_daemon_start_diagnostics.py b/tests/test_daemon_start_diagnostics.py index 7871e7e8..d9e30de1 100644 --- a/tests/test_daemon_start_diagnostics.py +++ b/tests/test_daemon_start_diagnostics.py @@ -251,6 +251,75 @@ async def fake_sleep(seconds): asyncio.sleep = real_sleep +# ── the start window is the host's to set (issue #1276 item 5) ─────────────── + + +def test_the_window_defaults_to_the_pair_the_signature_used_to_hold(monkeypatch): + """No variable set → the window is unchanged, so this is not a behaviour change. + + 15 x 0.3 s is what the loop waited before it was configurable, and a host who + never sets anything must keep waiting exactly that. + """ + monkeypatch.delenv(dm._START_WINDOW_ENV, raising=False) + assert dm._start_window_seconds() == 4.5 + assert dm._start_window_attempts() == 15 + + +def test_the_window_is_what_the_host_asked_for(tmp_path, monkeypatch): + """`EMRG_START_TIMEOUT` reaches the loop, and the failure reports it. + + Driven end to end through `_await_daemon_ready` rather than asserted on the + resolver alone: a value that is read but never used is the defect this whole + issue is about, so the test has to see the wait change, not the variable. + """ + log = tmp_path / "emrgd.log" + ticks: list[float] = [] + + async def fake_sleep(seconds): + ticks.append(seconds) + + monkeypatch.setenv(dm._START_WINDOW_ENV, "1.2") + real_sleep = asyncio.sleep + asyncio.sleep = fake_sleep + try: + with pytest.raises(RuntimeError) as err: + asyncio.run(dm._await_daemon_ready( + StubProc(returncode=None), log, dm._log_mark(log), + probe=lambda: False)) + finally: + asyncio.sleep = real_sleep + + assert "failed to start within 1.2s" in str(err.value) + # 1.2 s at the 0.3 s poll — four polls, not the default fifteen. + assert len(ticks) == 4 + + +@pytest.mark.parametrize("raw", ["soon", "-5", "0", "nan", "inf"]) +def test_a_window_that_is_not_a_duration_falls_back_instead_of_failing(raw, monkeypatch): + """A typo in a tuning variable must not be able to fail a start. + + The same rule `_truncate_start_stderr` follows: a diagnostic never gets to be + the reason a start dies. `-5`, `0` and `nan` are the interesting ones — each + parses as a float and would otherwise produce a loop that never waits, so + "float-shaped" is not the same test as "a duration". + """ + monkeypatch.setenv(dm._START_WINDOW_ENV, raw) + assert dm._start_window_seconds() == 4.5 + assert dm._start_window_attempts() == 15 + + +def test_a_whitespace_only_window_is_unset_not_a_parse_error(monkeypatch): + """`EMRG_START_TIMEOUT=""` is how a shell says unset; it must not warn.""" + monkeypatch.setenv(dm._START_WINDOW_ENV, " ") + assert dm._start_window_seconds() == 4.5 + + +def test_a_window_too_short_for_one_poll_still_polls_once(monkeypatch): + """A floor of one poll: a zero-iteration loop would report a start it never waited for.""" + monkeypatch.setenv(dm._START_WINDOW_ENV, "0.01") + assert dm._start_window_attempts() == 1 + + # ── a stop is not a crash ───────────────────────────────────────────────────