test/docker: wait for the docker daemon in the coordinator instead of failing on a one-shot probe

scripts/agent.mjs

@@ -4,6 +4,7 @@
 
 import { copyFileSync, existsSync, readFileSync, realpathSync } from "node:fs";
 import { join } from "node:path";
+import { setTimeout as setTimeoutPromise } from "node:timers/promises";
 import { fileURLToPath } from "node:url";
 import { parseArgs } from "node:util";
 import {
@@ -21,11 +22,13 @@ import {
   getKernel,
   getOs,
   homedir,
+  isLinux,
   isMacOS,
   isPosix,
   isWindows,
   mkdir,
   spawnSafe,
+  spawnSync,
   which,
   writeFile,
 } from "./utils.mjs";
@@ -105,6 +108,15 @@ async function doBuildkiteAgent(action, cliOptions = {}) {
     }
 
     if (isOpenRc()) {
+      // openrc starts a runlevel's unrelated services one at a time in name
+      // order, so without `after docker` this service ("b") starts, and the
+      // ephemeral agent acquires its job, before the boot has reached "docker";
+      // the shard then begins with no daemon socket at all (routine on the
+      // alpine test agents, occasionally for minutes when a service in between
+      // is slow). `after` is ordering only: images without docker still boot
+      // the agent. Alpine's docker service returns as soon as dockerd is
+      // spawned, so start() below additionally waits for the daemon to answer.
+      // Both take effect when the images are next published.
       const servicePath = "/etc/init.d/buildkite-agent";
       const service = `#!/sbin/openrc-run
         name="buildkite-agent"
@@ -123,6 +135,7 @@ async function doBuildkiteAgent(action, cliOptions = {}) {
         depend() {
           need net
           use dns logger
+          after docker
         }
       `;
       writeFile(servicePath, service, { mode: 0o755 });
@@ -390,6 +403,19 @@ async function doBuildkiteAgent(action, cliOptions = {}) {
       .map(([key, value]) => `${key}=${value}`)
       .join(",");
 
+    // The job this machine was booted for starts the moment the agent
+    // registers (acquire-job above), and the Linux test jobs need dockerd. The
+    // init system only orders this service after docker's start script (see
+    // install()), which on alpine returns as soon as dockerd is spawned, so
+    // give the daemon a bounded head start here: registering later only
+    // delays the job, registering before the daemon listens starts the job
+    // against a dead socket (test/docker/index.ts has the history). Past the
+    // budget the agent registers anyway and the job's "--- Docker" section
+    // reports the daemon's state.
+    if (isLinux && which("docker")) {
+      await waitForDockerDaemon(2 * 60_000);
+    }
+
     await spawnSafe(
       [
         command,
@@ -410,6 +436,29 @@ async function doBuildkiteAgent(action, cliOptions = {}) {
   }
 }
 
+/**
+ * Polls `docker version` (which fails until the daemon is listening) once a
+ * second for up to `budgetMs`. Returns either way; the outcome is logged.
+ * @param {number} budgetMs
+ */
+async function waitForDockerDaemon(budgetMs) {
+  const startedAt = Date.now();
+  const elapsed = () => `${Math.round((Date.now() - startedAt) / 1000)}s`;
+  const reachable = () => spawnSync(["docker", "version"], { timeout: 10_000 }).exitCode === 0;
+  if (reachable()) {
+    return;
+  }
+  console.log(`Docker daemon is not reachable yet; waiting up to ${Math.round(budgetMs / 1000)}s for it...`);
+  while (Date.now() - startedAt < budgetMs) {
+    await setTimeoutPromise(1_000);
+    if (reachable()) {
+      console.log(`Docker daemon became reachable after ${elapsed()}`);
+      return;
+    }
+  }
+  console.warn(`Docker daemon still unreachable after ${elapsed()}; starting the agent without it`);
+}
+
 /**
  * @returns {boolean}
  */

scripts/utils.mjs

@@ -3160,7 +3160,29 @@ export function printEnvironment() {
       startGroup("Docker", () => {
         const shell = which(["sh", "bash"]);
         if (shell) {
-          spawnSync([shell, "-c", "docker ps"], { stdio: "inherit" });
+          const { exitCode } = spawnSync([shell, "-c", "docker ps"], { stdio: "inherit" });
+          if (exitCode !== 0) {
+            // The agent can start the job before the boot has brought dockerd
+            // up (scripts/agent.mjs orders and waits for it on images published
+            // after that change; test/docker/coordinator.ts waits for it on
+            // every image, so this is not fatal). On openrc the service table
+            // shows which boot step the daemon was still behind.
+            if (which("rc-status")) {
+              spawnSync([shell, "-c", "rc-status"], { stdio: "inherit" });
+            }
+            // One line per affected job under a single per-build annotation, so
+            // how often this still happens can be read off builds (and compared
+            // across image publishes) without grepping job logs. Info style:
+            // nothing has failed, and `bun run ci:errors` lists only error-style
+            // annotations.
+            reportAnnotationToBuildKite({
+              context: "docker-daemon-not-up-at-job-start",
+              label: "docker daemon not up at job start",
+              content: `- dockerd was not up when [${getBuildLabel()}](${getBuildUrl()}) started on \`${getHostname()}\`\n`,
+              style: "info",
+              priority: 1,
+            });
+          }
         }
       });
     }

test/cli/install/bun-install-proxy.test.ts

@@ -1,43 +1,38 @@
 import { beforeAll, it } from "bun:test";
-import { exec } from "child_process";
 import { rm } from "fs/promises";
-import { bunEnv, bunExe, dockerExe, isDockerEnabled, tempDirWithFiles } from "harness";
+import { bunEnv, bunExe, isDockerEnabled, tempDirWithFiles } from "harness";
 import { join } from "path";
-import { promisify } from "util";
-const execAsync = promisify(exec);
-const dockerCLI = dockerExe() as string;
-const SQUID_URL = "http://127.0.0.1:3128";
+import { ensure } from "../../docker/index.ts";
+
+let SQUID_URL: string;
 if (isDockerEnabled()) {
+  // The compose `squid` service is the same ubuntu/squid image this file used
+  // to `docker run` itself on a fixed host port. Going through ensure() means
+  // the shard's coordinator starts it (and waits for the docker daemon if the
+  // job began before it was up) and it gets a free port like every other
+  // test service.
   beforeAll(async () => {
-    async function isSquidRunning() {
-      const text = await fetch(SQUID_URL)
-        .then(res => res.text())
-        .catch(() => {});
-      return text?.includes("squid") ?? false;
-    }
-    if (!(await isSquidRunning())) {
-      // try to create or error if is already created
-      await execAsync(
-        `${dockerCLI} run -d --name squid-container -e TZ=UTC -p 3128:3128 ubuntu/squid:5.2-22.04_beta`,
-      ).catch(() => {});
-
-      async function waitForSquid(max_wait = 60_000) {
-        const start = Date.now();
-        while (true) {
-          if (await isSquidRunning()) {
-            return;
-          }
-          if (Date.now() - start > max_wait) {
-            throw new Error("Squid did not start in time");
-          }
-
-          await Bun.sleep(1000);
-        }
-      }
-      // wait for squid to start
-      await waitForSquid();
+    const squid = await ensure("squid");
+    SQUID_URL = `http://${squid.host}:${squid.ports[3128]}`;
+    // The container counts as healthy once the squid process exists. Like the
+    // isSquidRunning() loop this replaces, wait until it answers HTTP (a plain
+    // GET of the proxy itself gets squid's own error page) before installing
+    // through it.
+    const squidAnswers = async () => {
+      const body = await fetch(SQUID_URL, { signal: AbortSignal.timeout(5_000) }).then(
+        res => res.text(),
+        () => "",
+      );
+      return body.includes("squid");
+    };
+    const deadline = Date.now() + 30_000;
+    while (!(await squidAnswers())) {
+      if (Date.now() > deadline) throw new Error(`squid at ${SQUID_URL} did not answer within 30s`);
+      await Bun.sleep(250);
     }
-  });
+    // Same hook budget as describeWithContainer(): a cold start is a `compose
+    // build` plus `up --wait` with a 180s wait-timeout.
+  }, 240_000);
 
   it("bun install with proxy with big packages", async () => {
     const files = {

test/docker/coordinator.ts

@@ -17,13 +17,18 @@
  * predicts which services argv's tests need and starts them at launch, so
  * they're healthy by the time the first test asks.
  *
+ * It is also the one place that waits for the docker daemon itself: the agent
+ * can start the shard while dockerd is still coming up, and every request
+ * (prestart or test) blocks on the shared wait below instead of failing on a
+ * one-shot probe.
+ *
  * Lifetime is tied to the runner: stdin is a pipe from it, and EOF means the
  * runner is gone.
  */
 
 import { unlinkSync } from "node:fs";
 import * as net from "node:net";
-import { ensure, type ServiceInfo, type ServiceName } from "./index.ts";
+import { ensure, waitForDockerDaemon, type ServiceInfo, type ServiceName } from "./index.ts";
 import { prestartMap as prestartMapRaw } from "./prestart-map.mjs";
 
 // Keys are paths relative to test/ — that's the shape runner.node.mjs passes
@@ -44,6 +49,30 @@ if (!socketPath) {
 // environment.
 delete process.env.BUN_DOCKER_COORDINATOR;
 
+// The shard may start before dockerd has finished coming up (see
+// waitForDockerDaemon); start polling for it right away so the wait overlaps
+// the non-container tests the runner schedules first. The window is well past
+// the latest the daemon has been seen to appear in CI (up by ~7 minutes into
+// the job); once it closes, requests fail immediately, so a host whose daemon
+// never comes up costs the shard one window rather than a full wait per file
+// attempt. The per-request cap is the budget scripts/runner.node.mjs gives the
+// hook that is typically awaiting the request (--timeout = testTimeout / 2 on
+// the release lanes; the ASAN lanes get three times that but run on systemd
+// images, where the daemon has always been up at job start), so a request
+// either gets the daemon or a clear error within the time its caller has
+// anyway, and the 3-minute file budget keeps room for `compose up` and the
+// tests after it. A file whose request hits the cap is retried by the runner,
+// and the retry's request gets a fresh cap against the same shared wait, so a
+// file's four attempts together cover ~6 minutes of daemon lateness from the
+// file's first request (container-backed files are also scheduled late in the
+// shard, see prestart-map.mjs).
+const awaitDockerDaemon = waitForDockerDaemon({
+  windowMs: 10 * 60_000,
+  pollMs: 1_000,
+  log: message => console.log(`coordinator: ${message}`),
+});
+const DAEMON_WAIT_PER_REQUEST_MS = 90_000;
+
 // Collapse concurrent requests for one service onto a single ensureServiceNow(),
 // and remember the last ServiceInfo a successful ensure produced. The full
 // ensure() path costs several serial `docker compose` spawns (build, ps -a,
@@ -97,6 +126,7 @@ async function ensureServiceNow(service: ServiceName): Promise<ServiceInfo> {
 
   console.log(`coordinator: ensuring ${service}`);
   try {
+    await awaitDockerDaemon(DAEMON_WAIT_PER_REQUEST_MS);
     const info = await ensure(service);
     console.log(`coordinator: ${service} ready`);
     lastGood.set(service, info);

test/docker/index.ts

@@ -125,6 +125,104 @@ function serviceFromEnv(service: ServiceName): ServiceInfo | null {
   return info;
 }
 
+/**
+ * One `docker version` round trip. The CLI exits non-zero until the daemon
+ * accepts connections on its socket, so this is the daemon readiness signal.
+ * (`docker compose version` is not: compose is a CLI plugin and succeeds with
+ * no daemon at all, which is why scripts/runner.node.mjs can use it to decide
+ * whether to start the coordinator before the daemon is up.) A daemon that
+ * accepts the connection but never answers would otherwise hang the CLI, and
+ * with it every wait built on this probe, so the CLI is killed after
+ * `timeoutMs` and counted as unreachable; a healthy round trip takes well
+ * under a second.
+ */
+export async function isDockerDaemonReachable(timeoutMs = 10_000): Promise<boolean> {
+  const proc = spawn({
+    cmd: ["docker", "version"],
+    stdout: "ignore",
+    stderr: "ignore",
+    timeout: timeoutMs,
+  });
+  return (await proc.exited) === 0;
+}
+
+export interface DockerDaemonWaitOptions {
+  /** Stop polling, and fail every waiter, once the daemon has stayed unreachable this long. */
+  windowMs: number;
+  /** Delay between probes. */
+  pollMs: number;
+  /** Replaces the `docker version` probe; tests script it. */
+  probe?: () => Promise<boolean>;
+  /** Where the "waiting" / "reachable after Ns" / "giving up" lines go. */
+  log?: (message: string) => void;
+}
+
+/**
+ * Starts polling for the docker daemon and returns `waitFor(capMs)`, which
+ * resolves once a probe has succeeded and rejects if the daemon is still
+ * unreachable after `capMs`, or once `windowMs` has passed in total. Every
+ * caller shares the one poll loop: a rejected `waitFor` does not stop it, so a
+ * caller that retries later gets the daemon as soon as it is up, and callers
+ * arriving after the window has closed fail immediately.
+ *
+ * Linux CI agents can pick up a job before dockerd has finished starting. The
+ * openrc (alpine) images published before scripts/agent.mjs ordered the agent
+ * service after docker routinely start a shard with no /var/run/docker.sock
+ * yet; the daemon usually appears within ~10s, but in builds 97891, 98647,
+ * 98707 and 98746 it was still down 3-4.5 minutes into the job and up by 5-7
+ * minutes, and the coordinator's one-shot probe failed every container-backed
+ * test file in those shards (all in-shard retries included, since they run
+ * within seconds of each other). The boot-ordering fix in agent.mjs is the
+ * primary fix once images are republished; this keeps shards green on the
+ * current images and covers whatever dockerd start-up time is left after it
+ * (the runner's `--- Docker` job section records how often that still
+ * happens). When a probe succeeds on the first try, which is the case on every
+ * systemd image, nothing is logged and `waitFor` costs nothing beyond that
+ * probe.
+ */
+export function waitForDockerDaemon({
+  windowMs,
+  pollMs,
+  probe = isDockerDaemonReachable,
+  log = console.log,
+}: DockerDaemonWaitOptions): (capMs: number) => Promise<void> {
+  const startedAt = Date.now();
+  const unreachableFor = () => `${Math.round((Date.now() - startedAt) / 1000)}s`;
+
+  const ready: Promise<void> = (async () => {
+    if (await probe()) return;
+    log(`docker daemon is not reachable yet; waiting up to ${Math.round(windowMs / 1000)}s for it to come up`);
+    while (Date.now() - startedAt < windowMs) {
+      await Bun.sleep(pollMs);
+      if (await probe()) {
+        log(`docker daemon became reachable after ${unreachableFor()}`);
+        return;
+      }
+    }
+    const message = `Docker daemon still unreachable after ${unreachableFor()} (\`docker version\` kept failing); not waiting for it any longer`;
+    log(message);
+    throw new Error(message);
+  })();
+  // The window can close while no request is waiting; each waiter gets the
+  // rejection through the race below, so it must not also be reported as an
+  // unhandled rejection here.
+  ready.catch(() => {});
+
+  return function waitFor(capMs: number): Promise<void> {
+    let timer: ReturnType<typeof setTimeout> | undefined;
+    const cap = new Promise<never>((_, reject) => {
+      timer = setTimeout(() => {
+        reject(
+          new Error(
+            `Docker daemon not reachable (unreachable for ${unreachableFor()} so far); gave up waiting for it after ${Math.round(capMs / 1000)}s for this request`,
+          ),
+        );
+      }, capMs);
+    });
+    return Promise.race([ready, cap]).finally(() => clearTimeout(timer));
+  };
+}
+
 interface DockerComposeOptions {
   projectName?: string;
   composeFile?: string;
@@ -174,15 +272,7 @@ class DockerComposeHelper {
   }
 
   async ensureDocker(): Promise<void> {
-    // Check Docker is available
-    const dockerCheck = spawn({
-      cmd: ["docker", "version"],
-      stdout: "pipe",
-      stderr: "pipe",
-    });
-
-    const exitCode = await dockerCheck.exited;
-    if (exitCode !== 0) {
+    if (!(await isDockerDaemonReachable())) {
       throw new Error("Docker is not available. Please ensure Docker is installed and running.");
     }
 

test/docker/prestart-map.mjs

@@ -25,6 +25,7 @@ export const prestartMap = {
   "js/bun/s3/": ["minio"],
   "js/web/websocket/autobahn": ["autobahn"],
   "js/web/websocket/websocket-proxy": ["squid"],
+  "cli/install/bun-install-proxy": ["squid"],
   "integration/mysql2/": ["mysql_plain", "mysql_native_password"],
   "regression/issue/21311": ["postgres_plain"],
   "regression/issue/24850": ["mysql_plain"],