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

Closed
RO
1mo ago
+574-45

Problem

  • test/js/sql/postgres-prepared-pipeline-reorder.test.ts went red on :alpine: 3.23 x64 in build 98746 with Failed to start service postgres_plain (via coordinator): Docker is not available. Please ensure Docker is installed and running. (thrown at test/docker/index.ts:336), on all four in-shard attempts. The same shard shape hit postgres-simple-query-pipeline and sql-onconnect-onclose-throw (98647), integration/mysql2 (98707) and sql.test.ts (97891); the second form of the failure is A functional \docker` is required in CI for some tests.fromisDockerEnabled()intest/harness.ts`.
  • Every one of those jobs is an alpine agent whose job started before dockerd was listening: the runner's --- Docker section prints dial unix /var/run/docker.sock: no such file or directory, the coordinator's prestart fails at ~+20s, the test files fail at +140..270s (the daemon is still down at the last of those), and in the three logs that run long enough the daemon is up by +305..405s. In build 98746, 6 of the 24 alpine jobs had no daemon at job start (5 of them got one within the next ~10s); all 116 debian/ubuntu jobs had one.
  • Root cause: scripts/agent.mjs installs the openrc buildkite-agent service with no ordering against docker. openrc starts a runlevel's unrelated services one at a time in name order, so the agent ("b") starts and acquires its job before the boot reaches "docker"; usually that is seconds later, and when a service in between is slow it is minutes. systemd images start everything in parallel, which is why this is alpine-only. Alpine's docker service also returns as soon as dockerd is spawned, so ordering alone still leaves dockerd's own start-up time.
  • Why it fails the tests: test/docker/coordinator.ts (since #32033) runs a single docker version per request and fails the request on the spot, and the runner's retries of a file run within seconds of each other, so a late daemon fails the file four times; isDockerEnabled() additionally runs docker info at import time of ~25 test files and throws in CI when the daemon is down.
  • No single commit to revert: the probe has been one-shot since the coordinator was introduced and the unit has been unordered since it was written; the daemon has been getting later on the alpine images recently. #34480 was an earlier attempt (30s poll in the runner, then exit 75 to re-run the shard on a new VM); closed as superseded by this PR.

Fix

Two layers, plus a way to see which one is doing the work:

  • Boot (the root-cause fix; scripts/agent.mjs, active from the next image publish): the openrc unit gets after docker, and start(), which is the boot command of the Linux images, polls docker version for up to two minutes before it starts buildkite-agent. The machine already holds its job (--acquire-job), so this only moves the job's start, and it covers everything in the job that talks to the daemon, including the few tests that call docker directly and the runner's own docker ps. Ordering is after, not need, so images without docker still boot; the poll is bounded, so a dead daemon delays a job by two minutes instead of never starting it. Activating it needs a [publish linux images] run per the flow documented in .buildkite/ci.mjs (no bootstrap version bump is needed for an agent.mjs change; #35996 was the same kind of republish). I have not triggered a publish from this PR since it replaces the live images; happy to amend the subject if a maintainer wants it done here, otherwise it rides along with the next publish.
  • Test infrastructure (what fixes CI on the images running today, and covers whatever daemon start-up time remains after the republish):
    • test/docker/index.ts: waitForDockerDaemon() runs one poll loop over docker version (each probe killed after 10s, so a CLI stuck on a half-up daemon counts as unreachable instead of stalling the loop) and returns waitFor(capMs): resolves once a probe succeeds, rejects a caller after its own cap while the loop keeps going, and after the 10-minute window every later caller fails immediately. A daemon that is up costs one probe and logs nothing.
    • test/docker/coordinator.ts: starts the wait at launch, so it overlaps the non-container tests the runner schedules first, and every ensure (prestart and test requests) awaits it for up to 90s before running compose. 90s is the per-test budget the runner gives the hook that is usually awaiting the request (--timeout = testTimeout / 2 on the release lanes), so a request gets the daemon or a clear error within the time its caller has anyway, the 3-minute file budget keeps room for compose up and the tests, and a file's four attempts cover ~6 minutes of lateness from its first request (container-backed files are also scheduled late in the shard), which covers every arrival seen above. The 10-minute window is well past the latest arrival seen (~6.7 minutes into the job) and bounds the cost of a daemon that never comes up to one window per shard instead of 4 x 90s per file.
    • test/harness.ts: isDockerEnabled() returns true when BUN_DOCKER_COORDINATOR is set (after the existing CLI and linux-arm64 checks) instead of probing the daemon itself, as describeWithContainer() and test/js/valkey/test-utils.ts already do; this is what lets sql.test.ts, sql-mysql.test.ts, s3.test.ts, autobahn, ... benefit from the wait, and it removes a docker info per file. Files that then use docker directly: bun-install-proxy.test.ts (converted below) and the four js/bun/test/parallel/test-docker-build-*.ts files, which the runner only runs after every other file in the shard has finished.
    • test/cli/install/bun-install-proxy.test.ts + test/docker/prestart-map.mjs: this file gated on isDockerEnabled() but then ran docker run -p 3128:3128 ubuntu/squid itself, so with the harness change it would have failed on its own 60s squid poll instead of at import. It now starts the compose squid service (built from the same image) through ensure(), keeps an HTTP readiness poll as before (the service's healthcheck only checks the process exists; each probe is bounded), and is in the prestart map so it runs late with squid prestarted, like websocket-proxy. It is in this PR because the harness change is what makes it necessary; #34175 touches the same file and will need a small rebase, noted there.
  • Visibility (scripts/utils.mjs): when docker ps fails in the job's --- Docker section, print rc-status (which boot step the daemon was behind) and append one info-style line to a per-build annotation, so the rate of jobs starting without the daemon can be read off builds before and after the republish. If it drops to zero after the publish, the coordinator wait is pure insurance and could be simplified; if not, it is still load-bearing. Info style keeps it out of bun run ci:errors, which lists error-style annotations only.
  • Why this shape: the daemon being up is a condition to wait for, and the two places to wait are where the invariant belongs (agent start-up, which needs a publish to reach the fleet) and the one process per shard that already owns docker and lives for the whole shard (which fixes the builds failing now and overlaps the wait with tests that do not need docker). Compared with #34480, nothing is added to the Buildkite retry rules (since rewritten to cover agent loss only), no shard is thrown away, and a 30s poll would not have covered any of the four builds above.
  • Unchanged behavior: local runs without a coordinator still fail fast in ensureDocker(); isDockerEnabled() still returns false on linux-arm64 and still probes when no coordinator is set; the runner still decides whether to spawn the coordinator from docker compose version, which does not need a daemon, so a late daemon still gets a coordinator; the systemd unit is untouched (the daemon has been up at job start on all 116 debian/ubuntu jobs sampled, and the start() poll covers those images too once published).
  • Verified: bun bd test test/internal/docker-coordinator.test.ts (8 pass). Scripted-probe tests cover a daemon that is up, concurrent waiters sharing one loop, a capped request followed by a successful retry, a request pending when the window closes, and the window closing with nobody waiting (fails with an escaped rejection if the internal catch is removed); a docker on PATH that sleeps pins the probe bound (fails without it); a fake docker whose first version fails checks isDockerEnabled() in a fresh process with and without the coordinator variable, and runs the real coordinator end to end (request answered with the port mapping; calls.log shows probe, probe, then compose). With test/docker/coordinator.ts reverted the end-to-end test fails with exactly the CI error; with test/harness.ts reverted the harness test fails with threw: A functional \docker` is required in CI for some tests.. The agent.mjs poll was run standalone against a docker that answers on the second probe (returns after 1s) and against none (returns at the budget); printEnvironment()was run with a fakerc-statusand a fakebuildkite-agenton PATH and produced the rc-status dump and the expectedannotate --append --style infocall;node --checkpasses on both scripts.bun-install-proxy.test.tshas no docker here, so its hook was exercised by pointingBUN_TEST_SERVICE_squidat a localBun.servestand-in: the hook resolves and the installs go through the stand-in's port. On the earlier CI runs of this branch the new test file passed on alpine x64, debian ASAN and darwin aarch64 (checked in the job logs), and an alpine shard'spostgres-listen-notify` log shows it getting postgres through the coordinator.

Background

  • Test-service coordinator: scripts/runner.node.mjs spawns test/docker/coordinator.ts once per Linux shard and exports its unix socket as BUN_DOCKER_COORDINATOR. ensure(service) in test/docker/index.ts, used by describeWithContainer() and the sql/valkey/s3 tests, sends the service name over that socket and gets back the container's host port mapping; the coordinator is the only process that runs docker compose up, and it prestarts the services the shard's files are known to need (prestart-map.mjs, which the runner also uses to schedule those files last). Without the variable (local runs) ensure() runs compose itself.
  • Runner retries and budgets: in CI a failing test file is re-run up to 3 more times immediately (--retries=3); each file's process gets 3 minutes (testTimeout), and bun test --timeout is set to half of that for individual tests and hooks (three times as much on ASAN lanes).
  • docker version vs docker compose version: the former talks to the daemon and exits non-zero until it is listening; the latter only checks the compose CLI plugin and succeeds with no daemon at all.
  • Ephemeral agents and images: each Linux test job gets a fresh VM booted from a pre-baked image whose boot command is scripts/agent.mjs start; the agent starts with --acquire-job and takes its job the moment it registers, so anything the boot has not finished by then races the job. Image contents (including agent.mjs) change only when images are republished ([publish images] on a PR, see .buildkite/ci.mjs).
  • openrc: Alpine's init system. Unless rc_parallel is enabled (it is not on these images) a runlevel's services start one at a time, ordered by declared dependencies and otherwise by name; after X orders a service after X when X is in the runlevel without making it a hard dependency. Alpine's docker service runs dockerd under supervise-daemon, so its start returns as soon as dockerd is spawned.
  • Buildkite annotations: buildkite-agent annotate --append --context X appends to one annotation per build, so many jobs appending a line each yields a single list per build.
Timelines from the four builds (seconds after job start) 
98746  alpine 3.23 x64  (ip-172-31-33-40-1)
  +11s  --- Docker: dial unix /var/run/docker.sock: no such file or directory
  +22s  COORDINATOR_READY; redis_unified, mysql_plain prestart fail: Docker is not available
 +170s  postgres-prepared-pipeline-reorder: 4 attempts, all "Docker is not available" (+170, +179, +190, +205)
 +210s  valkey: redis_unified request fails           <- still down
 +405s  coordinator: ensuring redis_unified -> ready at +416s   <- up
 +416s  coordinator: ensuring mysql_plain   -> ready at +445s

98647  alpine 3.23 x64
  +10s  --- Docker: socket missing;  +21s prestart fails
 +207..238s  postgres_plain requests fail;  +243..267s sql-onconnect-onclose-throw: isDockerEnabled() throws
 +310s  coordinator: postgres_plain ready                <- up (down at +267s)

98707  alpine 3.23 aarch64
  +10s  socket missing;  +18s prestart of 6 services fails
 +143..172s  mysql_plain / mysql_native_password / redis_unified requests fail
 +365s  coordinator: redis_unified ready                 <- up (down at +172s)

97891  alpine 3.23 x64
  +11s  socket missing;  +22s prestart fails
 +190..222s  sql.test.ts x4: isDockerEnabled() throws ("A functional `docker` is required in CI")

98746, all 140 Linux test jobs: daemon missing at job start on 6/24 alpine jobs (5 recovered within
~10s, before the coordinator's first probe), 0/116 debian + ubuntu jobs.