Danielvallance/arm ci

.github/workflows/test-examples.yaml

@@ -147,18 +147,25 @@ jobs:
     needs: detect-changes
     if: needs.detect-changes.outputs.matrix != ''
     timeout-minutes: 60
-    runs-on: ubuntu-latest
+    runs-on: ${{ matrix.os }}
 
     strategy:
       fail-fast: false
       matrix:
+        os: [ ubuntu-latest, ubuntu-24.04-arm ]
         example: ${{ fromJson(needs.detect-changes.outputs.matrix) }}
 
-    name: pytest (${{ matrix.example }})
+    name: pytest (${{ matrix.example }}) (${{ matrix.os }})
 
     steps:
     - uses: actions/checkout@v5
 
+    - name: Set up QEMU
+      if: matrix.os == 'ubuntu-24.04-arm'
+      uses: docker/setup-qemu-action@v4
+      with: 
+        image: tonistiigi/binfmt:qemu-v10.0.4
+
     - name: Set up Python
       uses: actions/setup-python@v5
       with:
@@ -175,7 +182,7 @@ jobs:
         pip install -r requirements.txt
 
     - name: Install Unikraft CLI
-      uses: unikraft/setup-action@main
+      uses: unikraft/setup-action@v1.0.1
       with:
         version: ${{ inputs.unikraft_version || 'latest' }}
 
@@ -204,11 +211,11 @@ jobs:
 
     - name: Run tests
       env:
-        UKC_TEST_ID: ${{ github.run_id }}-${{ matrix.example}}-${{ github.run_attempt }}
+        UKC_TEST_ID: ${{ github.run_id }}-${{ matrix.os }}-${{ matrix.example}}-${{ github.run_attempt }}
       run: exec pytest --log-cli-level=INFO "${{ matrix.example }}"
 
     - name: Cleanup test resources
       if: always()
       env:
-        UKC_TEST_ID: ${{ github.run_id }}-${{ matrix.example}}-${{ github.run_attempt }}
+        UKC_TEST_ID: ${{ github.run_id }}-${{ matrix.os }}-${{ matrix.example}}-${{ github.run_attempt }}
       run: bash scripts/cleanup-test-resources.sh

_testlib/readiness.py

@@ -0,0 +1,94 @@
+"""Readiness helper for services that are still warming up.
+
+``wait_instance(..., "running")`` reports the Unikraft Cloud *instance*
+lifecycle state — the unikernel booted and its entrypoint started. It says
+nothing about whether the service inside has finished initialising, and
+because unikernels boot in milliseconds that second gap is routinely the
+larger of the two.
+
+Databases make this especially visible: they accept TCP connections well
+before they are ready to serve. PostgreSQL answers with ``FATAL: the database
+system is starting up`` while ``initdb`` runs, and a client-side
+``connect_timeout`` does not help — the connection itself *succeeds*, the
+server simply rejects the session.
+
+:func:`retry_until_ready` closes that gap for connection-oriented clients,
+mirroring the retry behaviour :mod:`_testlib.http_client` already provides for
+HTTP endpoints.
+"""
+
+from __future__ import annotations
+
+import logging
+import time
+from typing import Callable, TypeVar
+
+log = logging.getLogger(__name__)
+
+T = TypeVar("T")
+
+DEFAULT_TIMEOUT = 120.0
+DEFAULT_BACKOFF = 2.0
+
+
+def retry_until_ready(
+    fn: Callable[[], T],
+    *,
+    exceptions: type[BaseException] | tuple[type[BaseException], ...],
+    timeout: float = DEFAULT_TIMEOUT,
+    backoff: float = DEFAULT_BACKOFF,
+    description: str = "service",
+) -> T:
+    """Call ``fn`` until it succeeds, returning its result.
+
+    The budget is wall-clock (``timeout`` seconds in total), deliberately not a
+    retry count: these clients already carry their own multi-second connect
+    timeouts, so a fixed number of attempts would multiply into a worst case of
+    many minutes. A deadline bounds the total regardless of how long any single
+    attempt blocks.
+
+    Only ``exceptions`` are retried; anything else propagates immediately, so a
+    genuine bug is never hidden behind a warm-up loop. If the budget expires,
+    the last failure is re-raised with its original traceback.
+
+    Wrap whichever call actually performs I/O:
+
+    * Eager clients (``psycopg2``, ``pymysql``) connect in the constructor, so
+      wrap the constructor and keep what it returns::
+
+          conn = retry_until_ready(
+              lambda: psycopg2.connect(...),
+              exceptions=psycopg2.OperationalError,
+              description="postgres",
+          )
+
+    * Lazy clients (``redis``, ``pymongo``, ``pymemcache``) do no I/O until
+      first use, so the constructor alone proves nothing. Build the client once
+      and wrap a cheap readiness probe instead::
+
+          client = redis.Redis(...)
+          retry_until_ready(
+              client.ping,
+              exceptions=redis.ConnectionError,
+              description="redis",
+          )
+    """
+    deadline = time.monotonic() + timeout
+    attempt = 0
+
+    while True:
+        attempt += 1
+        try:
+            return fn()
+        except exceptions as exc:
+            remaining = deadline - time.monotonic()
+            log.warning(
+                "%s not ready (attempt %d, %.0fs of budget left): %s",
+                description,
+                attempt,
+                max(remaining, 0.0),
+                exc,
+            )
+            if remaining <= backoff:
+                raise
+            time.sleep(backoff)

