From 4e9e90c0f225b66219bb1fa5874bcf38266dab52 Mon Sep 17 00:00:00 2001 From: Michael Johnson Date: Tue, 10 Nov 2026 11:26:43 -0500 Subject: [PATCH 1/3] fix(appjail): run appjail with PAGER=cat appjail logs read pages its output through $PAGER even when stdout is a pipe, and dbuild calls it through doas, which drops the caller's environment. The less it starts waits on a terminal nobody has, so the AppJail CIT sat for hours in the ready wait. Set PAGER=cat in appjail's environment for every call. --- dbuild/appjail.py | 5 ++++- tests/test_appjail.py | 26 ++++++++++++++++++++++++++ 2 files changed, 30 insertions(+), 1 deletion(-) create mode 100644 tests/test_appjail.py diff --git a/dbuild/appjail.py b/dbuild/appjail.py index 39e2149..5805e09 100644 --- a/dbuild/appjail.py +++ b/dbuild/appjail.py @@ -51,7 +51,10 @@ def _run( cmd = _priv_prefix() + cmd if not quiet: log.info(f"$ {' '.join(cmd)}") - result = subprocess.run(cmd, capture_output=capture, text=True) + # appjail pages `logs read` through $PAGER even on a pipe, and less waits + # on a terminal nobody has: the run hangs. + env = {**os.environ, "PAGER": "cat"} + result = subprocess.run(cmd, capture_output=capture, text=True, env=env) if check and result.returncode != 0: stderr = result.stderr.strip() if result.stderr else "" raise AppJailError(cmd, result.returncode, stderr) diff --git a/tests/test_appjail.py b/tests/test_appjail.py new file mode 100644 index 0000000..50812aa --- /dev/null +++ b/tests/test_appjail.py @@ -0,0 +1,26 @@ +"""Tests for dbuild.appjail helpers.""" + +import subprocess +from unittest.mock import patch + +from dbuild import appjail + + +def test_run_sets_pager_to_cat(): + """`appjail logs read` pages through $PAGER; cat keeps it from blocking.""" + seen = {} + + def fake_run(cmd, **kwargs): + seen["cmd"] = cmd + seen["env"] = kwargs.get("env") + return subprocess.CompletedProcess(cmd, 0, "", "") + + with ( + patch("dbuild.appjail.subprocess.run", side_effect=fake_run), + patch("dbuild.appjail._priv_prefix", return_value=[]), + patch.dict("os.environ", {"PAGER": "less"}), + ): + appjail._run(["appjail", "logs", "read", "jails/x/container/y.log"]) + + assert seen["cmd"][0] == "appjail" + assert seen["env"]["PAGER"] == "cat" From 6bd111db23fa835688b4219d42ea155579fbe633 Mon Sep 17 00:00:00 2001 From: Michael Johnson Date: Tue, 10 Nov 2026 11:26:43 -0500 Subject: [PATCH 2/3] fix(test): end the ready wait when the port opens Images without cit.ready waited the full cit.wait for a log pattern that base-exec never prints, then passed on the port and health checks anyway: two minutes per backend on every CI job for about a third of the fleet. Race the pattern against a TCP connect on cit.port and report the new ready state "port" when the port wins; the pattern still wins when it matches first. The three poll loops now use a monotonic deadline instead of summing sleeps, so connect time counts. The timeout warning names the port, and only mentions s6 notification-fd when the repo has root/etc/services.d. Measured on stalwart:pkg, podman: 130 s to 5 s. --- README.md | 7 ++- dbuild/test.py | 103 ++++++++++++++++++++++++++++++++------------- tests/test_test.py | 87 +++++++++++++++++++++++++++++++++++++- 3 files changed, 164 insertions(+), 33 deletions(-) diff --git a/README.md b/README.md index d7806e0..5ad807f 100644 --- a/README.md +++ b/README.md @@ -373,8 +373,11 @@ doas podman save ghcr.io/daemonless/myapp:build-latest | ssh jupiter doas podman ``` Each test is `"pass"`, `"fail"`, or `"skip"`. The `ready` key can also be -`"timeout"`: the log ready-pattern never matched but the run continued — -worth checking for a missing s6 `notification-fd` or a stale `ready:` regex. +`"port"`: the port accepted a connection before any log line matched the +ready pattern, so `cit.ready` (or the built-in patterns) is unused for this +image; or `"timeout"`: neither happened within `wait`, the run continued and +the port/health checks decided. A `timeout` on an image that then passes +means a stale `ready:` regex (or, on an s6 image, a missing `notification-fd`). ## Development diff --git a/dbuild/test.py b/dbuild/test.py index c208fbf..cf551f7 100644 --- a/dbuild/test.py +++ b/dbuild/test.py @@ -265,6 +265,23 @@ def _resolve_mode( # ── Ready-pattern log waiting ──────────────────────────────────────── +def _port_open(ip: str, port: int, timeout: float = 1.0) -> bool: + """One TCP connect attempt; True when something accepts on ip:port.""" + sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + sock.settimeout(timeout) + try: + return sock.connect_ex((ip, port)) == 0 + except OSError: + return False + finally: + sock.close() + + +def _s6_image(repo_dir: Path | None = None) -> bool: + """Whether the repo ships s6 service dirs (the notification-fd hint applies).""" + return ((repo_dir or Path.cwd()) / "root" / "etc" / "services.d").is_dir() + + def _wait_for_ready( cname: str, patterns: str, @@ -272,17 +289,29 @@ def _wait_for_ready( *, backend: ContainerBackend, poll_interval: float = 3.0, + ip: str | None = None, + port: int | None = None, + s6_hint: bool = False, ) -> str: - """Poll container logs for ready patterns. + """Poll container logs for ready patterns, racing them against the port. - Returns ``"ready"`` when a pattern matched, ``"timeout"`` when the - timeout elapsed without a match (non-fatal -- the port/health checks - decide), ``"crashed"`` when a fatal crash pattern is detected, or - ``"exited"`` when the container died during the wait. + Returns ``"ready"`` when a pattern matched, ``"port"`` when *ip*:*port* + accepted a connection before any pattern did (the app is up; the + pattern was only ever a fast path), ``"timeout"`` when the timeout + elapsed with neither (non-fatal -- the port/health checks decide), + ``"crashed"`` when a fatal crash pattern is detected, or ``"exited"`` + when the container died during the wait. + + Without a port the wait is pattern-only; the PUID phase uses that to + wait for init to finish, which no open port can prove. """ compiled = re.compile(patterns) - elapsed = 0.0 - while elapsed < timeout: + # Wall clock, not a sum of sleeps: a connect that hangs for its own + # timeout is time spent too, and the old sum stretched 120 s to 200 s. + start = time.monotonic() + deadline = start + timeout + while time.monotonic() < deadline: + elapsed = time.monotonic() - start if not backend.running(cname, quiet=True): log.error("Container exited during ready wait") for line in backend.logs(cname).splitlines()[-50:]: @@ -309,13 +338,25 @@ def _wait_for_ready( log.info(f" {line}") return "crashed" + if ip and port and _port_open(ip, port): + log.info( + f"Port {port} open after {elapsed:.1f}s with no ready line matched " + "-- cit.ready is unused for this image" + ) + return "port" + time.sleep(poll_interval) - elapsed += poll_interval - log.warn( - f"No ready signal after {timeout}s -- check the ready pattern, or a " - "missing s6 notification-fd if the run script uses s6-ready-when" - ) + hint = "" + if s6_hint: + hint = ", or a missing s6 notification-fd if the run script uses s6-ready-when" + if port: + log.warn( + f"No ready signal after {timeout}s: no log line matched the ready pattern " + f"and port {port} never opened -- check the ready pattern{hint}" + ) + else: + log.warn(f"No ready signal after {timeout}s -- check the ready pattern{hint}") return "timeout" # not fatal -- the port/health check will catch failures @@ -381,19 +422,14 @@ def _test_port( ) -> bool: """Wait for a TCP port to be listening using stdlib socket.""" log.info(f"Waiting for {ip}:{port} (timeout: {timeout}s)") - elapsed = 0.0 - while elapsed < timeout: - sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) - sock.settimeout(min(2.0, max(0.01, float(timeout) - elapsed))) - try: - result = sock.connect_ex((ip, port)) - if result == 0: - log.info(f"Port ready after {elapsed:.1f}s") - return True - finally: - sock.close() + start = time.monotonic() + deadline = start + timeout + while time.monotonic() < deadline: + elapsed = time.monotonic() - start + if _port_open(ip, port, min(2.0, max(0.01, float(timeout) - elapsed))): + log.info(f"Port ready after {elapsed:.1f}s") + return True time.sleep(poll_interval) - elapsed += poll_interval log.error(f"Port {port} not listening after {timeout}s") return False @@ -425,10 +461,12 @@ def _test_health( ctx.check_hostname = False ctx.verify_mode = ssl.CERT_NONE - elapsed = 0.0 + start = time.monotonic() + deadline = start + timeout last = "no response" http_timeout = min(5.0, max(0.1, float(timeout))) - while elapsed < timeout: + while time.monotonic() < deadline: + elapsed = time.monotonic() - start try: if https: conn = http.client.HTTPSConnection(ip, port, timeout=http_timeout, context=ctx) @@ -451,7 +489,6 @@ def _test_health( pass time.sleep(poll_interval) - elapsed += poll_interval log.error(f"Health check failed after {timeout}s (last: {last})") return False @@ -667,8 +704,11 @@ def _functional_checks( return 1 log.info(f"Container IP: {ip}") if mode in ("health", "screenshot"): - state = _wait_for_ready(cname, ready_patterns, test.wait, backend=backend) - results["ready"] = {"ready": "pass", "timeout": "timeout"}.get(state, "fail") + state = _wait_for_ready( + cname, ready_patterns, test.wait, backend=backend, + ip=ip, port=port, s6_hint=_s6_image(), + ) + results["ready"] = {"ready": "pass", "port": "port", "timeout": "timeout"}.get(state, "fail") if state in ("exited", "crashed"): return 1 @@ -1125,7 +1165,10 @@ def run_screenshot(cfg: Config, args: argparse.Namespace) -> int: log.info(f"Container IP: {ip}") # Wait for ready - state = _wait_for_ready(container_name, ready_patterns, test.wait, backend=backend) + state = _wait_for_ready( + container_name, ready_patterns, test.wait, backend=backend, + ip=ip, port=port, s6_hint=_s6_image(repo_dir), + ) if state in ("exited", "crashed"): return 1 diff --git a/tests/test_test.py b/tests/test_test.py index 6411b35..dd10c94 100644 --- a/tests/test_test.py +++ b/tests/test_test.py @@ -369,6 +369,36 @@ def test_none_when_no_image(self): self.assertIsNone(ref) +class _FakeClock: + """time.monotonic/time.sleep stand-in: sleep advances the clock.""" + + def __init__(self): + self.now = 0.0 + + def monotonic(self): + return self.now + + def advance(self, seconds): + self.now += seconds + + +class _fake_clock: + """Patch dbuild.test's time.sleep and time.monotonic with one _FakeClock.""" + + def __enter__(self): + self.clock = _FakeClock() + self._p1 = patch("dbuild.test.time.sleep", side_effect=self.clock.advance) + self._p2 = patch("dbuild.test.time.monotonic", side_effect=self.clock.monotonic) + self._p1.start() + self._p2.start() + return self.clock + + def __exit__(self, *exc): + self._p2.stop() + self._p1.stop() + return False + + class _FakeReadyBackend: """Minimal backend fake for _wait_for_ready().""" @@ -394,9 +424,64 @@ def test_ready_on_pattern_match(self): def test_timeout_when_no_match(self): be = _FakeReadyBackend(logs="still warming up\n") - with patch("dbuild.test.time.sleep"): + with _fake_clock(): + state = cit._wait_for_ready("c", r"Server started", 3, backend=be) + self.assertEqual(state, "timeout") + + def test_port_open_ends_the_wait(self): + # No log line ever matches, but the app accepts on its port: that is + # ready, and the wait must not run to its timeout. + be = _FakeReadyBackend(logs="[init] Executing as bsd: /daemonless/libexec/app\n") + with _fake_clock() as clock, patch("dbuild.test._port_open", return_value=True): + state = cit._wait_for_ready( + "c", r"Server started", 120, backend=be, ip="10.88.0.2", port=8080, + ) + self.assertEqual(state, "port") + self.assertLess(clock.now, 10) + + def test_pattern_wins_over_port(self): + be = _FakeReadyBackend(logs="Server started\n") + with _fake_clock(), patch("dbuild.test._port_open", return_value=True): + state = cit._wait_for_ready( + "c", r"Server started", 10, backend=be, ip="10.88.0.2", port=8080, + ) + self.assertEqual(state, "ready") + + def test_without_port_the_wait_is_pattern_only(self): + # The PUID phase waits for init to finish; an open port proves nothing there. + be = _FakeReadyBackend(logs="still warming up\n") + with _fake_clock(), patch("dbuild.test._port_open", return_value=True) as po: state = cit._wait_for_ready("c", r"Server started", 3, backend=be) self.assertEqual(state, "timeout") + po.assert_not_called() + + def test_timeout_is_wall_clock_not_a_sum_of_sleeps(self): + # Each log read costs 4 s of wall clock; with a 3 s poll interval the + # old sum-of-sleeps loop would poll 10/3 -> 4 times (28 s real time). + be = _FakeReadyBackend(logs="still warming up\n") + with _fake_clock() as clock: + orig = be.logs + + def slow_logs(cname, quiet=False): + clock.advance(4) + return orig(cname, quiet=quiet) + + be.logs = slow_logs + state = cit._wait_for_ready("c", r"Server started", 10, backend=be) + self.assertEqual(state, "timeout") + self.assertLess(clock.now, 10 + 7 + 1) # one poll (4+3) may overrun the deadline + + def test_timeout_warning_names_the_port_and_s6_only_when_asked(self): + be = _FakeReadyBackend(logs="still warming up\n") + with _fake_clock(), patch("dbuild.test._port_open", return_value=False), \ + patch("dbuild.test.log.warn") as warn: + cit._wait_for_ready("c", r"x", 3, backend=be, ip="10.88.0.2", port=8080) + msg = warn.call_args[0][0] + self.assertIn("port 8080 never opened", msg) + self.assertNotIn("notification-fd", msg) + with _fake_clock(), patch("dbuild.test.log.warn") as warn: + cit._wait_for_ready("c", r"x", 3, backend=be, s6_hint=True) + self.assertIn("notification-fd", warn.call_args[0][0]) def test_exited_when_container_dies(self): be = _FakeReadyBackend(running=False) From 53074e8cef05887c5f2a4fdce59ff2458710609f Mon Sep 17 00:00:00 2001 From: Michael Johnson Date: Wed, 11 Nov 2026 17:29:47 -0500 Subject: [PATCH 3/3] fix(appjail): set PAGER=cat past doas with env(1) Passing PAGER in the subprocess environment only reaches doas, which drops it, so appjail logs read still started less and the AppJail CIT hung on saturn. Put env PAGER=cat between the privilege prefix and appjail instead; it works the same as root. Proven on an immich-ml AppJail CIT: no pager, port ready, health 200. --- dbuild/appjail.py | 10 +++++----- tests/test_appjail.py | 8 +++----- 2 files changed, 8 insertions(+), 10 deletions(-) diff --git a/dbuild/appjail.py b/dbuild/appjail.py index 5805e09..90c0c4f 100644 --- a/dbuild/appjail.py +++ b/dbuild/appjail.py @@ -48,13 +48,13 @@ def _run( check: bool = True, quiet: bool = False, ) -> subprocess.CompletedProcess[str]: - cmd = _priv_prefix() + cmd + # appjail pages `logs read` through $PAGER even on a pipe, and less waits + # on a terminal nobody has: the run hangs. doas drops the environment, so + # set PAGER past it with env(1). + cmd = [*_priv_prefix(), "env", "PAGER=cat", *cmd] if not quiet: log.info(f"$ {' '.join(cmd)}") - # appjail pages `logs read` through $PAGER even on a pipe, and less waits - # on a terminal nobody has: the run hangs. - env = {**os.environ, "PAGER": "cat"} - result = subprocess.run(cmd, capture_output=capture, text=True, env=env) + result = subprocess.run(cmd, capture_output=capture, text=True) if check and result.returncode != 0: stderr = result.stderr.strip() if result.stderr else "" raise AppJailError(cmd, result.returncode, stderr) diff --git a/tests/test_appjail.py b/tests/test_appjail.py index 50812aa..ccc9535 100644 --- a/tests/test_appjail.py +++ b/tests/test_appjail.py @@ -12,15 +12,13 @@ def test_run_sets_pager_to_cat(): def fake_run(cmd, **kwargs): seen["cmd"] = cmd - seen["env"] = kwargs.get("env") return subprocess.CompletedProcess(cmd, 0, "", "") with ( patch("dbuild.appjail.subprocess.run", side_effect=fake_run), - patch("dbuild.appjail._priv_prefix", return_value=[]), - patch.dict("os.environ", {"PAGER": "less"}), + patch("dbuild.appjail._priv_prefix", return_value=["doas"]), ): appjail._run(["appjail", "logs", "read", "jails/x/container/y.log"]) - assert seen["cmd"][0] == "appjail" - assert seen["env"]["PAGER"] == "cat" + # env(1) sits between doas and appjail, so doas cannot drop the variable. + assert seen["cmd"][:4] == ["doas", "env", "PAGER=cat", "appjail"]