feat/cit ready port race

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
 

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)

dbuild/test.py

@@ -265,24 +265,53 @@ 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,
     timeout: int,
     *,
     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
 

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"]

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)