_testlib/unikraft.py

@@ -10,15 +10,25 @@
 import json
 import logging
 import os
+import re
 import shutil
 import subprocess
+import threading
+import time
 from dataclasses import dataclass
 from typing import Any, Mapping, Sequence
 
 log = logging.getLogger(__name__)
 
 UNIKRAFT_BIN = os.environ.get("UNIKRAFT_BIN", "unikraft")
 
+# BuildKit emits a step header (``#12 [build 3/4] RUN ...``) followed by a
+# completion marker (``#12 DONE 245.3s``) carrying that step's wall time — the
+# per-stage timings we care about. The byte-level layer progress in between
+# (``#6 sha256:... 0B / 63.99MB``) is pure noise, so it is kept at DEBUG.
+_ANSI_RE = re.compile(r"\x1b\[[0-9;?]*[a-zA-Z]")
+_STEP_RE = re.compile(r"^#\d+\s+(?:\[|DONE\b|CACHED\b|ERROR\b)")
+
 
 def _as_tuple(value: str | Sequence[str] | None) -> tuple[str, ...]:
     """Accept a single value or a sequence for repeatable flags."""
@@ -84,18 +94,36 @@ def run(
         check: bool = True,
         capture_output: bool = True,
         timeout: float | None = 600,
+        stream: bool = False,
+        env: Mapping[str, str] | None = None,
     ) -> subprocess.CompletedProcess[str]:
+        """Invoke the CLI.
+
+        With ``stream=False`` the output is buffered and returned, which is
+        what the JSON-emitting commands need. With ``stream=True`` it is
+        surfaced line by line as it is produced: a long build then reports its
+        progress live, and — crucially — a build that is later killed by
+        ``timeout`` still leaves a record of how far it got. Buffered output is
+        discarded when the process is killed, which is why a timing-sensitive
+        command must not use it.
+        """
         bin_path = _resolve_bin()
         cmd = [bin_path, *args]
         log.debug("exec: %s (cwd=%s)", " ".join(cmd), cwd)
 
+        if stream:
+            return self._run_streaming(
+                cmd, args, cwd=cwd, check=check, timeout=timeout, env=env
+            )
+
         proc = subprocess.run(
             cmd,
             cwd=str(cwd) if cwd else None,
             check=False,
             capture_output=capture_output,
             text=True,
             timeout=timeout,
+            env={**os.environ, **env} if env else None,
         )
 
         if proc.stdout:
@@ -108,9 +136,79 @@ def run(
                 f"stdout: {proc.stdout}\n"
                 f"stderr: {proc.stderr}"
             )
-        
+
         return proc
 
