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/appjail.py b/dbuild/appjail.py index 39e2149..90c0c4f 100644 --- a/dbuild/appjail.py +++ b/dbuild/appjail.py @@ -48,7 +48,10 @@ 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)}") result = subprocess.run(cmd, capture_output=capture, text=True) 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_appjail.py b/tests/test_appjail.py new file mode 100644 index 0000000..ccc9535 --- /dev/null +++ b/tests/test_appjail.py @@ -0,0 +1,24 @@ +"""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 + return subprocess.CompletedProcess(cmd, 0, "", "") + + with ( + patch("dbuild.appjail.subprocess.run", side_effect=fake_run), + patch("dbuild.appjail._priv_prefix", return_value=["doas"]), + ): + appjail._run(["appjail", "logs", "read", "jails/x/container/y.log"]) + + # env(1) sits between doas and appjail, so doas cannot drop the variable. + assert seen["cmd"][:4] == ["doas", "env", "PAGER=cat", "appjail"] 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)