+    def _run_streaming(
+        self,
+        cmd: Sequence[str],
+        args: Sequence[str],
+        *,
+        cwd: str | os.PathLike[str] | None,
+        check: bool,
+        timeout: float | None,
+        env: Mapping[str, str] | None,
+    ) -> subprocess.CompletedProcess[str]:
+        """Run ``cmd``, logging its merged output as it arrives.
+
+        A reader thread pumps the pipe so the parent never blocks on a full
+        buffer while waiting out the timeout.
+        """
+        popen = subprocess.Popen(
+            list(cmd),
+            cwd=str(cwd) if cwd else None,
+            stdout=subprocess.PIPE,
+            stderr=subprocess.STDOUT,
+            text=True,
+            bufsize=1,
+            env={**os.environ, **env} if env else None,
+        )
+
+        collected: list[str] = []
+
+        def _pump() -> None:
+            assert popen.stdout is not None
+            for raw in popen.stdout:
+                line = _ANSI_RE.sub("", raw).rstrip()
+                collected.append(line)
+                # The CLI wraps its own output in box-drawing characters;
+                # strip them so BuildKit's step markers still match.
+                probe = line.lstrip("│┏┗├└ \t")
+                if _STEP_RE.match(probe) or "error" in probe.lower():
+                    log.info("%s", line)
+                else:
+                    log.debug("%s", line)
+
+        pump = threading.Thread(target=_pump, daemon=True)
+        pump.start()
+
+        try:
+            popen.wait(timeout=timeout)
+        except subprocess.TimeoutExpired:
+            popen.kill()
+            popen.wait()
+            # Drain whatever is already buffered so the timeout still carries
+            # the progress so far, then give up on the reader: a grandchild
+            # (BuildKit) may keep the pipe open after the CLI is killed. The
+            # thread is a daemon, so it cannot hold up interpreter exit.
+            # Joined here and *not* in a `finally`, so this bounded wait is
+            # paid once rather than twice.
+            pump.join(timeout=5)
+            raise subprocess.TimeoutExpired(
+                list(cmd), timeout, output="\n".join(collected)
+            ) from None
+
+        pump.join(timeout=5)
+
+        output = "\n".join(collected)
+        if check and popen.returncode != 0:
+            raise UnikraftError(
+                f"`unikraft {' '.join(args)}` exited with {popen.returncode}\n"
+                f"output: {output}"
+            )
+
+        return subprocess.CompletedProcess(list(cmd), popen.returncode, output, "")
+
     # ------------------------------------------------------------------
     # High-level helpers
     # ------------------------------------------------------------------
@@ -121,18 +219,43 @@ def build(
         output: str,
         *,
         extra_args: Sequence[str] = (),
+        timeout: float | None = 1800,
     ) -> None:
         """Build an image from ``context`` and publish/tag it as ``output``.
 
         ``output`` is typically ``<org>/<name>:<tag>`` as shown in example
         READMEs, e.g. ``my-org/nginx:test``.
+
+        The default timeout is deliberately generous: on a non-amd64 runner the
+        amd64 stages execute under QEMU and both architectures of every base
+        image have to be pulled, so a build that takes ~3 minutes on x86 can
+        take several times that. A too-tight limit SIGKILLs the build before it
+        can report anything, which hides the very information needed to tell
+        "genuinely too slow" from "slower than the limit".
+
+        Progress is streamed, so BuildKit's per-step ``DONE <n>s`` markers land
+        in the log and show where the time actually went.
         """
         log.info(
-            "building image from context %s with output tag %s", 
-            context, 
-            output
+            "building image from context %s with output tag %s (timeout=%ss)",
+            context,
+            output,
+            timeout,
         )
-        self.run(["build", str(context), "--output", output, *extra_args])
+
+        started = time.monotonic()
+        try:
+            self.run(
+                ["build", str(context), "--output", output, *extra_args],
+                timeout=timeout,
+                stream=True,
+                # Best-effort: ask for non-interactive progress so each step is
+                # emitted as its own line rather than a redrawn TTY display.
+                # Ignored by CLIs that do not honour it, which costs nothing.
+                env={"BUILDKIT_PROGRESS": "plain"},
+            )
+        finally:
+            log.info("build of %s took %.1fs", output, time.monotonic() - started)
 
     def run_instance(
         self,
@@ -223,7 +346,9 @@ def run_instance(
             memory,
             name,
         )
+        started = time.monotonic()
         proc = self.run(args)
+        log.info("instance start took %.1fs", time.monotonic() - started)
 
         return _parse_json(proc.stdout)
 
@@ -251,6 +376,7 @@ def wait_instance(
         Returns the parsed JSON description of the instance once it reaches
         the desired state.
         """
+        started = time.monotonic()
         proc = self.run(
             [
                 "instances",
@@ -263,6 +389,12 @@ def wait_instance(
             ],
             timeout=timeout,
         )
+        log.info(
+            "instance %s reached state %r after %.1fs",
+            target,
+            state,
+            time.monotonic() - started,
+        )
         return _parse_json(proc.stdout)
 
     def delete_instance(self, target: str) -> None:
@@ -362,7 +494,6 @@ def extract_instance_name(instance: dict[str, Any]) -> str:
         raise UnikraftError(
             "could not determine instance name/uuid from CLI output"
         )
-
     return name