aba298d Merge branch 'perf/job-timing-and-caches' into main (!4) · ermite-runner

M docs/cache-and-artifacts.md +56 -1

@@ -1,6 +1,6 @@
1		# Cache and artifacts	1		# Cache and artifacts
2			2
3	-	The runner serves the GitHub Actions cache and artifacts v4 to jobs. Both use one channel per sandbox.	3	+	The runner serves the GitHub Actions cache, artifacts v4 and a Docker Hub mirror to jobs. All three use one channel per sandbox.
4			4
5		## Channel	5		## Channel
6			6

@@ -79,3 +79,58 @@ Works with `actions/cache`, `setup-go` and `setup-node` with `cache:`, and anyth
79		- Artifacts v3.	79		- Artifacts v3.
80		- The `artifact-url` output. It points at the fake host. The run page in ermite lists the artifacts.	80		- The `artifact-url` output. It points at the fake host. The run page in ermite lists the artifacts.
81		- Downloads from another run (`run-id` with `github-token`).	81		- Downloads from another run (`run-id` with `github-token`).
			82	+
			83	+	## Docker Hub images
			84	+
			85	+	The runner provides an anonymous, pull-only Docker Hub mirror on the same private
			86	+	channel. Each job's dockerd uses `http://127.0.0.1:9089` as a registry mirror.
			87	+	Other registries are not cached. There is no HTTPS interception, and the mirror
			88	+	needs no network policy rule. Guest credentials are never forwarded upstream. Private pulls
			89	+	fall back to Docker Hub directly, where dockerd can use the job's credentials.
			90	+
			91	+	Verified sha256 blobs and manifests live under `<state dir>/registry/`. Tags are
			92	+	revalidated by an upstream HEAD on each request, with the client's Accept headers
			93	+	reduced to the known manifest media types. If Docker Hub is unreachable, times
			94	+	out, returns a server error or rate-limits (429), a previously cached tag can be
			95	+	served stale while its manifest remains stored. Unknown tags return an error so
			96	+	dockerd can fall back.
			97	+
			98	+	A cold blob is downloaded once, whoever asks for it, and is not tied to any one
			99	+	client: every client waits for the digest check and then reads the stored file.
			100	+	A corrupt download returns 502 and leaves no file. A client that disconnects
			101	+	does not stop the download while another client waits for it; once no client
			102	+	has waited for 5 s, the download is cancelled and its temporary file removed.
			103	+	Each job may have started at most 3 cold blob downloads at once (dockerd's
			104	+	default concurrency), and at most 16 run at once across all jobs. A download
			105	+	counts against the job that started it until it ends; a job that asks for a
			106	+	layer another job is already downloading waits for it and uses none of its
			107	+	quota. A request over either limit waits up to 30 s for a slot, its connection
			108	+	kept alive, and then gets 503. A refused layer makes dockerd retry for about
			109	+	50 s before it pulls that layer from Docker Hub directly. Each sandbox may also
			110	+	have at most 8 registry requests in progress; one more gets 503 at once.
			111	+
			112	+	Downloads have no total time limit, but they fail after 30 s without progress.
			113	+	Auth, manifest and HEAD requests are limited to 10 s. Auth and manifest requests
			114	+	never follow redirects; blob requests, HEAD included, follow the CDN redirect
			115	+	without the bearer token. Stored blobs support range requests. Cold blob HEAD
			116	+	requests fetch only upstream metadata, not the layer body.
			117	+
			118	+	`ERMITE_RUNNER_REGISTRY_CACHE_MAX` defaults to `10G`. Blobs, manifests and tag
			119	+	files share one least-recently-used eviction; each is charged at least 4 KiB, so
			120	+	the number of files stays below the cap divided by 4 KiB. An entry that is being served is
			121	+	never evicted. This cap is independent of
			122	+	`ERMITE_RUNNER_CACHE_MAX`. A zero size in any unit (`0`, `0M`, `0G`) disables only
			123	+	the proxy. `ERMITE_RUNNER_CACHE=0` disables the whole channel and therefore also
			124	+	the proxy (logged at startup). Dockerd retains its mirror setting and falls back
			125	+	to Docker Hub if the mirror is unavailable. To clear the cache, stop the runner
			126	+	and remove `<state dir>/registry/`.
			127	+
			128	+	Jobs with neither cache permissions nor artifacts get the loopback channel for
			129	+	dockerd when the proxy is on, but no `ACTIONS_CACHE_URL`, `ACTIONS_RESULTS_URL`, or
			130	+	`ACTIONS_RUNTIME_TOKEN` is exposed to their steps. Registry routes need no token:
			131	+	only public content is served over a channel exclusive to that sandbox.
			132	+
			133	+	The host logs one `registry manifest` line per request with `job_id`, `repo`,
			134	+	`ref`, `hit` and `ms`. Blob misses log `registry blob` at debug level with
			135	+	`job_id`, `digest`, `bytes` and `ms`; `job_id` is the job that started the
			136	+	download.

M docs/configuration.md +2 -1

 | Variable | Default | Meaning |
 | --- | --- | --- |
-| `ERMITE_RUNNER_CACHE` | `1` | `0` turns the Actions cache off. See [cache and artifacts](cache-and-artifacts.md) |
+| `ERMITE_RUNNER_CACHE` | `1` | `0` turns the cache channel off, including the Actions cache and Docker Hub proxy. See [cache and artifacts](cache-and-artifacts.md) |
 | `ERMITE_RUNNER_CACHE_MAX` | `10G` | Size cap of the cache. Least recently used entries are evicted |
 | `ERMITE_RUNNER_ACTIONS_CACHE_MAX` | `2G` | Size cap of the action archive cache. `0` turns it off |
+| `ERMITE_RUNNER_REGISTRY_CACHE_MAX` | `10G` | Docker Hub blob and manifest cache cap, independent of `ERMITE_RUNNER_CACHE_MAX`. A zero size (`0`, `0M`, `0G`) turns only the proxy off; `ERMITE_RUNNER_CACHE=0` also disables it |
 | `ERMITE_RUNNER_ARTIFACTS` | `1` | `0` turns artifacts v4 off. Artifacts need the cache service |
 | `ERMITE_RUNNER_NODE` | `1` | `0` turns the Node.js externals off. See [externals](externals.md) |
 | `ERMITE_RUNNER_GUEST_FORGE` | `0` | `1` lets sandboxes reach the server host and port. Read the security notes first. See [sandboxes](sandboxes.md#guest-forge-access) |

M docs/development.md +26 -0


@@ -23,6 +23,7 @@ They are opt-in. They run the real stub executor. Output and exit codes come bac
23	\| `ERMITE_RUNNER_IT_E2E=1` \| End-to-end job tests in `internal/e2e` \|	23		\| `ERMITE_RUNNER_IT_E2E=1` \| End-to-end job tests in `internal/e2e` \|
24	\| `ERMITE_RUNNER_IT_NET=1` \| Packet-level firewall test \|	24		\| `ERMITE_RUNNER_IT_NET=1` \| Packet-level firewall test \|
25	\| `ERMITE_RUNNER_IT_DOCKER_API=1` \| Docker Engine calls against any daemon, including rootless \|	25		\| `ERMITE_RUNNER_IT_DOCKER_API=1` \| Docker Engine calls against any daemon, including rootless \|
		26	+	\| `ERMITE_RUNNER_IT_REGISTRY=1` \| Live Docker Hub pulls through the registry proxy with `curl` (`TestDockerHubCurl`). Needs internet access \|
26	\| `ERMITE_RUNNER_IT_NODE_DIR` \| Directory with `node-v24.21.0-linux-x64.tar.gz`, for offline hosts \|	27		\| `ERMITE_RUNNER_IT_NODE_DIR` \| Directory with `node-v24.21.0-linux-x64.tar.gz`, for offline hosts \|
27	\| `ERMITE_RUNNER_TEST_IMAGE` \| Image used by the container and end-to-end tests \|	28		\| `ERMITE_RUNNER_TEST_IMAGE` \| Image used by the container and end-to-end tests \|
28		29

@@ -63,3 +64,28 @@ ERMITE_RUNNER_IT_E2E=1 ERMITE_RUNNER_TEST_IMAGE=ermite-runner-ubuntu-26.04:dev G
63	- Docker API. Production `container` mode supports Docker Engine and sysbox. Podman's compatibility API is not a drop-in: it cannot disable DNS on the network that the runner creates.	64		- Docker API. Production `container` mode supports Docker Engine and sysbox. Podman's compatibility API is not a drop-in: it cannot disable DNS on the network that the runner creates.
64	- Jailer. The jailer needs `--chroot-base-dir` to exist. The driver creates `<state dir>/jail`. It leaves `<state dir>/jail/<exec name>` and `/sys/fs/cgroup/firecracker` behind.	65		- Jailer. The jailer needs `--chroot-base-dir` to exist. The driver creates `<state dir>/jail`. It leaves `<state dir>/jail/<exec name>` and `/sys/fs/cgroup/firecracker` behind.
65	- Host firewalls. A firewall that rejects `53` on `ertap` or `erbr` breaks guest DNS. The symptom is `dns silent` in `TestVMNetworkPolicy`.	66		- Host firewalls. A firewall that rejects `53` on `ertap` or `erbr` breaks guest DNS. The symptom is `dns silent` in `TestVMNetworkPolicy`.
		67	+
		68	+	## Measuring start-up on a small host
		69	+
		70	+	Build and register the [runner container](container.md) as usual, then constrain
		71	+	its CPU budget to reproduce a small host without changing the boot sequence:
		72	+
		73	+	```sh
		74	+	docker run -d --name runner-timing --cpus=1 \
		75	+	--device /dev/kvm --device /dev/net/tun --cap-add NET_ADMIN \
		76	+	-v runner-timing-state:/var/lib/ermite-runner \
		77	+	--env-file runner.env -e ERMITE_RUNNER_LOG_FORMAT=json ermite-runner:<tag>
		78	+	```
		79	+
		80	+	Use a registered state volume or supply the registration settings in
		81	+	`runner.env`; never put tokens in shared shell history. Podman accepts the same
		82	+	CPU limit (device access may need the CDI setup described in the container
		83	+	guide). Submit representative jobs, then extract completed-job measurements:
		84	+
		85	+	```sh
		86	+	docker logs runner-timing 2>&1 \| jq 'select(.message=="job finished")'
		87	+	```
		88	+
		89	+	Compare `sandbox_ms`, the `sb_` stages and `guest_` boot stages across jobs.
		90	+	`run_ms` includes action downloads and step execution; archive misses have their
		91	+	own counters. See [Job timing](service.md#job-timing) for the full field table.

M docs/images.md +17 -2

 | `container` | OCI reference | Default `ermite-runner-ubuntu-26.04:latest` |
 | `vm` | Directory | `vmlinux` (`Image` on arm64) and `base.ext4`. Default `<state dir>/image` |
-Both come from `images/ubuntu-26.04/Dockerfile` (Ubuntu 26.04 LTS). The runner executable and Node.js are attached by the host. They are never part of the image.
+Both come from `images/ubuntu-26.04/Dockerfile` (Ubuntu 26.04 LTS). The runner executable and action runtime Node.js are attached by the host. The image also includes system Node.js and the cached toolchains listed below.
 ## Build
 ## What the image must contain
 - User `runner`, uid and gid 1001, home `/home/runner`. Steps run as this user. Without it, steps run as root (test images only).
-- `/home/runner/work` and `/opt/hostedtoolcache`, owned by `runner`.
+- `/home/runner/work` and `/opt/hostedtoolcache`, owned by `runner`. The tool cache holds the toolchains listed in `images/ubuntu-26.04/toolcache.lock` for the image architecture.
 - `bash` and `sh`. `python3` and a `python` command for `shell: python`.
 - `dockerd` and passwordless `sudo` for `runner`, for jobs that use Docker.
+- No `registry-mirrors` in `/etc/docker/daemon.json`. The runner starts dockerd with `--registry-mirror` (its Docker Hub mirror), and dockerd refuses to start when an option is set both as a flag and in that file.
 - Common tools: git, curl, jq, build-essential, ca-certificates, tzdata, zip and unzip.
 `pwsh` is not in the image. A step that asks for it fails with `pwsh: command not found`.
+## Toolchains
+`images/ubuntu-26.04/toolcache.lock` pins Go and Node.js archives by version,
+action architecture (`x64` or `arm64`), official SHA-256 and download URL.
+To add a version, add a line for each supported architecture with the checksum
+from go.dev's download JSON or nodejs.org's `SHASUMS256.txt`, then rebuild with
+`scripts/build-image.sh tmp/image`. A checksum mismatch fails the build.
+The installer uses the `@actions/tool-cache` layout, including the sibling
+`<arch>.complete` marker. `actions/setup-go` with an exact version, including
+one read from `go.mod`, uses the cache only for an exact match. A range such as
+`1.27` selects the highest matching cached version. Versions not in the cache
+still download normally (and `check-latest: true` may check upstream).

M docs/service.md +31 -0


@@ -64,3 +64,34 @@ Do not add:
64	- `Delegate` and `UMask`: not needed.	64		- `Delegate` and `UMask`: not needed.
65		65
66	The security boundary of a job is its microVM or container, not the unit.	66		The security boundary of a job is its microVM or container, not the unit.
		67	+
		68	+	## Job timing
		69	+
		70	+	The `job finished` line carries integer milliseconds (all `*_ms` fields).
		71	+	Phases that did not run are omitted, and the driver (`sb_*`) timings appear only
		72	+	when the sandbox started. `resolve_ms` includes `archive_miss_ms`, and both are
		73	+	part of `run_ms`.
		74	+
		75	+	\| Fields \| Meaning \|
		76	+	\| --- \| --- \|
		77	+	\| `ack_ms` \| Assignment received to successful first heartbeat acknowledgement \|
		78	+	\| `sandbox_ms` \| Host `startSandbox` call \|
		79	+	\| `run_ms` \| Executor session (`drive`) \|
		80	+	\| `stop_ms` \| Sandbox `Stop` call \|
		81	+	\| `complete_ms` \| Completion call, including retries \|
		82	+	\| `total_ms` \| Assignment received to this log line, including log flushing \|
		83	+	\| `resolve_calls`, `resolve_ms` \| Number and summed duration of action resolution requests \|
		84	+	\| `archive_misses`, `archive_miss_ms`, `archive_miss_bytes` \| Archive misses and their summed fetch duration and bytes \|
		85	+	\| `sb_tap_ms`, `sb_net_ms` (VM) \| TAP creation and the rest of network setup \|
		86	+	\| `sb_vmm_ms`, `sb_files_ms`, `sb_scratch_ms` (VM) \| VMM launch/API readiness, shared files excluding scratch, scratch creation \|
		87	+	\| `sb_vsock_ms`, `sb_configure_ms`, `sb_connect_ms` (VM) \| Executor/cache sockets, VM configuration/start, executor connection wait \|
		88	+	\| `sb_socket_ms`, `sb_cache_ms`, `sb_scratch_ms` (container) \| Executor socket, cache socket, scratch setup \|
		89	+	\| `sb_net_ms`, `sb_container_ms`, `sb_connect_ms` (container) \| Network setup, container creation/start, executor connection wait \|
		90	+	\| `guest_kernel_ms`, `guest_setup_ms` (VM only) \| Kernel uptime at init entry, VM filesystem/system setup \|
		91	+	\| `guest_containerd_ms`, `guest_dockerd_ms` \| Containerd start/readiness, dockerd spawn through readiness wait \|
		92	+
		93	+	Guest boot overlaps the driver's executor connection wait: do not sum those
		94	+	fields with `sandbox_ms`. Driver `container running` and `micro-VM running`
		95	+	lines also carry unprefixed phase fields and `total_ms` for their boot sequence.
		96	+	The `action archive cache` line carries `verify_ms` for integrity verification;
		97	+	a miss also carries `fetch_ms` and `bytes`. Archive verification is never skipped.

M host_cmd.go +42 -6

 	"flag"
 	"fmt"
 	"net"
+	"net/http"
 	"os"
 	"path/filepath"
 	"strings"
 	"bnema.dev/ermite-runner/internal/cachesvc"
 	"bnema.dev/ermite-runner/internal/externals"
 	"bnema.dev/ermite-runner/internal/host"
+	"bnema.dev/ermite-runner/internal/registryproxy"
 	"bnema.dev/ermite-runner/internal/resultssvc"
 	"bnema.dev/ermite-runner/internal/sandbox"
 	"bnema.dev/ermite-runner/internal/sandbox/drivers"
 	switch strings.ToLower(strings.TrimSpace(os.Getenv(envCache))) {
 	case "", "1", "true", "yes":
 	case "0", "false", "no":
-		log.Info().Msg("the cache service is off (" + envCache + "=0)")
+		log.Info().Msg("the cache service and registry proxy are off (" + envCache + "=0)")
 		return nil, nil, nil
 	default:
 		return nil, nil, fmt.Errorf("%s: %q is not 0 or 1", envCache, os.Getenv(envCache))
 	}
-	max, err := cachesvc.ParseMax(os.Getenv(cachesvc.EnvMax))
+	// The cache API cannot be turned off by its size: 0 is refused.
+	max, err := cachesvc.ParseSize(os.Getenv(cachesvc.EnvMax), cachesvc.DefaultMax)
+	if err == nil && max == 0 {
+		err = errors.New("0 is not a size cap; " + envCache + "=0 turns the cache off")
+	}
 	if err != nil {
-		return nil, nil, err
+		return nil, nil, fmt.Errorf("%s: %w", cachesvc.EnvMax, err)
 	}
 	archives, err := setupArchives(ctx, scfg.StateDir)
 	if err != nil {
 		return nil, nil, err
 	}
-	svc, err := cachesvc.New(cachesvc.Config{Dir: filepath.Join(scfg.StateDir, "cache"), Max: max, Log: log, Archives: archives})
+	registry, err := setupRegistry(ctx, scfg.StateDir)
+	if err != nil {
+		return nil, nil, err
+	}
+	svc, err := cachesvc.New(cachesvc.Config{Dir: filepath.Join(scfg.StateDir, "cache"), Max: max, Log: log, Archives: archives, Registry: registry})
 	if err != nil {
 		return nil, nil, err
 	}
 // service, so it is only used when that is on.
 func setupArchives(ctx context.Context, stateDir string) (*actionscache.Cache, error) {
 	log := zerowrap.FromCtx(ctx)
-	max, err := actionscache.ParseMax(os.Getenv(actionscache.EnvMax))
+	max, err := cachesvc.ParseSize(os.Getenv(actionscache.EnvMax), actionscache.DefaultMax)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("%s: %w", actionscache.EnvMax, err)
 	}
 	if max == 0 {
 		log.Info().Msg("the action archive cache is off (" + actionscache.EnvMax + "=0)")
 	return c, nil
 }
+// envRegistryMax is the size cap of the Docker Hub mirror (default
+// defaultRegistryMax); 0 turns it off.
+const envRegistryMax = "ERMITE_RUNNER_REGISTRY_CACHE_MAX"
+const defaultRegistryMax = 10 << 30
+// setupRegistry opens the Docker Hub mirror. The caller only calls this when
+// the cache channel is enabled; its capacity is independent of the cache API.
+func setupRegistry(ctx context.Context, stateDir string) (http.Handler, error) {
+	log := zerowrap.FromCtx(ctx)
+	max, err := cachesvc.ParseSize(os.Getenv(envRegistryMax), defaultRegistryMax)
+	if err != nil {
+		return nil, fmt.Errorf("%s: %w", envRegistryMax, err)
+	}
+	if max == 0 {
+		log.Info().Msg("registry proxy off (" + envRegistryMax + "=0)")
+		return nil, nil
+	}
+	p, err := registryproxy.New(registryproxy.Config{Dir: filepath.Join(stateDir, "registry"), Max: max, Log: log})
+	if err != nil {
+		return nil, err
+	}
+	log.Info().Int64("max_bytes", max).Msg("registry proxy on (Docker Hub pull-through)")
+	return p, nil
+}
 // envCache=0 turns the cache service off.
 const envCache = "ERMITE_RUNNER_CACHE"

M images/ubuntu-26.04/Dockerfile +4 -0


@@ -78,6 +78,10 @@ RUN useradd --create-home --uid 1001 --shell /bin/bash runner \
78	ENV RUNNER_TOOL_CACHE=/opt/hostedtoolcache \	78		ENV RUNNER_TOOL_CACHE=/opt/hostedtoolcache \
79	LANG=C.UTF-8	79		LANG=C.UTF-8
80		80
		81	+	COPY toolcache.lock install-toolcache.sh /tmp/toolcache/
		82	+	RUN sh /tmp/toolcache/install-toolcache.sh /tmp/toolcache/toolcache.lock \
		83	+	&& rm -rf /tmp/toolcache
		84	+
81	# The runner executable is bind-mounted (container) or provided by the init	85		# The runner executable is bind-mounted (container) or provided by the init
82	# disk (vm) here; its init subcommand starts the job's own Docker daemon.	86		# disk (vm) here; its init subcommand starts the job's own Docker daemon.
83	ENTRYPOINT ["/opt/ermite/ermite-runner", "init"]	87		ENTRYPOINT ["/opt/ermite/ermite-runner", "init"]

A images/ubuntu-26.04/install-toolcache.sh +42 -0

@@ -0,0 +1,42 @@
	1	+	#!/bin/sh
	2	+	# SPDX-License-Identifier: MIT
	3	+	# Installs the toolchains of a lock file (tool version arch sha256 url per
	4	+	# line) for the image architecture into the @actions/tool-cache layout.
	5	+	set -eu
	6	+
	7	+	lock=${1:?usage: install-toolcache.sh LOCK_FILE}
	8	+	case "$(dpkg --print-architecture)" in
	9	+	amd64) arch=x64 ;;
	10	+	arm64) arch=arm64 ;;
	11	+	*) echo 'unsupported toolcache architecture' >&2; exit 1 ;;
	12	+	esac
	13	+	cache=${RUNNER_TOOL_CACHE:-/opt/hostedtoolcache}
	14	+	tmp=$(mktemp -d)
	15	+	trap 'rm -rf "$tmp"' EXIT
	16	+	trap 'exit 130' INT TERM
	17	+	installed=0
	18	+	# The last line is read even without a final newline.
	19	+	while read -r tool version entry_arch sha url \|\| [ -n "$tool" ]; do
	20	+	case "$tool" in ''\|'#'*) continue ;; esac
	21	+	case "$tool" in go\|node) ;; *) echo "unsupported tool: $tool" >&2; exit 1 ;; esac
	22	+	case "$entry_arch" in x64\|arm64) ;; *) echo "unsupported arch for $tool $version: $entry_arch" >&2; exit 1 ;; esac
	23	+	[ "$entry_arch" = "$arch" ] \|\| continue
	24	+	case "$url" in
	25	+	*.tar.gz) compression=z ;;
	26	+	*.tar.xz) compression=J ;;
	27	+	*) echo "unsupported archive: $url" >&2; exit 1 ;;
	28	+	esac
	29	+	curl -fsSL --retry 3 "$url" -o "$tmp/archive"
	30	+	printf '%s %s\n' "$sha" "$tmp/archive" \| sha256sum -c -
	31	+	dest="$cache/$tool/$version/$arch"
	32	+	mkdir -p "$dest"
	33	+	tar -x"$compression"f "$tmp/archive" -C "$dest" --strip-components=1 --no-same-owner
	34	+	touch "$dest.complete"
	35	+	rm "$tmp/archive"
	36	+	installed=$((installed + 1))
	37	+	done < "$lock"
	38	+	if [ "$installed" -eq 0 ]; then
	39	+	echo "no toolchain for $arch in $lock" >&2
	40	+	exit 1
	41	+	fi
	42	+	chown -R runner:runner "$cache"

A images/ubuntu-26.04/toolcache.lock +11 -0

@@ -0,0 +1,11 @@
	1	+	# tool version arch sha256 url
	2	+	go 1.27.3 x64 65efbc80fdc1fa2cd2631cad5b481777a68e8725f34e89f50fc6ac714e379b40 https://go.dev/dl/go1.27.3.linux-amd64.tar.gz
	3	+	go 1.27.3 arm64 a06e99309dbcbdca1a8ccd2282c3ee146e55930886e26b4f1193269587165f49 https://go.dev/dl/go1.27.3.linux-arm64.tar.gz
	4	+	go 1.27.1 x64 63d339f0da5ab53635a56f2490a7984dfe12dfcff22ad749f63edaf590168445 https://go.dev/dl/go1.27.1.linux-amd64.tar.gz
	5	+	go 1.27.1 arm64 3450b45a3f9ee8568792736a5c5e70a1f2e9b36c35a8f74958c03e51d7d92bec https://go.dev/dl/go1.27.1.linux-arm64.tar.gz
	6	+	go 1.26.10 x64 ccfe7ae822d2c2f41f4fe7c956199967a4dac22d0ee0d2b2bfdb440aab3b20c5 https://go.dev/dl/go1.26.10.linux-amd64.tar.gz
	7	+	go 1.26.10 arm64 3f4227ce7b206a513e794f1393adb473a07b46e94d18bd15d1c684bbb7319797 https://go.dev/dl/go1.26.10.linux-arm64.tar.gz
	8	+	node 24.21.0 x64 fd8e59d5a511510f6a298afb548f18c7d2b1be404d8b4a27d94fbe49f56cb2d6 https://nodejs.org/dist/v24.21.0/node-v24.21.0-linux-x64.tar.xz
	9	+	node 24.21.0 arm64 6ad1325edbdb5649c379b75a237147a666c95d4f9ae8d340fef2d1575d289ad2 https://nodejs.org/dist/v24.21.0/node-v24.21.0-linux-arm64.tar.xz
	10	+	node 22.23.3 x64 df450af89261115ef9f9e3830c3eeb2cc9213b63c720b1af623cb5dcbe2e02de https://nodejs.org/dist/v22.23.3/node-v22.23.3-linux-x64.tar.xz
	11	+	node 22.23.3 arm64 a44aeb94849a299b22df10b9e622ec2f605c2183501bc40590705131de7c740f https://nodejs.org/dist/v22.23.3/node-v22.23.3-linux-arm64.tar.xz

M internal/actionscache/cache.go +17 -43

 // download it when it does not (a miss: hit is false). Concurrent calls for the
 // same key share one download; the others report a hit once it is in place. The
 // entry is pinned for PinFor.
-func (c *Cache) Ensure(ctx context.Context, key string, fetch Fetch) (hit bool, err error) {
+func (c *Cache) Ensure(ctx context.Context, key string, fetch Fetch) (hit bool, verify time.Duration, err error) {
 	if !validKey(key) {
-		return false, ErrNotFound
+		return false, verify, ErrNotFound
 	}
 	for {
-		if c.verify(key) == nil {
+		duration, err := c.verify(key)
+		verify += duration
+		if err == nil {
 			c.touch(key, true)
-			return true, nil
+			return true, verify, nil
 		}
 		c.mu.Lock()
 		if f, ok := c.flights[key]; ok {
 			select {
 			case <-f.done:
 			case <-ctx.Done():
-				return false, ctx.Err()
+				return false, verify, ctx.Err()
 			}
 			if f.err != nil {
-				return false, f.err
+				return false, verify, f.err
 			}
 			continue
 		}
 		c.mu.Unlock()
 		close(f.done)
 		if f.err != nil {
-			return false, f.err
+			return false, verify, f.err
 		}
 		c.touch(key, true)
-		return false, nil
+		return false, verify, nil
 	}
 }
 // verify re-hashes the archive of key against its sum. Any mismatch (or a
 // missing file) drops the entry and returns ErrNotFound.
-func (c *Cache) verify(key string) error {
+func (c *Cache) verify(key string) (time.Duration, error) {
+	start := time.Now()
 	sb, err := os.ReadFile(c.sumPath(key))
 	if err != nil {
 		c.drop(key)
-		return ErrNotFound
+		return time.Since(start), ErrNotFound
 	}
 	want, sizeS, _ := strings.Cut(strings.TrimSpace(string(sb)), " ")
 	size, perr := strconv.ParseInt(sizeS, 10, 64)
 			_ = f.Close()
 		}
 		c.drop(key)
-		return ErrNotFound
+		return time.Since(start), ErrNotFound
 	}
 	defer func() { _ = f.Close() }()
 	h := sha256.New()
 	if err != nil || n != size || hex.EncodeToString(h.Sum(nil)) != want {
 		c.log.Warn().Str("key", key).Msg("action archive failed its integrity check; dropped")
 		c.drop(key)
-		return ErrNotFound
+		return time.Since(start), ErrNotFound
 	}
-	return nil
+	return time.Since(start), nil
 }
 func (c *Cache) drop(key string) {
 	if !validKey(key) {
 		return nil, ErrNotFound
 	}
-	if err := c.verify(key); err != nil {
+	if _, err := c.verify(key); err != nil {
 		return nil, err
 	}
 	f, err := os.Open(c.archivePath(key))
 	return c.total
 }
-// ParseMax reads ERMITE_RUNNER_ACTIONS_CACHE_MAX: empty is DefaultMax, 0 is off
-// (returned as 0), otherwise a number of bytes or a size with a K, M, G or T
-// suffix (optionally followed by iB or B).
-func ParseMax(v string) (int64, error) {
-	v = strings.TrimSpace(v)
-	if v == "" {
-		return DefaultMax, nil
-	}
-	s := strings.TrimRight(strings.ToUpper(v), "IB")
-	mult := int64(1)
-	if n := len(s); n > 0 {
-		switch s[n-1] {
-		case 'K':
-			mult, s = 1<<10, s[:n-1]
-		case 'M':
-			mult, s = 1<<20, s[:n-1]
-		case 'G':
-			mult, s = 1<<30, s[:n-1]
-		case 'T':
-			mult, s = 1<<40, s[:n-1]
-		}
-	}
-	n, err := strconv.ParseInt(s, 10, 64)
-	if err != nil || n < 0 || n > (1<<62)/mult {
-		return 0, fmt.Errorf("%s: %q is not a size (examples: 2G, 500M, 0)", EnvMax, v)
-	}
-	return n * mult, nil
-}
 // Dir is the directory of the cache (tests).
 func (c *Cache) Dir() string { return c.dir }

M internal/actionscache/cache_test.go +17 -30

 	k := keyOf(t, 0)
 	var fetches int
 	f := func(ctx context.Context, w io.Writer) error { fetches++; return body("archive")(ctx, w) }
-	if hit, err := c.Ensure(context.Background(), k, f); err != nil || hit {
+	if hit, _, err := c.Ensure(context.Background(), k, f); err != nil || hit {
 		t.Fatalf("first: hit=%v err=%v", hit, err)
 	}
-	if hit, err := c.Ensure(context.Background(), k, f); err != nil || !hit {
+	if hit, verify, err := c.Ensure(context.Background(), k, f); err != nil || !hit || verify <= 0 {
 		t.Fatalf("second: hit=%v err=%v", hit, err)
 	}
 	if fetches != 1 || read(t, c, k) != "archive" {
 	if err != nil {
 		t.Fatal(err)
 	}
-	if hit, _ := c2.Ensure(context.Background(), k, f); !hit || fetches != 1 {
+	if hit, _, _ := c2.Ensure(context.Background(), k, f); !hit || fetches != 1 {
 		t.Fatalf("restart: hit=%v fetches=%d", hit, fetches)
 	}
 }
 	c, _ := newCache(t, 1<<20)
 	k := keyOf(t, 0)
 	boom := errors.New("429")
-	_, err := c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error { _, _ = io.WriteString(w, "part"); return boom })
+	_, _, err := c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error { _, _ = io.WriteString(w, "part"); return boom })
 	if !errors.Is(err, boom) {
 		t.Fatal(err)
 	}
 		wg.Add(1)
 		go func() {
 			defer wg.Done()
-			hit, err := c.Ensure(context.Background(), k, f)
+			hit, _, err := c.Ensure(context.Background(), k, f)
 			if err != nil {
 				t.Error(err)
 			}
 func TestCorruptEntryIsDroppedAndRefetched(t *testing.T) {
 	c, _ := newCache(t, 1<<20)
 	k := keyOf(t, 0)
-	if _, err := c.Ensure(context.Background(), k, body("good bytes")); err != nil {
+	if _, _, err := c.Ensure(context.Background(), k, body("good bytes")); err != nil {
 		t.Fatal(err)
 	}
 	// Same size, other content: only the hash can tell.
 	if c.Size() != 0 {
 		t.Errorf("size %d after the drop", c.Size())
 	}
-	hit, err := c.Ensure(context.Background(), k, body("good bytes"))
+	hit, _, err := c.Ensure(context.Background(), k, body("good bytes"))
 	if err != nil || hit {
 		t.Fatalf("hit=%v err=%v", hit, err)
 	}
 	step := func() { *now = now.Add(time.Hour + PinFor) } // past every pin
 	a, b, d := keyOf(t, 0), keyOf(t, 1), keyOf(t, 2)
 	for _, k := range []string{a, b} {
-		if _, err := c.Ensure(ctx, k, body(strings.Repeat("x", 10))); err != nil {
+		if _, _, err := c.Ensure(ctx, k, body(strings.Repeat("x", 10))); err != nil {
 			t.Fatal(err)
 		}
 		step()
 	}
 	// Use a again: b is now the least recently used.
-	if hit, _ := c.Ensure(ctx, a, body("unused")); !hit {
+	if hit, _, _ := c.Ensure(ctx, a, body("unused")); !hit {
 		t.Fatal("a should hit")
 	}
 	step()
-	if _, err := c.Ensure(ctx, d, body(strings.Repeat("y", 10))); err != nil {
+	if _, _, err := c.Ensure(ctx, d, body(strings.Repeat("y", 10))); err != nil {
 		t.Fatal(err)
 	}
 	if _, err := c.Open(b); !errors.Is(err, ErrNotFound) {
 	c, _ := newCache(t, 15)
 	ctx := context.Background()
 	a, b := keyOf(t, 0), keyOf(t, 1)
-	if _, err := c.Ensure(ctx, a, body(strings.Repeat("x", 10))); err != nil {
+	if _, _, err := c.Ensure(ctx, a, body(strings.Repeat("x", 10))); err != nil {
 		t.Fatal(err)
 	}
-	if _, err := c.Ensure(ctx, b, body(strings.Repeat("y", 10))); !errors.Is(err, ErrTooLarge) {
+	if _, _, err := c.Ensure(ctx, b, body(strings.Repeat("y", 10))); !errors.Is(err, ErrTooLarge) {
 		t.Fatalf("got %v", err)
 	}
 	if _, err := c.Open(a); err != nil {
 		go func() {
 			defer wg.Done()
 			k := keyOf(t, i)
-			_, _ = c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error {
+			_, _, _ = c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error {
 				for range 6 { // 6 x 10 bytes, in pieces
 					if _, err := w.Write([]byte(strings.Repeat("z", 10))); err != nil {
 						return err
 func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
 	c, _ := newCache(t, 50)
 	seen := int64(-1)
-	_, err := c.Ensure(context.Background(), keyOf(t, 0), func(_ context.Context, w io.Writer) error {
+	_, _, err := c.Ensure(context.Background(), keyOf(t, 0), func(_ context.Context, w io.Writer) error {
 		_, _ = io.WriteString(w, strings.Repeat("a", 30))
 		c.mu.Lock()
 		seen = c.pending
 		t.Fatalf("err=%v pending during=%d", err, seen)
 	}
 	// Refused midway for size: the part already written is released too.
-	_, err = c.Ensure(context.Background(), keyOf(t, 1), body(strings.Repeat("b", 60)))
+	_, _, err = c.Ensure(context.Background(), keyOf(t, 1), body(strings.Repeat("b", 60)))
 	if !errors.Is(err, ErrTooLarge) {
 		t.Fatalf("got %v", err)
 	}
 		t.Fatalf("pending=%d size=%d disk=%d", c.pending, c.Size(), diskUse(t, c))
 	}
 	// The size is what was written, whatever the server announced.
-	if _, err := c.Ensure(context.Background(), keyOf(t, 2), body(strings.Repeat("c", 50))); err != nil {
+	if _, _, err := c.Ensure(context.Background(), keyOf(t, 2), body(strings.Repeat("c", 50))); err != nil {
 		t.Fatal(err)
 	}
 	if c.Size() != 50 {
 func TestTooLarge(t *testing.T) {
 	c, _ := newCache(t, 10)
-	_, err := c.Ensure(context.Background(), keyOf(t, 0), body(strings.Repeat("x", 11)))
+	_, _, err := c.Ensure(context.Background(), keyOf(t, 0), body(strings.Repeat("x", 11)))
 	if !errors.Is(err, ErrTooLarge) {
 		t.Fatalf("got %v", err)
 	}
 		t.Error("shape")
 	}
 }
-func TestParseMax(t *testing.T) {
-	for in, want := range map[string]int64{"": DefaultMax, "0": 0, "500M": 500 << 20, "2G": 2 << 30, "2GiB": 2 << 30, "1024": 1024} {
-		if got, err := ParseMax(in); err != nil || got != want {
-			t.Errorf("%q: %d %v", in, got, err)
-		}
-	}
-	for _, in := range []string{"-1", "x", "G"} {
-		if _, err := ParseMax(in); err == nil {
-			t.Errorf("%q accepted", in)
-		}
-	}
-}

M internal/cachesvc/archives_test.go +1 -1


@@ -24,7 +24,7 @@ func archiveRig(t testing.T) (rig, *actionscache.Cache, string) {
24		}	24		}
25		r := newRigWith(t, Config{Max: 1 << 20, MinCharge: 1, Archives: ac})	25		r := newRigWith(t, Config{Max: 1 << 20, MinCharge: 1, Archives: ac})
26		key, _ := actionscache.Key("https://github.com", "o/r", strings.Repeat("a", 40))	26		key, _ := actionscache.Key("https://github.com", "o/r", strings.Repeat("a", 40))
27	-	if _, err := ac.Ensure(context.Background(), key, func(_ context.Context, w io.Writer) error {	27	+	if _, _, err := ac.Ensure(context.Background(), key, func(_ context.Context, w io.Writer) error {
28		_, err := io.WriteString(w, "tarball")	28		_, err := io.WriteString(w, "tarball")
29		return err	29		return err
30		}); err != nil {	30		}); err != nil {

M internal/cachesvc/handler.go +51 -3


@@ -13,6 +13,8 @@ import (
13		"strconv"	13		"strconv"
14		"strings"	14		"strings"
15		"time"	15		"time"
			16	+
			17	+	"bnema.dev/ermite-runner/internal/registryproxy"
16		)	18		)
17			19
18		// APIPath is the prefix of the cache API: the toolkit appends "_apis/	20		// APIPath is the prefix of the cache API: the toolkit appends "_apis/

@@ -45,6 +47,11 @@ func (s *Service) Handler() http.Handler { return s.handler("") }
45		// any other sandbox's channel.	47		// any other sandbox's channel.
46		func (s *Service) handler(job string) http.Handler {	48		func (s *Service) handler(job string) http.Handler {
47		mux := http.NewServeMux()	49		mux := http.NewServeMux()
			50	+	if s.registry != nil {
			51	+	registry := s.serveRegistry(job, make(chan struct{}, s.registryPerChannel), registryproxy.NewQuota(RegistryDownloadsPerChannel))
			52	+	mux.HandleFunc("GET "+RegistryPath, registry)
			53	+	mux.HandleFunc("HEAD "+RegistryPath, registry)
			54	+	}
48		// The routes are those of the toolkit's v1 client (cacheHttpClient.ts):	55		// The routes are those of the toolkit's v1 client (cacheHttpClient.ts):
49		// GET cache?keys=k1,k2&version=v :89 lookup	56		// GET cache?keys=k1,k2&version=v :89 lookup
50		// GET caches?key=k :132 diagnostics (core.isDebug())	57		// GET caches?key=k :132 diagnostics (core.isDebug())

@@ -73,8 +80,8 @@ func (s *Service) handler(job string) http.Handler {
73		})	80		})
74		}	81		}
75			82
76	-	// channelHandler is the handler of a sandbox's channel: the cache API and the	83	+	// channelHandler is the handler of a sandbox's channel: the cache API, the
77	-	// action archives, and when results is not nil everything else goes to it (the results service of the	84	+	// action archives and the registry, and when results is not nil everything else goes to it (the results service of the
78		// job: Twirp and blob paths). The results service gets the same progress	85		// job: Twirp and blob paths). The results service gets the same progress
79		// deadlines as the cache: its bodies and replies must keep moving.	86		// deadlines as the cache: its bodies and replies must keep moving.
80		func (s *Service) channelHandler(job string, results http.Handler) http.Handler {	87		func (s *Service) channelHandler(job string, results http.Handler) http.Handler {

@@ -83,7 +90,7 @@ func (s *Service) channelHandler(job string, results http.Handler) http.Handler
83		return cache	90		return cache
84		}	91		}
85		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {	92		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
86	-	if strings.HasPrefix(r.URL.Path, APIPath) \|\| strings.HasPrefix(r.URL.Path, ArchivePath) {	93	+	if strings.HasPrefix(r.URL.Path, APIPath) \|\| strings.HasPrefix(r.URL.Path, ArchivePath) \|\| strings.HasPrefix(r.URL.Path, RegistryPath) {
87		cache.ServeHTTP(w, r)	94		cache.ServeHTTP(w, r)
88		return	95		return
89		}	96		}

@@ -388,6 +395,47 @@ func (p *progressWriter) Write(b []byte) (int, error) {
388		// Unwrap lets http.ResponseController reach the real writer.	395		// Unwrap lets http.ResponseController reach the real writer.
389		func (p *progressWriter) Unwrap() http.ResponseWriter { return p.ResponseWriter }	396		func (p *progressWriter) Unwrap() http.ResponseWriter { return p.ResponseWriter }
390			397
			398	+	var _ registryproxy.KeepAliver = (*progressWriter)(nil)
			399	+
			400	+	// KeepAlive moves the deadlines without writing. The registry proxy calls it
			401	+	// while the client waits for a shared upstream download that is progressing,
			402	+	// before the first byte of the reply. The read deadline moves too: once it
			403	+	// passes, net/http cancels the request's context and the wait would end.
			404	+	func (p *progressWriter) KeepAlive() {
			405	+	d := deadline(p.idle, p.remaining)
			406	+	_ = p.rc.SetReadDeadline(d)
			407	+	_ = p.rc.SetWriteDeadline(d)
			408	+	}
			409	+
			410	+	// serveRegistry serves the Docker Hub mirror with the same sliding progress
			411	+	// deadline as the other downloads: a layer of GiB keeps going as long as it
			412	+	// moves, and a client that stops reading is cut after one progress period.
			413	+	// slots caps the requests of this channel in progress at once; one over the
			414	+	// cap gets 503 at once, which dockerd retries or answers by pulling from
			415	+	// Docker Hub, so the channel's connections stay free for the cache. quota is
			416	+	// the channel's share of the proxy's cold downloads. job, when not empty, is
			417	+	// the channel's job, which the registry logs.
			418	+	func (s Service) serveRegistry(job string, slots chan struct{}, quota registryproxy.Quota) http.HandlerFunc {
			419	+	return func(w http.ResponseWriter, r *http.Request) {
			420	+	select {
			421	+	case slots <- struct{}{}:
			422	+	defer func() { <-slots }()
			423	+	default:
			424	+	w.Header().Set("Retry-After", "1")
			425	+	reply(w, http.StatusServiceUnavailable, "registry busy")
			426	+	return
			427	+	}
			428	+	rc := http.NewResponseController(w)
			429	+	defer func() { _ = rc.SetWriteDeadline(deadline(s.progress, nil)) }()
			430	+	ctx := registryproxy.WithQuota(r.Context(), quota)
			431	+	if job != "" {
			432	+	ctx = registryproxy.WithJob(ctx, job)
			433	+	}
			434	+	r = r.WithContext(ctx)
			435	+	s.registry.ServeHTTP(&progressWriter{ResponseWriter: w, rc: rc, idle: s.progress}, r)
			436	+	}
			437	+	}
			438	+
391		func (s Service) commit(w http.ResponseWriter, r http.Request, c Claims) {	439		func (s Service) commit(w http.ResponseWriter, r http.Request, c Claims) {
392		id, ok := parseID(r)	440		id, ok := parseID(r)
393		var req struct {	441		var req struct {

A internal/cachesvc/registry_deadline_test.go +127 -0

@@ -0,0 +1,127 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package cachesvc
	4	+
	5	+	import (
	6	+	"bufio"
	7	+	"fmt"
	8	+	"io"
	9	+	"net"
	10	+	"net/http"
	11	+	"strings"
	12	+	"testing"
	13	+	"time"
	14	+
	15	+	"bnema.dev/ermite-runner/internal/registryproxy"
	16	+	)
	17	+
	18	+	const registryProgress = 300 * time.Millisecond
	19	+
	20	+	// registryRig serves a fake registry behind the service's real HTTP server, so
	21	+	// that the connection deadlines apply.
	22	+	func registryRig(t testing.T, h http.HandlerFunc) rig {
	23	+	t.Helper()
	24	+	return newRigWith(t, Config{Max: 1 << 20, MinCharge: 1, ProgressTimeout: registryProgress, Registry: h})
	25	+	}
	26	+
	27	+	// A registry download that keeps moving may last longer than the progress
	28	+	// period set when the request started.
	29	+	func TestRegistryProgressingTransferSucceeds(t *testing.T) {
	30	+	const chunks = 14
	31	+	r := registryRig(t, func(w http.ResponseWriter, _ *http.Request) {
	32	+	w.Header().Set("Content-Length", fmt.Sprint(chunks*1024))
	33	+	for range chunks {
	34	+	if _, err := w.Write([]byte(strings.Repeat("x", 1024))); err != nil {
	35	+	return
	36	+	}
	37	+	_ = http.NewResponseController(w).Flush()
	38	+	time.Sleep(registryProgress / 6)
	39	+	}
	40	+	})
	41	+	start := time.Now()
	42	+	resp, err := http.Get(r.srv.URL + RegistryPath + "library/alpine/blobs/x")
	43	+	if err != nil {
	44	+	t.Fatal(err)
	45	+	}
	46	+	defer func() { _ = resp.Body.Close() }()
	47	+	b, err := io.ReadAll(resp.Body)
	48	+	if err != nil \|\| len(b) != chunks*1024 {
	49	+	t.Fatalf("read %d bytes: %v", len(b), err)
	50	+	}
	51	+	if d := time.Since(start); d < 2*registryProgress {
	52	+	t.Fatalf("transfer took %v, not longer than the progress period", d)
	53	+	}
	54	+	}
	55	+
	56	+	// The proxy keeps a client alive while it waits for a shared upstream
	57	+	// download, before the first byte; the read deadline moves too, so the request
	58	+	// context stays alive.
	59	+	func TestRegistryKeepAliveWhileWaiting(t *testing.T) {
	60	+	r := registryRig(t, func(w http.ResponseWriter, req *http.Request) {
	61	+	k, ok := w.(registryproxy.KeepAliver)
	62	+	if !ok {
	63	+	t.Error("the registry writer is no KeepAliver")
	64	+	return
	65	+	}
	66	+	for range 12 { // two progress periods
	67	+	time.Sleep(registryProgress / 6)
	68	+	k.KeepAlive()
	69	+	if req.Context().Err() != nil {
	70	+	t.Error("request context ended while kept alive")
	71	+	return
	72	+	}
	73	+	}
	74	+	_, _ = io.WriteString(w, "verified")
	75	+	})
	76	+	resp, err := http.Get(r.srv.URL + RegistryPath + "library/alpine/blobs/x")
	77	+	if err != nil {
	78	+	t.Fatal(err)
	79	+	}
	80	+	defer func() { _ = resp.Body.Close() }()
	81	+	if b, err := io.ReadAll(resp.Body); err != nil \|\| string(b) != "verified" {
	82	+	t.Fatalf("%q %v", b, err)
	83	+	}
	84	+	}
	85	+
	86	+	// A client that stops reading is cut after one progress period.
	87	+	func TestRegistryStalledReaderIsCut(t *testing.T) {
	88	+	result := make(chan error, 1)
	89	+	r := registryRig(t, func(w http.ResponseWriter, _ *http.Request) {
	90	+	chunk := []byte(strings.Repeat("x", 64<<10))
	91	+	deadline := time.Now().Add(5 * time.Second)
	92	+	for time.Now().Before(deadline) {
	93	+	if _, err := w.Write(chunk); err != nil {
	94	+	result <- err
	95	+	return
	96	+	}
	97	+	}
	98	+	result <- nil
	99	+	})
	100	+	conn, err := net.Dial("tcp", strings.TrimPrefix(r.srv.URL, "http://"))
	101	+	if err != nil {
	102	+	t.Fatal(err)
	103	+	}
	104	+	defer func() { _ = conn.Close() }()
	105	+	if tc, ok := conn.(*net.TCPConn); ok {
	106	+	_ = tc.SetReadBuffer(4096)
	107	+	}
	108	+	if _, err := fmt.Fprint(conn, "GET "+RegistryPath+"library/alpine/blobs/x HTTP/1.1\r\nHost: x\r\n\r\n"); err != nil {
	109	+	t.Fatal(err)
	110	+	}
	111	+	resp, err := http.ReadResponse(bufio.NewReader(conn), nil)
	112	+	if err != nil {
	113	+	t.Fatal(err)
	114	+	}
	115	+	if resp.StatusCode != http.StatusOK {
	116	+	t.Fatal(resp.StatusCode)
	117	+	}
	118	+	// Read nothing more.
	119	+	select {
	120	+	case err := <-result:
	121	+	if err == nil {
	122	+	t.Fatal("a stalled reader was not cut")
	123	+	}
	124	+	case <-time.After(10 * time.Second):
	125	+	t.Fatal("handler still blocked")
	126	+	}
	127	+	}

A internal/cachesvc/registry_limits_test.go +195 -0

@@ -0,0 +1,195 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package cachesvc
	4	+
	5	+	import (
	6	+	"bytes"
	7	+	"context"
	8	+	"crypto/sha256"
	9	+	"fmt"
	10	+	"io"
	11	+	"net/http"
	12	+	"net/http/httptest"
	13	+	"strings"
	14	+	"sync"
	15	+	"sync/atomic"
	16	+	"testing"
	17	+	"time"
	18	+
	19	+	"github.com/bnema/zerowrap"
	20	+
	21	+	"bnema.dev/ermite-runner/internal/registryproxy"
	22	+	)
	23	+
	24	+	// The registry requests of one channel in progress at once are capped: one
	25	+	// over the cap gets 503 at once, the cache API of that channel still answers,
	26	+	// and another channel has its own slots.
	27	+	func TestRegistryPerChannelCap(t *testing.T) {
	28	+	const limit = 2
	29	+	var inside atomic.Int32
	30	+	release := make(chan struct{})
	31	+	svc, err := New(Config{Dir: t.TempDir(), RegistryPerChannel: limit, Registry: http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
	32	+	inside.Add(1)
	33	+	<-release
	34	+	_, _ = io.WriteString(w, "ok")
	35	+	})})
	36	+	if err != nil {
	37	+	t.Fatal(err)
	38	+	}
	39	+	t.Cleanup(func() { _ = svc.CloseAll() })
	40	+	var once sync.Once
	41	+	unblock := func() { once.Do(func() { close(release) }) }
	42	+	t.Cleanup(unblock)
	43	+	a, b := channel(t, svc, "sb-a", "job-a"), channel(t, svc, "sb-b", "job-b")
	44	+	get := func(c *http.Client) int {
	45	+	resp, err := c.Get("http://cache" + RegistryPath + "library/alpine/blobs/x")
	46	+	if err != nil {
	47	+	t.Error(err)
	48	+	return 0
	49	+	}
	50	+	_, _ = io.Copy(io.Discard, resp.Body)
	51	+	_ = resp.Body.Close()
	52	+	return resp.StatusCode
	53	+	}
	54	+	var wg sync.WaitGroup
	55	+	codes := make(chan int, limit)
	56	+	for range limit {
	57	+	wg.Go(func() { codes <- get(a) })
	58	+	}
	59	+	waitUntil(t, func() bool { return inside.Load() == limit })
	60	+	if code := get(a); code != http.StatusServiceUnavailable {
	61	+	t.Fatalf("over the cap: %d", code)
	62	+	}
	63	+	if code := lookupStatus(t, a, ""); code != http.StatusForbidden {
	64	+	t.Fatalf("cache API behind the registry cap: %d", code)
	65	+	}
	66	+	other := make(chan int, 1)
	67	+	go func() { other <- get(b) }()
	68	+	waitUntil(t, func() bool { return inside.Load() == limit+1 })
	69	+	unblock()
	70	+	wg.Wait()
	71	+	close(codes)
	72	+	for code := range codes {
	73	+	if code != http.StatusOK {
	74	+	t.Fatalf("within the cap: %d", code)
	75	+	}
	76	+	}
	77	+	if code := <-other; code != http.StatusOK {
	78	+	t.Fatalf("other channel: %d", code)
	79	+	}
	80	+	if code := get(a); code != http.StatusOK {
	81	+	t.Fatalf("slots not released: %d", code)
	82	+	}
	83	+	}
	84	+
	85	+	// stallingHub fakes Docker Hub for a real registryproxy: a manifest, and blobs
	86	+	// whose download stalls until the test ends. It counts the blob downloads
	87	+	// started.
	88	+	func stallingHub(t testing.T) (httptest.Server, *atomic.Int32, string) {
	89	+	t.Helper()
	90	+	const manifest = `{"schemaVersion":2}`
	91	+	digest := fmt.Sprintf("sha256:%x", sha256.Sum256([]byte(manifest)))
	92	+	var started atomic.Int32
	93	+	done := make(chan struct{})
	94	+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	95	+	switch {
	96	+	case r.URL.Path == "/token":
	97	+	_, _ = io.WriteString(w, `{"token":"public"}`)
	98	+	case strings.Contains(r.URL.Path, "/manifests/"):
	99	+	w.Header().Set("Content-Type", "application/vnd.oci.image.index.v1+json")
	100	+	w.Header().Set("Docker-Content-Digest", digest)
	101	+	_, _ = io.WriteString(w, manifest)
	102	+	default:
	103	+	started.Add(1)
	104	+	w.Header().Set("Content-Length", "1000000")
	105	+	_, _ = io.WriteString(w, "partial")
	106	+	w.(http.Flusher).Flush()
	107	+	select {
	108	+	case <-r.Context().Done():
	109	+	case <-done:
	110	+	}
	111	+	}
	112	+	}))
	113	+	t.Cleanup(srv.Close)
	114	+	t.Cleanup(func() { close(done) }) // before srv.Close, which waits for the handlers
	115	+	return srv, &started, digest
	116	+	}
	117	+
	118	+	// Each channel has its own quota of cold downloads: a channel that has
	119	+	// started RegistryDownloadsPerChannel of them waits for its own to end, while
	120	+	// another channel starts its download at once.
	121	+	func TestRegistryQuotaPerChannel(t *testing.T) {
	122	+	hub, started, _ := stallingHub(t)
	123	+	proxy, err := registryproxy.New(registryproxy.Config{Dir: t.TempDir(), Max: 1 << 30, Upstream: hub.URL, AuthURL: hub.URL + "/token",
	124	+	SlotWait: time.Hour, AbandonGrace: 10 * time.Millisecond})
	125	+	if err != nil {
	126	+	t.Fatal(err)
	127	+	}
	128	+	svc, err := New(Config{Dir: t.TempDir(), Registry: proxy})
	129	+	if err != nil {
	130	+	t.Fatal(err)
	131	+	}
	132	+	t.Cleanup(func() { _ = svc.CloseAll() })
	133	+	ctx, cancel := context.WithCancel(context.Background())
	134	+	defer cancel()
	135	+	var wg sync.WaitGroup
	136	+	defer wg.Wait()
	137	+	defer cancel()
	138	+	pull := func(c *http.Client, i int) {
	139	+	req, _ := http.NewRequestWithContext(ctx, http.MethodGet, fmt.Sprintf("http://cache%slibrary/alpine/blobs/sha256:%x", RegistryPath, sha256.Sum256(fmt.Appendf(nil, "blob-%d", i))), nil)
	140	+	wg.Go(func() {
	141	+	if resp, err := c.Do(req); err == nil {
	142	+	_ = resp.Body.Close()
	143	+	}
	144	+	})
	145	+	}
	146	+	a, b := channel(t, svc, "sb-a", "job-a"), channel(t, svc, "sb-b", "job-b")
	147	+	for i := range RegistryDownloadsPerChannel + 1 {
	148	+	pull(a, i)
	149	+	}
	150	+	waitUntil(t, func() bool { return started.Load() == RegistryDownloadsPerChannel })
	151	+	time.Sleep(50 * time.Millisecond) // the one over A's quota would have started by now
	152	+	if n := started.Load(); n != RegistryDownloadsPerChannel {
	153	+	t.Fatalf("channel A started %d downloads, its quota is %d", n, RegistryDownloadsPerChannel)
	154	+	}
	155	+	pull(b, 100)
	156	+	waitUntil(t, func() bool { return started.Load() == RegistryDownloadsPerChannel+1 })
	157	+	}
	158	+
	159	+	// The registry lines of a channel carry its job.
	160	+	func TestRegistryLogsJob(t *testing.T) {
	161	+	hub, _, digest := stallingHub(t)
	162	+	var logs bytes.Buffer
	163	+	var mu sync.Mutex
	164	+	proxy, err := registryproxy.New(registryproxy.Config{Dir: t.TempDir(), Max: 1 << 20, Upstream: hub.URL, AuthURL: hub.URL + "/token",
	165	+	Log: zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: writerFunc(func(p []byte) (int, error) {
	166	+	mu.Lock()
	167	+	defer mu.Unlock()
	168	+	return logs.Write(p)
	169	+	})})})
	170	+	if err != nil {
	171	+	t.Fatal(err)
	172	+	}
	173	+	svc, err := New(Config{Dir: t.TempDir(), Registry: proxy})
	174	+	if err != nil {
	175	+	t.Fatal(err)
	176	+	}
	177	+	t.Cleanup(func() { _ = svc.CloseAll() })
	178	+	resp, err := channel(t, svc, "sb-a", "job-a").Get("http://cache" + RegistryPath + "library/alpine/manifests/" + digest)
	179	+	if err != nil {
	180	+	t.Fatal(err)
	181	+	}
	182	+	_ = resp.Body.Close()
	183	+	if resp.StatusCode != http.StatusOK {
	184	+	t.Fatal(resp.StatusCode)
	185	+	}
	186	+	mu.Lock()
	187	+	defer mu.Unlock()
	188	+	if !strings.Contains(logs.String(), `"job_id":"job-a"`) \|\| !strings.Contains(logs.String(), `"message":"registry manifest"`) {
	189	+	t.Fatalf("logs: %s", logs.String())
	190	+	}
	191	+	}
	192	+
	193	+	type writerFunc func(p []byte) (int, error)
	194	+
	195	+	func (f writerFunc) Write(p []byte) (int, error) { return f(p) }

A internal/cachesvc/registry_test.go +37 -0

@@ -0,0 +1,37 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package cachesvc
	4	+
	5	+	import (
	6	+	"io"
	7	+	"net/http"
	8	+	"net/http/httptest"
	9	+	"testing"
	10	+	)
	11	+
	12	+	// The registry is served under RegistryPath on the cache handler and the
	13	+	// channel, never by the results service; without one, those paths are 404.
	14	+	func TestRegistryRoute(t *testing.T) {
	15	+	for _, on := range []bool{false, true} {
	16	+	cfg := Config{}
	17	+	if on {
	18	+	cfg.Registry = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { _, _ = io.WriteString(w, "registry") })
	19	+	}
	20	+	r := newRigWith(t, cfg)
	21	+	results := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	22	+	t.Error("registry fell through to results")
	23	+	w.WriteHeader(http.StatusInternalServerError)
	24	+	})
	25	+	for _, h := range []http.Handler{r.svc.Handler(), r.svc.channelHandler("job", results)} {
	26	+	w := httptest.NewRecorder()
	27	+	h.ServeHTTP(w, httptest.NewRequest(http.MethodGet, RegistryPath, nil))
	28	+	if on {
	29	+	if w.Code != http.StatusOK \|\| w.Body.String() != "registry" {
	30	+	t.Fatalf("%d %s", w.Code, w.Body)
	31	+	}
	32	+	} else if w.Code != http.StatusNotFound {
	33	+	t.Fatal(w.Code)
	34	+	}
	35	+	}
	36	+	}
	37	+	}

M internal/cachesvc/service.go +39 -13

 	// blocks at once by default, besides downloads and the cache.
 	DefaultConnsPerListener = 32
 	DefaultConns            = 128
+	// DefaultRegistryPerChannel bounds the registry requests of one channel in
+	// progress at once, so that one sandbox's pulls leave room for its cache and
+	// artifact traffic. dockerd pulls 3 layers at once by default.
+	DefaultRegistryPerChannel = 8
+	// RegistryDownloadsPerChannel bounds the cold Docker Hub downloads one
+	// channel may have started at once (dockerd's default
+	// max-concurrent-downloads), so that one sandbox cannot take every slot of
+	// the registry proxy.
+	RegistryDownloadsPerChannel = 3
+	// RegistryPath is the prefix of the Docker registry API on the channel.
+	RegistryPath = "/v2/"
 )
 // Config configures a Service.
 	// Archives, when not nil, is the host's cache of action archives, served on
 	// the channels (see ArchiveURL).
 	Archives *actionscache.Cache
+	// Registry is an anonymous pull-only registry on the private channel.
+	Registry http.Handler
 	// The limits below take the Default… values (or those of the store) when
 	// zero; tests set them.
 	ProgressTimeout              time.Duration
 	ConnsPerListener, Conns      int
+	RegistryPerChannel           int
 	MinCharge                    int64
 	MaxPending, MaxPendingPerJob int
 	// hookChunk, when set, is called by an upload once its range is admitted and
 	wg       sync.WaitGroup
 	closed   bool
-	archives    *actionscache.Cache
+	archives *actionscache.Cache
-	hookChunk   func(id int64)
+	registry http.Handler
-	progress    time.Duration
+	// registryPerChannel caps the registry requests in progress per handler.
-	perListener int
+	registryPerChannel int
-	connsGlobal chan struct{}
+	hookChunk          func(id int64)
+	progress           time.Duration
+	perListener        int
+	connsGlobal        chan struct{}
 }
 type listener struct {
 	if cfg.Conns <= 0 {
 		cfg.Conns = DefaultConns
 	}
+	if cfg.RegistryPerChannel <= 0 {
+		cfg.RegistryPerChannel = DefaultRegistryPerChannel
+	}
 	s := &Service{store: st, sign: sg, now: cfg.Now, log: cfg.Log, channels: map[string]*listener{}, stop: make(chan struct{}),
-		archives: cfg.Archives, hookChunk: cfg.hookChunk, progress: cfg.ProgressTimeout, perListener: cfg.ConnsPerListener, connsGlobal: make(chan struct{}, cfg.Conns)}
+		archives: cfg.Archives, registry: cfg.Registry, hookChunk: cfg.hookChunk, progress: cfg.ProgressTimeout, perListener: cfg.ConnsPerListener, connsGlobal: make(chan struct{}, cfg.Conns), registryPerChannel: cfg.RegistryPerChannel}
 	s.wg.Add(1)
 	go s.housekeeping()
 	return s, nil
 	}
 }
+// RegistryEnabled reports whether the channel serves an anonymous registry.
+func (s *Service) RegistryEnabled() bool { return s.registry != nil }
 // Token returns the ACTIONS_RUNTIME_TOKEN of a job. It is valid for ttl, which
 // should be the job timeout plus a margin. sc is the job's cache scope (the
 // zero Scope for a job without a cache: the cache then refuses the token);
 	return s.store.flush()
 }
-// ParseMax reads ERMITE_RUNNER_CACHE_MAX: a number of bytes or a size with a K,
+// ParseSize reads a size: a number of bytes or a number with a K, M, G or T
-// M, G or T suffix (optionally followed by iB or B). Empty means DefaultMax.
+// suffix (powers of 1024), optionally followed by iB or B, such as 10G, 500M
-func ParseMax(v string) (int64, error) {
+// or 2GiB. Surrounding spaces are ignored; empty means def. Zero in any unit
+// (0, 0G, 0GiB) is 0. The error names no variable: the caller prefixes it.
+func ParseSize(v string, def int64) (int64, error) {
+	v = strings.TrimSpace(v)
 	if v == "" {
-		return DefaultMax, nil
+		return def, nil
 	}
 	s := []byte(v)
-	for len(s) > 0 && (s[len(s)-1] == 'B' || s[len(s)-1] == 'b' || s[len(s)-1] == 'i') {
+	for len(s) > 0 && strings.IndexByte("bBiI", s[len(s)-1]) >= 0 {
 		s = s[:len(s)-1]
 	}
 	mult := int64(1)
 		}
 	}
 	n, err := strconv.ParseInt(string(s), 10, 64)
-	if err != nil || n <= 0 || n > (1<<62)/mult {
+	if err != nil || n < 0 || n > (1<<62)/mult {
-		return 0, fmt.Errorf("%s: %q is not a size (examples: 10G, 500M)", EnvMax, v)
+		return 0, fmt.Errorf("%q is not a size (examples: 10G, 500M)", v)
 	}
 	return n * mult, nil
 }

M internal/cachesvc/service_test.go +10 -5

 	}
 }
-func TestParseMax(t *testing.T) {
+func TestParseSize(t *testing.T) {
-	for in, want := range map[string]int64{"": DefaultMax, "10G": 10 << 30, "500m": 500 << 20, "1GiB": 1 << 30, "2048": 2048, "3TB": 3 << 40} {
+	const def = 7
-		if got, err := ParseMax(in); err != nil || got != want {
+	for in, want := range map[string]int64{"": def, "  ": def, "10G": 10 << 30, "500m": 500 << 20, "1GiB": 1 << 30, "2048": 2048, "3TB": 3 << 40, " 2G ": 2 << 30,
+		"0": 0, "00": 0, "0G": 0, "0GiB": 0, "2GIB": 2 << 30} {
+		if got, err := ParseSize(in, def); err != nil || got != want {
 			t.Errorf("%q: %d %v", in, got, err)
 		}
 	}
-	for _, in := range []string{"0", "-1", "G", "ten", "1.5G", "99999999999T"} {
+	for _, in := range []string{"-1", "G", "ten", "1.5G", "99999999999T"} {
-		if _, err := ParseMax(in); err == nil {
+		_, err := ParseSize(in, def)
+		if err == nil {
 			t.Errorf("%q accepted", in)
+		} else if strings.Contains(err.Error(), "ERMITE_") {
+			t.Errorf("%q: the error names a variable: %v", in, err)
 		}
 	}
 }

A internal/e2e/registry_test.go +114 -0

@@ -0,0 +1,114 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package e2e
	4	+
	5	+	import (
	6	+	"bytes"
	7	+	"encoding/json"
	8	+	"net/http"
	9	+	"strings"
	10	+	"sync"
	11	+	"testing"
	12	+	"time"
	13	+
	14	+	"github.com/bnema/zerowrap"
	15	+
	16	+	"bnema.dev/ermite-runner/internal/cachesvc"
	17	+	"bnema.dev/ermite-runner/internal/execstream/execpb"
	18	+	"bnema.dev/ermite-runner/internal/registryproxy"
	19	+	)
	20	+
	21	+	type registryLogs struct {
	22	+	mu sync.Mutex
	23	+	b bytes.Buffer
	24	+	}
	25	+
	26	+	func (b *registryLogs) Write(p []byte) (int, error) {
	27	+	b.mu.Lock()
	28	+	defer b.mu.Unlock()
	29	+	return b.b.Write(p)
	30	+	}
	31	+	func (b *registryLogs) text() string { b.mu.Lock(); defer b.mu.Unlock(); return b.b.String() }
	32	+	func (b *registryLogs) reset() { b.mu.Lock(); defer b.mu.Unlock(); b.b.Reset() }
	33	+
	34	+	func TestDockerHubRegistryAcrossJobs(t *testing.T) {
	35	+	image := needE2E(t)
	36	+	cl := &http.Client{Timeout: 10 * time.Second}
	37	+	resp, err := cl.Get("https://registry-1.docker.io/v2/")
	38	+	if err != nil {
	39	+	t.Skipf("Docker Hub unreachable: %v", err)
	40	+	}
	41	+	_ = resp.Body.Close()
	42	+	if resp.StatusCode != http.StatusUnauthorized && resp.StatusCode != http.StatusOK {
	43	+	t.Skipf("Docker Hub unavailable: HTTP %d", resp.StatusCode)
	44	+	}
	45	+	var logs registryLogs
	46	+	p, err := registryproxy.New(registryproxy.Config{Dir: t.TempDir(), Max: 256 << 20, Log: zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &logs})})
	47	+	if err != nil {
	48	+	t.Fatal(err)
	49	+	}
	50	+	svc, err := cachesvc.New(cachesvc.Config{Dir: t.TempDir(), Registry: p})
	51	+	if err != nil {
	52	+	t.Fatal(err)
	53	+	}
	54	+	defer func() { _ = svc.CloseAll() }()
	55	+	d := newCacheDriver(t, image, svc)
	56	+	probe := runJob(t, d, jobSpec(`on: push
	57	+	jobs:
	58	+	j:
	59	+	runs-on: x
	60	+	steps:
	61	+	- run: if docker info >/dev/null 2>&1; then echo nested-dockerd-ready; else echo nested-dockerd-unavailable; fi
	62	+	`), nil)
	63	+	if !strings.Contains(strings.Join(probe.Logs, "\n"), "nested-dockerd-ready") {
	64	+	t.Skip("nested dockerd unavailable in sandbox; rootless Docker harness cannot run job containers")
	65	+	}
	66	+	for i := 0; i < 2; i++ {
	67	+	logs.reset()
	68	+	spec := jobSpec(`on: push
	69	+	jobs:
	70	+	j:
	71	+	runs-on: x
	72	+	container: alpine:3
	73	+	steps:
	74	+	- run: echo alpine-job
	75	+	`)
	76	+	// A registry-only job: the host sends the port and no token.
	77	+	spec.CachePort = cachesvc.DefaultPort
	78	+	s := runJob(t, d, spec, nil)
	79	+	if s.Result == nil \|\| s.Result.Conclusion != execpb.StepConclusion_STEP_CONCLUSION_SUCCESS {
	80	+	t.Fatalf("pull job %d: %v\n%s", i, s.Result, strings.Join(s.Logs, "\n"))
	81	+	}
	82	+	all := logs.text()
	83	+	manifestHit := false
	84	+	for _, line := range strings.Split(all, "\n") {
	85	+	var event struct {
	86	+	Message string `json:"message"`
	87	+	Hit bool `json:"hit"`
	88	+	}
	89	+	if json.Unmarshal([]byte(line), &event) == nil && event.Message == "registry manifest" && event.Hit {
	90	+	manifestHit = true
	91	+	}
	92	+	}
	93	+	if i == 1 && !manifestHit {
	94	+	t.Fatalf("second job missing manifest hit:\n%s", all)
	95	+	}
	96	+	t.Logf("pull job %d proxy logs:\n%s", i+1, all)
	97	+	if i == 1 && strings.Contains(all, `"message":"registry blob"`) {
	98	+	t.Fatalf("second job fetched upstream blobs:\n%s", all)
	99	+	}
	100	+	}
	101	+	// The mirror argv is unconditional: a job without the runtime channel
	102	+	// must still pull directly from Docker Hub.
	103	+	off := runJob(t, d, jobSpec(`on: push
	104	+	jobs:
	105	+	j:
	106	+	runs-on: x
	107	+	container: alpine:3
	108	+	steps:
	109	+	- run: echo direct-pull
	110	+	`), nil)
	111	+	if off.Result == nil \|\| off.Result.Conclusion != execpb.StepConclusion_STEP_CONCLUSION_SUCCESS {
	112	+	t.Fatalf("proxy-off pull: %v\n%s", off.Result, strings.Join(off.Logs, "\n"))
	113	+	}
	114	+	}

A internal/e2e/timing_test.go +83 -0

@@ -0,0 +1,83 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package e2e
	4	+
	5	+	import (
	6	+	"context"
	7	+	"encoding/json"
	8	+	"net/http"
	9	+	"sync"
	10	+	"testing"
	11	+	"time"
	12	+
	13	+	"github.com/bnema/zerowrap"
	14	+
	15	+	ermite "bnema.dev/ermite-api/gen/ermite"
	16	+	"bnema.dev/ermite-api/gen/ermite/ermiteconnect"
	17	+
	18	+	"bnema.dev/ermite-runner/internal/host"
	19	+	"bnema.dev/ermite-runner/internal/host/hosttest"
	20	+	)
	21	+
	22	+	type timingWriter struct {
	23	+	mu sync.Mutex
	24	+	lines [][]byte
	25	+	}
	26	+
	27	+	func (w *timingWriter) Write(p []byte) (int, error) {
	28	+	w.mu.Lock()
	29	+	defer w.mu.Unlock()
	30	+	w.lines = append(w.lines, append([]byte(nil), p...))
	31	+	return len(p), nil
	32	+	}
	33	+
	34	+	func TestJobTiming(t *testing.T) {
	35	+	image := needE2E(t)
	36	+	drv := newDriver(t, image)
	37	+	srv := hosttest.New()
	38	+	defer srv.Close()
	39	+	srv.Queue(&ermite.Job{JobId: "timing", RunId: 1, Attempt: 1, JobToken: "ermitejob_timing", WorkflowPath: ".github/workflows/ci.yml", WorkflowYaml: "name: timing\non: push\njobs:\n main:\n runs-on: ubuntu-latest\n steps:\n - run: echo timing\n", JobKey: "main", Matrix: "{}", Contexts: chainContexts("main"), Repo: "hello", TimeoutMinutes: 2})
	40	+	r := &host.Runner{
	41	+	Cfg: host.Config{URL: srv.URL, Name: "timing", Capacity: 1, Version: "test"}, Driver: drv,
	42	+	Poll: host.NewClient(srv.URL, hosttest.RunnerToken, http.DefaultTransport),
	43	+	Job: func(tok string) ermiteconnect.RunnerServiceClient {
	44	+	return host.NewClient(srv.URL, tok, http.DefaultTransport)
	45	+	},
	46	+	Timing: host.Timing{LogFlush: 20 * time.Millisecond, NoJobPause: 100 * time.Millisecond},
	47	+	}
	48	+	var logs timingWriter
	49	+	ctx, cancel := context.WithCancel(zerowrap.WithCtx(context.Background(), zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &logs})))
	50	+	done := make(chan error, 1)
	51	+	go func() { done <- r.Run(ctx) }()
	52	+	select {
	53	+	case <-srv.Done():
	54	+	case <-time.After(3 * time.Minute):
	55	+	cancel()
	56	+	t.Fatal("job did not complete")
	57	+	}
	58	+	cancel()
	59	+	select {
	60	+	case err := <-done:
	61	+	if err != nil {
	62	+	t.Fatal(err)
	63	+	}
	64	+	case <-time.After(time.Minute):
	65	+	t.Fatal("runner did not stop")
	66	+	}
	67	+	logs.mu.Lock()
	68	+	defer logs.mu.Unlock()
	69	+	for _, line := range logs.lines {
	70	+	var fields map[string]any
	71	+	if json.Unmarshal(line, &fields) != nil \|\| fields["message"] != "job finished" {
	72	+	continue
	73	+	}
	74	+	for _, key := range []string{"sandbox_ms", "guest_dockerd_ms"} {
	75	+	value, ok := fields[key].(float64)
	76	+	if !ok \|\| value < 0 {
	77	+	t.Errorf("%s missing or negative: %v", key, fields)
	78	+	}
	79	+	}
	80	+	return
	81	+	}
	82	+	t.Fatal("no job finished log")
	83	+	}

A internal/e2e/toolcache_test.go +82 -0

@@ -0,0 +1,82 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package e2e
	4	+
	5	+	import (
	6	+	"context"
	7	+	"os/exec"
	8	+	"strings"
	9	+	"testing"
	10	+	"time"
	11	+
	12	+	"bnema.dev/ermite-runner/internal/execstream"
	13	+	"bnema.dev/ermite-runner/internal/execstream/execpb"
	14	+	"bnema.dev/ermite-runner/internal/sandbox"
	15	+	)
	16	+
	17	+	func TestContainerSetupGoFindsToolcache(t *testing.T) {
	18	+	image := needE2E(t)
	19	+	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Minute)
	20	+	defer cancel()
	21	+	// Distinguish a missing cache from an unavailable image or Docker daemon.
	22	+	out, err := exec.CommandContext(ctx, "docker", "run", "--rm", "--entrypoint", "sh", image, "-c", "if test -d /opt/hostedtoolcache/go/1.27.1; then echo present; else echo absent; fi").CombinedOutput()
	23	+	if err != nil {
	24	+	t.Fatalf("probe toolcache: %v\n%s", err, out)
	25	+	}
	26	+	if strings.TrimSpace(string(out)) == "absent" {
	27	+	t.Skip("test image has no Go 1.27.1 toolcache")
	28	+	}
	29	+	d := newDriver(t, image)
	30	+	sb, err := d.New()
	31	+	if err != nil {
	32	+	t.Fatal(err)
	33	+	}
	34	+	defer func() {
	35	+	if err := sb.Stop(context.Background()); err != nil {
	36	+	t.Error(err)
	37	+	}
	38	+	}()
	39	+	conn, err := sb.Start(ctx, sandbox.JobSpec{JobID: "e2e-toolcache"})
	40	+	if err != nil {
	41	+	t.Fatal(err)
	42	+	}
	43	+	spec := jobSpec(`on: push
	44	+	jobs:
	45	+	j:
	46	+	runs-on: x
	47	+	steps:
	48	+	- uses: actions/setup-go@v7
	49	+	with:
	50	+	go-version: '1.27.1'
	51	+	cache: false
	52	+	- run: go version
	53	+	`)
	54	+	var logs []string
	55	+	var result *execpb.JobResult
	56	+	_, exit, err := execstream.DriveJob(conn, &execpb.Run{Job: spec}, nil, execstream.JobHandler{
	57	+	Resolve: func(_ context.Context, r execpb.ResolveRequest) execpb.ResolveResponse {
	58	+	resp := &execpb.ResolveResponse{}
	59	+	for _, ref := range r.Uses {
	60	+	if ref != "actions/setup-go@v7" {
	61	+	return &execpb.ResolveResponse{Error: "unexpected action: " + ref}
	62	+	}
	63	+	resp.Actions = append(resp.Actions, &execpb.ResolvedAction{Ref: ref, NameWithOwner: "actions/setup-go", ResolvedSha: "v7", TarballUrl: "https://codeload.github.com/actions/setup-go/tar.gz/refs/tags/v7"})
	64	+	}
	65	+	return resp
	66	+	},
	67	+	Log: func(l *execpb.Log) { logs = append(logs, l.Text) },
	68	+	JobResult: func(r *execpb.JobResult) { result = r },
	69	+	})
	70	+	all := strings.Join(logs, "\n")
	71	+	if err != nil {
	72	+	t.Fatalf("drive: %v\n%s", err, all)
	73	+	}
	74	+	if result == nil \|\| result.Conclusion != execpb.StepConclusion_STEP_CONCLUSION_SUCCESS \|\| exit == nil \|\| exit.Code != 0 {
	75	+	t.Fatalf("result %v exit %v\n%s", result, exit, all)
	76	+	}
	77	+	for _, want := range []string{"Found in cache", "go version go1.27.1"} {
	78	+	if !strings.Contains(all, want) {
	79	+	t.Errorf("log lacks %q\n%s", want, all)
	80	+	}
	81	+	}
	82	+	}

M internal/execstream/exec.proto +1 -0


@@ -48,6 +48,7 @@ message Hello {
48	string version = 1; // runner version of the executor	48		string version = 1; // runner version of the executor
49	string sandbox = 2; // "vm" or "container"	49		string sandbox = 2; // "vm" or "container"
50	string hostname = 3;	50		string hostname = 3;
		51	+	map<string, int64> boot_ms = 4;
51	}	52		}
52		53
53	// Run asks the executor to run a script or a job. Without job it is the stub	54		// Run asks the executor to run a script or a job. Without job it is the stub

M internal/execstream/execpb/exec.pb.go +39 -25 generated file: collapsed

load diff

M internal/guest/cacheurl_test.go +3 -3


@@ -121,11 +121,11 @@ func TestStartCacheRelay(t *testing.T) {
121		}	121		}
122		}	122		}
123			123
124	-	// No cache service, no relay and no variables; a port that is taken leaves the	124	+	// No port, no relay and no variables; a port that is taken leaves the job
125	-	// job without a cache instead of failing it.	125	+	// without a cache instead of failing it.
126		func TestStartCacheRelayWithoutServiceOrPort(t *testing.T) {	126		func TestStartCacheRelayWithoutServiceOrPort(t *testing.T) {
127		target := Target{Network: "unix", Addr: filepath.Join(t.TempDir(), "exec.sock")}	127		target := Target{Network: "unix", Addr: filepath.Join(t.TempDir(), "exec.sock")}
128	-	for _, spec := range []*execpb.JobSpec{{}, {CachePort: 9089}, {CacheToken: "tok"}} {	128	+	for _, spec := range []*execpb.JobSpec{{}, {CacheToken: "tok"}, {CacheToken: "tok", CacheMode: "write"}} {
129		if got := startCacheRelay(context.Background(), target, spec, noBridge); got != (cacheRelay{}) {	129		if got := startCacheRelay(context.Background(), target, spec, noBridge); got != (cacheRelay{}) {
130		t.Errorf("%+v: relay %+v", spec, got)	130		t.Errorf("%+v: relay %+v", spec, got)
131		}	131		}

A internal/guest/dockerd.go +15 -0

@@ -0,0 +1,15 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package guest
	4	+
	5	+	import (
	6	+	"fmt"
	7	+
	8	+	"bnema.dev/ermite-runner/internal/sandbox"
	9	+	)
	10	+
	11	+	func defaultDockerdArgs() []string {
	12	+	return []string{"/usr/bin/dockerd", "--data-root", sandbox.GuestScratch + "/docker",
	13	+	"--storage-driver", "overlay2", "--host", "unix:///var/run/docker.sock",
	14	+	"--registry-mirror", fmt.Sprintf("http://127.0.0.1:%d", sandbox.CacheVsockPort)}
	15	+	}

M internal/guest/exec.go +2 -1

 // ExecConfig configures the executor.
 type ExecConfig struct {
+	BootMs  map[string]int64
 	Target  Target
 	Sandbox string // "vm" or "container", reported in Hello
 	Version string
 	conn := execstream.NewConn(rw)
 	host, _ := os.Hostname()
 	if err := conn.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{
-		Version: cfg.Version, Sandbox: cfg.Sandbox, Hostname: host,
+		Version: cfg.Version, Sandbox: cfg.Sandbox, Hostname: host, BootMs: cfg.BootMs,
 	}}}); err != nil {
 		return 1, fmt.Errorf("send hello: %w", err)
 	}

M internal/guest/init.go +31 -6

 	"net/http"
 	"os"
 	"os/signal"
+	"strconv"
 	"strings"
 	"syscall"
 	"time"
 // (`ermite-runner exec`) as a child, reap orphans, stop dockerd, and finish by
 // powering the VM off, or exiting with the executor's code in a container.
 func Init(ctx context.Context, cfg InitConfig) int {
+	entry := time.Now()
+	// bootMs is the boot phase timing handed to the executor (ERMITE_BOOT_MS),
+	// which reports it in its Hello.
+	bootMs := make(map[string]int64)
 	log := zerowrap.FromCtx(ctx)
 	// The kernel starts a VM's init with umask 0, which dockerd, the executor
 	// and every step would inherit: files and t.TempDir() directories would be
 	mode := string(sandbox.Container)
 	if inVM {
 		mode = string(sandbox.VM)
+		if b, err := os.ReadFile("/proc/uptime"); err == nil {
+			if fields := strings.Fields(string(b)); len(fields) > 0 {
+				if seconds, err := strconv.ParseFloat(fields[0], 64); err == nil && seconds >= 0 {
+					bootMs["kernel"] = max(0, int64(seconds*1000)-time.Since(entry).Milliseconds())
+				}
+			}
+		}
+		start := time.Now()
 		if err := setupVM(log, args); err != nil {
 			log.Error().Err(err).Msg("init: vm setup failed")
 			powerOff()
 			return 1
 		}
+		bootMs["setup"] = time.Since(start).Milliseconds()
 	}
-	code := runPayload(ctx, cfg, mode, args)
+	code := runPayload(ctx, cfg, mode, args, bootMs)
 	if inVM {
 		powerOff()
 	}
 // with an empty environment.
 const defaultPath = "/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
-func runPayload(ctx context.Context, cfg InitConfig, mode string, args map[string]string) int {
+// runPayload starts dockerd and the executor and waits for them. It adds its
+// boot phases to bootMs, which the executor gets.
+func runPayload(ctx context.Context, cfg InitConfig, mode string, args map[string]string, bootMs map[string]int64) int {
 	log := zerowrap.FromCtx(ctx)
 	if os.Getenv("PATH") == "" {
 		_ = os.Setenv("PATH", defaultPath)
 		return 1
 	}
+	var dockerStart time.Time
 	var dockerPid, containerdPid int
 	_, statErr := os.Stat("/usr/bin/dockerd")
 	if !cfg.SkipDocker && (statErr == nil || cfg.DockerdArgs != nil) {
 		_ = os.MkdirAll(sandbox.GuestScratch+"/docker", 0o711)
 		argv := cfg.DockerdArgs
 		if argv == nil {
-			argv = []string{"/usr/bin/dockerd", "--data-root", sandbox.GuestScratch + "/docker",
+			argv = defaultDockerdArgs()
-				"--storage-driver", "overlay2", "--host", "unix:///var/run/docker.sock"}
 			// dockerd sets its umask to 0, and a containerd it starts itself
 			// inherits it, then every `docker exec` (the steps of a job
 			// container): their files would be world-writable. Start containerd
 			// here with our umask instead, as systemd does on GitHub's runners.
-			if pid, ok := startContainerd(ctx, log); ok {
+			start := time.Now()
+			pid, ok := startContainerd(ctx, log)
+			// A containerd that never came up still cost its wait: keep it in the
+			// breakdown. A missing binary returns at once (0 ms) and is omitted.
+			if ms := time.Since(start).Milliseconds(); ok || ms > 0 {
+				bootMs["containerd"] = ms
+			}
+			if ok {
 				containerdPid = pid
 				argv = append(argv, "--containerd", containerdSocket)
 			}
 		}
+		dockerStart = time.Now()
 		pid, err := spawn(argv, nil)
 		if err != nil {
 			log.Error().Err(err).Msg("init: start dockerd")
 			timeout = dockerReadyTimeout
 		}
 		err := waitDockerReady(ctx, log, sock, dockerPid, timeout, sigs)
+		bootMs["dockerd"] = time.Since(dockerStart).Milliseconds()
 		var exited *dockerdExitError
 		var abort *abortBootError
 		switch {
 		}
 	}
-	execEnv := append(os.Environ(), "ERMITE_CONNECT="+target, "ERMITE_SANDBOX="+mode, "ERMITE_VERSION="+cfg.Version)
+	execEnv := append(os.Environ(), "ERMITE_CONNECT="+target, "ERMITE_SANDBOX="+mode, "ERMITE_VERSION="+cfg.Version, "ERMITE_BOOT_MS="+formatBootMs(bootMs))
 	execPid, err := spawn(cfg.ExecArgs, execEnv)
 	if err != nil {
 		log.Error().Err(err).Msg("init: start executor")

M internal/guest/jobexec.go +7 -1

 func startCacheRelay(ctx context.Context, target Target, spec *execpb.JobSpec, bridge bridgeLookup) cacheRelay {
 	port := spec.GetCachePort()
 	url := cacheURL(port)
-	if url == "" || spec.GetCacheToken() == "" {
+	if url == "" {
 		return cacheRelay{}
 	}
 	log := zerowrap.FromCtx(ctx)
 		return cacheRelay{}
 	}
 	results := spec.GetResults()
+	// A registry-only job (no cache scope, no results service: the host sends
+	// no token) needs dockerd's loopback relay, but no action runtime URLs or
+	// token: neither node nor docker actions get ACTIONS_* variables.
+	if spec.GetCacheToken() == "" || (!results && spec.GetCacheMode() == "") {
+		return cacheRelay{relay: r}
+	}
 	c := cacheRelay{relay: r, url: url, token: spec.GetCacheToken(), mode: spec.GetCacheMode(),
 		results: results, cacheOff: results && spec.GetCacheMode() == ""}
 	if bridge == nil {

A internal/guest/registry_test.go +35 -0

@@ -0,0 +1,35 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package guest
	4	+
	5	+	import (
	6	+	"context"
	7	+	"strings"
	8	+	"testing"
	9	+
	10	+	"bnema.dev/ermite-runner/internal/execstream/execpb"
	11	+	)
	12	+
	13	+	func TestDefaultDockerdMirror(t *testing.T) {
	14	+	args := strings.Join(defaultDockerdArgs(), " ")
	15	+	if !strings.Contains(args, "--registry-mirror http://127.0.0.1:9089") {
	16	+	t.Fatal(args)
	17	+	}
	18	+	}
	19	+
	20	+	// A registry-only job (a port, no token, no mode, no results) gets the
	21	+	// loopback relay for dockerd and no runtime environment for its steps.
	22	+	func TestRegistryOnlyRelayHasNoRuntimeEnvironment(t *testing.T) {
	23	+	target := serveCache(t, t.TempDir())
	24	+	got := startCacheRelay(context.Background(), target, &execpb.JobSpec{CachePort: freePort(t)}, noBridge)
	25	+	defer got.close()
	26	+	if got.relay == nil {
	27	+	t.Fatal("missing loopback relay")
	28	+	}
	29	+	if got.token != "" {
	30	+	t.Fatalf("token %q for a registry-only job", got.token)
	31	+	}
	32	+	if got.url != "" \|\| got.containerURL != "" \|\| got.mode != "" \|\| got.results \|\| got.bridge != nil {
	33	+	t.Fatalf("runtime environment leaked: %+v", got)
	34	+	}
	35	+	}

A internal/guest/timing.go +38 -0

@@ -0,0 +1,38 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package guest
	4	+
	5	+	import (
	6	+	"sort"
	7	+	"strconv"
	8	+	"strings"
	9	+	)
	10	+
	11	+	func formatBootMs(ms map[string]int64) string {
	12	+	keys := make([]string, 0, len(ms))
	13	+	for k := range ms {
	14	+	keys = append(keys, k)
	15	+	}
	16	+	sort.Strings(keys)
	17	+	pairs := make([]string, 0, len(keys))
	18	+	for _, k := range keys {
	19	+	pairs = append(pairs, k+"="+strconv.FormatInt(ms[k], 10))
	20	+	}
	21	+	return strings.Join(pairs, ",")
	22	+	}
	23	+
	24	+	// ParseBootMs reads init's boot timing environment, ignoring malformed pairs.
	25	+	func ParseBootMs(value string) map[string]int64 {
	26	+	ms := make(map[string]int64)
	27	+	for _, pair := range strings.Split(value, ",") {
	28	+	key, value, ok := strings.Cut(pair, "=")
	29	+	if !ok \|\| key == "" {
	30	+	continue
	31	+	}
	32	+	n, err := strconv.ParseInt(value, 10, 64)
	33	+	if err == nil && n >= 0 {
	34	+	ms[key] = n
	35	+	}
	36	+	}
	37	+	return ms
	38	+	}

A internal/guest/timing_test.go +33 -0

@@ -0,0 +1,33 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package guest
	4	+
	5	+	import (
	6	+	"reflect"
	7	+	"testing"
	8	+	)
	9	+
	10	+	func TestBootMs(t *testing.T) {
	11	+	want := map[string]int64{"setup": 40, "dockerd": 2300, "kernel": 812}
	12	+	encoded := formatBootMs(want)
	13	+	if encoded != "dockerd=2300,kernel=812,setup=40" {
	14	+	t.Fatal(encoded)
	15	+	}
	16	+	if got := ParseBootMs(encoded); !reflect.DeepEqual(got, want) {
	17	+	t.Fatal(got)
	18	+	}
	19	+	if got := ParseBootMs("a=x,b,=3,c=-1,d=5"); !reflect.DeepEqual(got, map[string]int64{"d": 5}) {
	20	+	t.Fatal(got)
	21	+	}
	22	+	}
	23	+
	24	+	func TestHelloBootMs(t *testing.T) {
	25	+	want := map[string]int64{"dockerd": 23}
	26	+	_, _, _, hello, _, err := host(t, "true", 0, func(cfg *ExecConfig) { cfg.BootMs = want })
	27	+	if err != nil {
	28	+	t.Fatal(err)
	29	+	}
	30	+	if !reflect.DeepEqual(hello.BootMs, want) {
	31	+	t.Fatalf("Hello boot_ms = %v", hello.BootMs)
	32	+	}
	33	+	}

M internal/host/archives.go +39 -5


@@ -30,7 +30,7 @@ const (
30		// busy runner does not trip the forge's rate limit (codeload 429).	30		// busy runner does not trip the forge's rate limit (codeload 429).
31		//	31		//
32		// It only ever improves a resolution: an action that cannot be cached (no cache,	32		// It only ever improves a resolution: an action that cannot be cached (no cache,
33	-	// no channel for this job, a ref that did not resolve to a sha, a download that	33	+	// no cache scope for this job, a ref that did not resolve to a sha, a download that
34		// failed, a full disk) keeps its original URL and token, and the sandbox	34		// failed, a full disk) keeps its original URL and token, and the sandbox
35		// downloads it as before, with its retries and its messages. The sandbox prints	35		// downloads it as before, with its retries and its messages. The sandbox prints
36		// "Download action repository" in either case, so a hit reads like a miss in the	36		// "Download action repository" in either case, so a hit reads like a miss in the

@@ -41,7 +41,7 @@ func (j jobRun) cacheArchives(ctx context.Context, orig []ermite.ResolvedActio
41		return	41		return
42		}	42		}
43		if _, ok, err := cacheScope(j.job, j.contexts); err != nil \|\| !ok {	43		if _, ok, err := cacheScope(j.job, j.contexts); err != nil \|\| !ok {
44	-	return // no channel for this job: the guest has no relay either	44	+	return // action archives are served only to jobs with a cache scope
45		}	45		}
46		ttl := time.Duration(j.timeoutMinutes())*time.Minute + cacheTokenMargin	46		ttl := time.Duration(j.timeoutMinutes())*time.Minute + cacheTokenMargin
47		for i, a := range orig {	47		for i, a := range orig {

@@ -54,9 +54,27 @@ func (j jobRun) cacheArchives(ctx context.Context, orig []ermite.ResolvedActio
54		if !ok {	54		if !ok {
55		continue	55		continue
56		}	56		}
57	-	hit, err := rt.Archives.Ensure(ctx, key, func(ctx context.Context, w io.Writer) error {	57	+	// fetched: this call ran the download itself. An invalid key, a wait
58	-	return j.fetchArchive(ctx, a, origin, w)	58	+	// that was cancelled or a joined download that failed are no misses.
			59	+	var fetched bool
			60	+	var fetchTime time.Duration
			61	+	var bytes int64
			62	+	hit, verify, err := rt.Archives.Ensure(ctx, key, func(ctx context.Context, w io.Writer) error {
			63	+	fetched = true
			64	+	start := time.Now()
			65	+	cw := &archiveCountWriter{Writer: w}
			66	+	err := j.fetchArchive(ctx, a, origin, cw)
			67	+	fetchTime += time.Since(start)
			68	+	bytes += cw.n
			69	+	return err
59		})	70		})
			71	+	if fetched {
			72	+	j.mu.Lock()
			73	+	j.timeline.addMs("archive_miss_ms", fetchTime)
			74	+	j.timeline.add("archive_misses", 1)
			75	+	j.timeline.add("archive_miss_bytes", bytes)
			76	+	j.mu.Unlock()
			77	+	}
60		log := j.log.With().Str("action", a.NameWithOwner).Str("sha", a.ResolvedSha).Logger()	78		log := j.log.With().Str("action", a.NameWithOwner).Str("sha", a.ResolvedSha).Logger()
61		if err != nil {	79		if err != nil {
62		log.Warn().Err(err).Msg("action archive not cached; the sandbox downloads it")	80		log.Warn().Err(err).Msg("action archive not cached; the sandbox downloads it")

@@ -66,7 +84,11 @@ func (j jobRun) cacheArchives(ctx context.Context, orig []ermite.ResolvedActio
66		if u == "" {	84		if u == "" {
67		continue	85		continue
68		}	86		}
69	-	log.Info().Bool("hit", hit).Msg("action archive cache")	87	+	event := log.Info().Bool("hit", hit).Int64("verify_ms", verify.Milliseconds())
			88	+	if fetched {
			89	+	event = event.Int64("fetch_ms", fetchTime.Milliseconds()).Int64("bytes", bytes)
			90	+	}
			91	+	event.Msg("action archive cache")
70		c.TarballUrl, c.Token, c.AuthOrigin = u, "", ""	92		c.TarballUrl, c.Token, c.AuthOrigin = u, "", ""
71		}	93		}
72		}	94		}

@@ -102,3 +124,15 @@ func (j jobRun) fetchArchive(ctx context.Context, a ermite.ResolvedAction, ori
102		}	124		}
103		return err	125		return err
104		}	126		}
			127	+
			128	+	// archiveCountWriter counts bytes accepted by the cache.
			129	+	type archiveCountWriter struct {
			130	+	io.Writer
			131	+	n int64
			132	+	}
			133	+
			134	+	func (w *archiveCountWriter) Write(p []byte) (int, error) {
			135	+	n, err := w.Writer.Write(p)
			136	+	w.n += int64(n)
			137	+	return n, err
			138	+	}

M internal/host/archives_test.go +83 -2


@@ -3,7 +3,10 @@
3		package host	3		package host
4			4
5		import (	5		import (
			6	+	"bytes"
6		"context"	7		"context"
			8	+	"encoding/json"
			9	+	"io"
7		"net/http"	10		"net/http"
8		"net/http/httptest"	11		"net/http/httptest"
9		"path/filepath"	12		"path/filepath"

@@ -58,7 +61,7 @@ func newArchiveRig(t testing.T) archiveRig {
58		func (a archiveRig) job(id string) jobRun {	61		func (a archiveRig) job(id string) jobRun {
59		j := &jobRun{r: a.r, log: zerowrap.Logger{}, ctx: context.Background(),	62		j := &jobRun{r: a.r, log: zerowrap.Logger{}, ctx: context.Background(),
60		job: &ermite.Job{JobId: id, Ref: "refs/heads/main"},	63		job: &ermite.Job{JobId: id, Ref: "refs/heads/main"},
61	-	contexts: `{"github":{"repository":"o/r"}}`}	64	+	contexts: `{"github":{"repository":"o/r"}}`, timeline: timeline{}}
62		return j	65		return j
63		}	66		}
64			67

@@ -128,7 +131,7 @@ func TestCacheArchivesFallsBack(t *testing.T) {
128		}	131		}
129		}	132		}
130			133
131	-	// No cache channel for the job (no repository): the guest has no relay.	134	+	// No cache scope for the job (no repository): archives are not served.
132		o, c = a.action(strings.Repeat("d", 40))	135		o, c = a.action(strings.Repeat("d", 40))
133		j := a.job("j")	136		j := a.job("j")
134		j.contexts = `{}`	137		j.contexts = `{}`

@@ -145,3 +148,81 @@ func TestCacheArchivesFallsBack(t *testing.T) {
145		t.Errorf("cache off: %+v", c)	148		t.Errorf("cache off: %+v", c)
146		}	149		}
147		}	150		}
			151	+
			152	+	func TestArchiveTimingLogs(t *testing.T) {
			153	+	a := newArchiveRig(t)
			154	+	var logs bytes.Buffer
			155	+	j := a.job("timing")
			156	+	j.log = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &logs})
			157	+	for i := 0; i < 2; i++ {
			158	+	logs.Reset()
			159	+	o, c := a.action(strings.Repeat("a", 40))
			160	+	j.cacheArchives(context.Background(), []ermite.ResolvedAction{o}, []execpb.ResolvedAction{c})
			161	+	var fields map[string]any
			162	+	if err := json.Unmarshal(logs.Bytes(), &fields); err != nil {
			163	+	t.Fatal(err, logs.String())
			164	+	}
			165	+	if value, ok := fields["verify_ms"].(float64); !ok \|\| value < 0 {
			166	+	t.Fatal(fields)
			167	+	}
			168	+	if fields["hit"] != (i == 1) {
			169	+	t.Fatal(fields)
			170	+	}
			171	+	if i == 0 {
			172	+	if value, ok := fields["fetch_ms"].(float64); !ok \|\| value < 0 {
			173	+	t.Fatal(fields)
			174	+	}
			175	+	if value, ok := fields["bytes"].(float64); !ok \|\| value <= 0 {
			176	+	t.Fatal(fields)
			177	+	}
			178	+	} else if _, ok := fields["fetch_ms"]; ok {
			179	+	t.Fatal("hit has fetch_ms", fields)
			180	+	}
			181	+	}
			182	+	if j.timeline["archive_misses"] != 1 \|\| j.timeline["archive_miss_bytes"] <= 0 {
			183	+	t.Fatal(j.timeline)
			184	+	}
			185	+	}
			186	+
			187	+	// Only a download the job ran itself is a miss: a failed one counts, a job
			188	+	// whose wait for another job's download is cancelled does not.
			189	+	func TestArchiveMissesCountFetches(t *testing.T) {
			190	+	a := newArchiveRig(t)
			191	+	a.status.Store(http.StatusTooManyRequests)
			192	+	failed := a.job("failed")
			193	+	o, c := a.action(strings.Repeat("a", 40))
			194	+	failed.cacheArchives(context.Background(), []ermite.ResolvedAction{o}, []execpb.ResolvedAction{c})
			195	+	if failed.timeline["archive_misses"] != 1 {
			196	+	t.Fatalf("failed fetch: %v", failed.timeline)
			197	+	}
			198	+
			199	+	a.status.Store(http.StatusOK)
			200	+	// A joiner whose wait is cancelled while another job downloads.
			201	+	release := make(chan struct{})
			202	+	started, done := make(chan struct{}), make(chan struct{})
			203	+	sha := strings.Repeat("b", 40)
			204	+	key, ok := actionscache.Key(originOf(a.srv.URL), "x/y", sha)
			205	+	if !ok {
			206	+	t.Fatal("key")
			207	+	}
			208	+	go func() {
			209	+	defer close(done)
			210	+	_, _, _ = a.r.Archives.Ensure(context.Background(), key, func(_ context.Context, w io.Writer) error {
			211	+	close(started)
			212	+	<-release
			213	+	_, err := io.WriteString(w, "tarball")
			214	+	return err
			215	+	})
			216	+	}()
			217	+	<-started
			218	+	ctx, cancel := context.WithCancel(context.Background())
			219	+	cancel()
			220	+	joiner := a.job("joiner")
			221	+	o, c = a.action(sha)
			222	+	joiner.cacheArchives(ctx, []ermite.ResolvedAction{o}, []execpb.ResolvedAction{c})
			223	+	close(release)
			224	+	<-done // the download writes under t.TempDir: let it finish before cleanup
			225	+	if _, ok := joiner.timeline["archive_misses"]; ok {
			226	+	t.Fatalf("cancelled joiner: %v", joiner.timeline)
			227	+	}
			228	+	}

M internal/host/cache.go +8 -4

 // runtimeFor returns what the executor needs of the job's runtime channel: the
 // port it has in the guest, the job's ACTIONS_RUNTIME_TOKEN, the cache mode and
 // whether the channel serves the results service. The channel exists when the
-// runner serves a cache and the job has a cache scope or the results service;
+// runner serves a cache and the job has a cache scope, the results service,
-// without it, 0, "", "" and false. A job with the results service and no cache
+// or the cache serves a registry proxy. Without it, 0, "", "" and false.
-// scope gets an empty mode (the executor then sets no ACTIONS_CACHE_URL) and a
+// A job with the results service and no cache scope gets an empty mode and a
-// token that the cache refuses.
+// token that the cache refuses. A registry-only job (neither) gets the port
+// alone: no token, and so no runtime environment variables for its steps.
 func (j *jobRun) runtimeFor(rt *Runner) (port uint32, token, mode string, results bool) {
 	if rt.Cache == nil {
 		return 0, "", "", false
 		}
 	}
 	if !ok && !j.results {
+		if rt.Cache.RegistryEnabled() {
+			return cachesvc.DefaultPort, "", "", false
+		}
 		return 0, "", "", false
 	}
 	var scopes []string

M internal/host/fake_test.go +8 -2

 	blockStart chan struct{}     // when set, Start waits on it
 	specs      []sandbox.JobSpec // what each Start was asked for
 	iso        sandbox.Isolation
+	bootMs     map[string]int64 // the guest's Hello.boot_ms; nil: dockerd=2
 }
 func (d *fakeDriver) Mode() sandbox.Mode           { return sandbox.Container }
 	stoped bool
 }
-func (s *fakeSandbox) ID() string { return "er00000000" }
+func (s *fakeSandbox) ID() string                     { return "er00000000" }
+func (s *fakeSandbox) StartTimings() map[string]int64 { return map[string]int64{"socket_ms": 1} }
 func (s *fakeSandbox) Start(ctx context.Context, spec sandbox.JobSpec) (sandbox.Conn, error) {
 	d := s.d
 	d.mu.Lock()
 	}
 	d.started++
 	sc := d.script
+	bootMs := d.bootMs
+	if bootMs == nil {
+		bootMs = map[string]int64{"dockerd": 2}
+	}
 	d.mu.Unlock()
 	host, guest := net.Pipe()
 	s.mu.Lock()
 	go func() {
 		defer func() { _ = guest.Close() }()
 		c := execstream.NewConn(guest)
-		_ = c.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{Version: "test", Sandbox: "container"}}})
+		_ = c.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{Version: "test", Sandbox: "container", BootMs: bootMs}}})
 		// NamedValue frames (secrets, variables) come before Run.
 		vals := &seenValues{secrets: map[string]string{}, vars: map[string]string{}}
 		var f *execpb.Frame

M internal/host/job.go +23 -0


@@ -62,6 +62,8 @@ type jobRun struct {
62		62
63	mu sync.Mutex	63		mu sync.Mutex
64	steps map[int32]*ermite.StepUpdate	64		steps map[int32]*ermite.StepUpdate
		65	+	// timeline is the job's phase timing, guarded by mu.
		66	+	timeline timeline
65	// What the guest has told us, for the validation of the next frame: the	67		// What the guest has told us, for the validation of the next frame: the
66	// guest is untrusted code, its step numbers and lines are checked before	68		// guest is untrusted code, its step numbers and lines are checked before
67	// they reach the server (see violate).	69		// they reach the server (see violate).

@@ -494,6 +496,7 @@ func (j *jobRun) acknowledge(ctx context.Context, shutdown <-chan struct{}) bool
494	}	496		}
495	}()	497		}()
496	if j.ack(ackCtx) {	498		if j.ack(ackCtx) {
		499	+	j.timeSet("ack_ms", time.Since(j.receivedAt))
497	return true	500		return true
498	}	501		}
499	select {	502		select {

@@ -627,7 +630,16 @@ func (j jobRun) execute(ctx context.Context, rt Runner, stopHard <-chan struct
627	j.features = j.loadFeatures(ctx, rt)	630		j.features = j.loadFeatures(ctx, rt)
628	j.results = j.resultsOn(rt)	631		j.results = j.resultsOn(rt)
629		632
		633	+	start := time.Now()
630	conn, err := j.startSandbox(ctx, rt, sb, stopHard)	634		conn, err := j.startSandbox(ctx, rt, sb, stopHard)
		635	+	j.timeSet("sandbox_ms", time.Since(start))
		636	+	if timed, ok := sb.(sandbox.Timed); ok && err == nil {
		637	+	j.mu.Lock()
		638	+	for k, v := range timed.StartTimings() {
		639	+	j.timeline["sb_"+k] = max(0, v)
		640	+	}
		641	+	j.mu.Unlock()
		642	+	}
631	if err != nil {	643		if err != nil {
632	if ctx.Err() != nil \|\| j.cancelRequested() {	644		if ctx.Err() != nil \|\| j.cancelRequested() {
633	return outcome{conclusion: ermite.CiConclusion_CI_CONCLUSION_CANCELLED, shutdown: j.isStopping()}	645		return outcome{conclusion: ermite.CiConclusion_CI_CONCLUSION_CANCELLED, shutdown: j.isStopping()}

@@ -651,7 +663,9 @@ func (j jobRun) execute(ctx context.Context, rt Runner, stopHard <-chan struct
651	}	663		}
652	}()	664		}()
653		665
		666	+	start = time.Now()
654	exit, err := j.drive(conn, rt)	667		exit, err := j.drive(conn, rt)
		668	+	j.timeSet("run_ms", time.Since(start))
655	return j.outcomeOf(ctx, exit, err)	669		return j.outcomeOf(ctx, exit, err)
656	}	670		}
657		671

@@ -660,6 +674,8 @@ func (j jobRun) execute(ctx context.Context, rt Runner, stopHard <-chan struct
660	func (j jobRun) stopSandbox(ctx context.Context, rt Runner, sb sandbox.Sandbox) {	674		func (j jobRun) stopSandbox(ctx context.Context, rt Runner, sb sandbox.Sandbox) {
661	sctx, cancel := context.WithTimeout(context.WithoutCancel(ctx), j.t.StopDeadline)	675		sctx, cancel := context.WithTimeout(context.WithoutCancel(ctx), j.t.StopDeadline)
662	defer cancel()	676		defer cancel()
		677	+	start := time.Now()
		678	+	defer func() { j.timeSet("stop_ms", time.Since(start)) }()
663	if err := sb.Stop(sctx); err != nil {	679		if err := sb.Stop(sctx); err != nil {
664	j.log.Error().Err(err).Msg("stopping the sandbox")	680		j.log.Error().Err(err).Msg("stopping the sandbox")
665	if errors.Is(err, sandbox.ErrLeaked) {	681		if errors.Is(err, sandbox.ErrLeaked) {

@@ -706,6 +722,11 @@ func (j jobRun) drive(conn sandbox.Conn, rt Runner) (*execpb.Exit, error) {
706	}	722		}
707	run.Job.CachePort, run.Job.CacheToken, run.Job.CacheMode, run.Job.Results = j.runtimeFor(rt)	723		run.Job.CachePort, run.Job.CacheToken, run.Job.CacheMode, run.Job.Results = j.runtimeFor(rt)
708	_, exit, err := execstream.DriveJob(conn, run, j.cancelCh, execstream.JobHandler{	724		_, exit, err := execstream.DriveJob(conn, run, j.cancelCh, execstream.JobHandler{
		725	+	Hello: func(h *execpb.Hello) {
		726	+	j.mu.Lock()
		727	+	defer j.mu.Unlock()
		728	+	j.timeline.addGuestBoot(h.GetBootMs())
		729	+	},
709	StepStarted: j.stepStarted, StepCompleted: j.stepCompleted,	730		StepStarted: j.stepStarted, StepCompleted: j.stepCompleted,
710	Log: j.logLine,	731		Log: j.logLine,
711	JobResult: func(r *execpb.JobResult) { j.mu.Lock(); j.result = r; j.mu.Unlock() },	732		JobResult: func(r *execpb.JobResult) { j.mu.Lock(); j.result = r; j.mu.Unlock() },

@@ -818,6 +839,8 @@ func (j *jobRun) sandboxError(msg string) {
818	// complete reports the end of the job. CompleteJob is idempotent, so a lost	839		// complete reports the end of the job. CompleteJob is idempotent, so a lost
819	// response is retried until it is answered (applied or not).	840		// response is retried until it is answered (applied or not).
820	func (j *jobRun) complete(ctx context.Context, conclusion ermite.CiConclusion, outputs map[string]string, shutdown bool) {	841		func (j *jobRun) complete(ctx context.Context, conclusion ermite.CiConclusion, outputs map[string]string, shutdown bool) {
		842	+	start := time.Now()
		843	+	defer func() { j.timeSet("complete_ms", time.Since(start)) }()
821	req := &ermite.CompleteJobRequest{	844		req := &ermite.CompleteJobRequest{
822	JobId: j.job.JobId, Conclusion: conclusion, Outputs: outputs,	845		JobId: j.job.JobId, Conclusion: conclusion, Outputs: outputs,
823	RunnerShutdown: shutdown && conclusion == ermite.CiConclusion_CI_CONCLUSION_CANCELLED,	846		RunnerShutdown: shutdown && conclusion == ermite.CiConclusion_CI_CONCLUSION_CANCELLED,

A internal/host/registry_test.go +49 -0

@@ -0,0 +1,49 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import (
	6	+	"testing"
	7	+
	8	+	"bnema.dev/ermite-api/gen/ermite"
	9	+
	10	+	"bnema.dev/ermite-runner/internal/cachesvc"
	11	+	"bnema.dev/ermite-runner/internal/registryproxy"
	12	+	)
	13	+
	14	+	// A job with neither a cache scope nor the results service gets the channel
	15	+	// for the registry proxy alone: its port and no token. Without the proxy, or
	16	+	// without the cache, it gets no channel.
	17	+	func TestRuntimeForRegistryOnly(t *testing.T) {
	18	+	proxy, err := registryproxy.New(registryproxy.Config{Dir: t.TempDir(), Max: 1 << 20})
	19	+	if err != nil {
	20	+	t.Fatal(err)
	21	+	}
	22	+	withRegistry, err := cachesvc.New(cachesvc.Config{Dir: t.TempDir(), Registry: proxy})
	23	+	if err != nil {
	24	+	t.Fatal(err)
	25	+	}
	26	+	defer func() { _ = withRegistry.CloseAll() }()
	27	+	without, err := cachesvc.New(cachesvc.Config{Dir: t.TempDir()})
	28	+	if err != nil {
	29	+	t.Fatal(err)
	30	+	}
	31	+	defer func() { _ = without.CloseAll() }()
	32	+	// No repository in the contexts: the job has no cache scope.
	33	+	j := &jobRun{job: &ermite.Job{JobId: "j1", TimeoutMinutes: 5}}
	34	+	port, tok, mode, results := j.runtimeFor(&Runner{Cache: withRegistry})
	35	+	if port != cachesvc.DefaultPort \|\| tok != "" \|\| mode != "" \|\| results {
	36	+	t.Fatalf("registry only: %d %q %q %v", port, tok, mode, results)
	37	+	}
	38	+	if p, _, _, _ := j.runtimeFor(&Runner{Cache: without}); p != 0 {
	39	+	t.Fatal("proxy off still supplies a channel")
	40	+	}
	41	+	if p, _, _, _ := j.runtimeFor(&Runner{}); p != 0 {
	42	+	t.Fatal("cache off still supplies a channel")
	43	+	}
	44	+	// A job with a cache scope still gets its token, proxy or not.
	45	+	scoped := &jobRun{job: &ermite.Job{JobId: "j1", Ref: "refs/heads/main", TimeoutMinutes: 5}, contexts: `{"github":{"repository":"o/r"}}`}
	46	+	if _, tok, mode, _ := scoped.runtimeFor(&Runner{Cache: withRegistry}); tok == "" \|\| mode != "write" {
	47	+	t.Fatalf("scoped job: %q %q", tok, mode)
	48	+	}
	49	+	}

M internal/host/resolve.go +8 -0


@@ -8,6 +8,7 @@ import (
8	"errors"	8		"errors"
9	"fmt"	9		"fmt"
10	"strings"	10		"strings"
		11	+	"time"
11	"unicode/utf8"	12		"unicode/utf8"
12		13
13	"connectrpc.com/connect"	14		"connectrpc.com/connect"

@@ -111,6 +112,13 @@ func badRefRune(r rune) bool {
111	// (ActionManager: FailedToResolveActionDownloadInfoException). ctx ends with the	112		// (ActionManager: FailedToResolveActionDownloadInfoException). ctx ends with the
112	// session.	113		// session.
113	func (j jobRun) resolveActions(ctx context.Context, req execpb.ResolveRequest) *execpb.ResolveResponse {	114		func (j jobRun) resolveActions(ctx context.Context, req execpb.ResolveRequest) *execpb.ResolveResponse {
		115	+	start := time.Now()
		116	+	defer func() {
		117	+	j.mu.Lock()
		118	+	defer j.mu.Unlock()
		119	+	j.timeline.addMs("resolve_ms", time.Since(start))
		120	+	j.timeline.add("resolve_calls", 1)
		121	+	}()
114	fail := func(format string, a ...any) *execpb.ResolveResponse {	122		fail := func(format string, a ...any) *execpb.ResolveResponse {
115	return &execpb.ResolveResponse{Error: fmt.Sprintf(format, a...)}	123		return &execpb.ResolveResponse{Error: fmt.Sprintf(format, a...)}
116	}	124		}

M internal/host/resolve_test.go +1 -1


@@ -48,7 +48,7 @@ func (c resolveStub) ResolveActions(_ context.Context, r connect.Request[ermit
48		}	48		}
49			49
50		func resolveJob(c jobClient) *jobRun {	50		func resolveJob(c jobClient) *jobRun {
51	-	j := &jobRun{client: c, ctx: context.Background(), job: &ermite.Job{JobId: "j1"}, log: zerowrap.Logger{},	51	+	j := &jobRun{client: c, ctx: context.Background(), job: &ermite.Job{JobId: "j1"}, log: zerowrap.Logger{}, timeline: timeline{},
52		t: Timing{CallTimeout: time.Second, BackoffMin: time.Millisecond, BackoffMax: time.Millisecond}}	52		t: Timing{CallTimeout: time.Second, BackoffMin: time.Millisecond, BackoffMax: time.Millisecond}}
53		j.setOrigins(`{"github":{"server_url":"https://ermite.example"}}`, "https://ermite.example", "")	53		j.setOrigins(`{"github":{"server_url":"https://ermite.example"}}`, "https://ermite.example", "")
54		return j	54		return j

M internal/host/results_test.go +1 -1


@@ -485,7 +485,7 @@ func TestAnnotationsWaitingForTheServerAreBounded(t *testing.T) {
485		tm := fastTiming()	485		tm := fastTiming()
486		ctx, cancel := context.WithCancel(context.Background())	486		ctx, cancel := context.WithCancel(context.Background())
487		defer cancel()	487		defer cancel()
488	-	j := &jobRun{client: cl, t: tm, ctx: ctx, job: &ermite.Job{JobId: "j1"}, steps: map[int32]*ermite.StepUpdate{},	488	+	j := &jobRun{client: cl, t: tm, ctx: ctx, job: &ermite.Job{JobId: "j1"}, steps: map[int32]*ermite.StepUpdate{}, timeline: timeline{},
489		annSeen: map[int32]bool{}, sumSeen: map[int32]bool{}, features: jobFeatures{annotations: true},	489		annSeen: map[int32]bool{}, sumSeen: map[int32]bool{}, features: jobFeatures{annotations: true},
490		cancelCh: make(chan *execpb.Cancel, 1), log: zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: logs})}	490		cancelCh: make(chan *execpb.Cancel, 1), log: zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: logs})}
491		j.outbox = newOutbox(cl, "j1", tm, func(error) {}, j.log)	491		j.outbox = newOutbox(cl, "j1", tm, func(error) {}, j.log)

M internal/host/runner.go +2 -2


@@ -211,7 +211,7 @@ func (r Runner) startJob(ctx context.Context, log zerowrap.Logger, job ermite.
211		r: r, job: job, client: r.Job(job.JobToken), t: t, ctx: jctx, cancel: cancel,	211		r: r, job: job, client: r.Job(job.JobToken), t: t, ctx: jctx, cancel: cancel,
212		log: zerowrap.Logger{Logger: log.With().Str("job_id", job.JobId).Int64("run_id", job.RunId).Int32("attempt", job.Attempt).Logger()},	212		log: zerowrap.Logger{Logger: log.With().Str("job_id", job.JobId).Int64("run_id", job.RunId).Int32("attempt", job.Attempt).Logger()},
213		receivedAt: r.clock(), cancelCh: make(chan execpb.Cancel, 1), steps: map[int32]ermite.StepUpdate{},	213		receivedAt: r.clock(), cancelCh: make(chan execpb.Cancel, 1), steps: map[int32]ermite.StepUpdate{},
214	-	annSeen: map[int32]bool{}, sumSeen: map[int32]bool{},	214	+	annSeen: map[int32]bool{}, sumSeen: map[int32]bool{}, timeline: timeline{},
215		}	215		}
216		jr.log.Info().Str("job_key", job.JobKey).Msg("job assigned")	216		jr.log.Info().Str("job_key", job.JobKey).Msg("job assigned")
217		r.active.Add(1)	217		r.active.Add(1)

@@ -219,7 +219,7 @@ func (r Runner) startJob(ctx context.Context, log zerowrap.Logger, job ermite.
219		defer r.active.Done()	219		defer r.active.Done()
220		defer func() { <-slots }()	220		defer func() { <-slots }()
221		jr.run(r, shutdown)	221		jr.run(r, shutdown)
222	-	jr.log.Info().Msg("job finished")	222	+	jr.log.Info().Fields(jr.timingFields()).Msg("job finished")
223		}()	223		}()
224		}	224		}
225			225

M internal/host/runner_test.go +12 -0


@@ -39,6 +39,18 @@ func TestJobRunsAndReports(t *testing.T) {
39	if err := stop(); err != nil {	39		if err := stop(); err != nil {
40	t.Fatal(err)	40		t.Fatal(err)
41	}	41		}
		42	+	fields := jobFinished(t, h.logs.String())
		43	+	ms := map[string]float64{}
		44	+	for _, key := range []string{"ack_ms", "sandbox_ms", "run_ms", "stop_ms", "complete_ms", "total_ms", "sb_socket_ms", "guest_dockerd_ms"} {
		45	+	value, ok := fields[key].(float64)
		46	+	if !ok \|\| value < 0 {
		47	+	t.Errorf("%s = %v", key, fields[key])
		48	+	}
		49	+	ms[key] = value
		50	+	}
		51	+	if ms["total_ms"] < ms["sandbox_ms"]+ms["run_ms"] {
		52	+	t.Error("total shorter than sandbox + run")
		53	+	}
42	s := h.srv	54		s := h.srv
43	s.mu.Lock()	55		s.mu.Lock()
44	defer s.mu.Unlock()	56		defer s.mu.Unlock()

M internal/host/shutdown_test.go +1 -1


@@ -81,7 +81,7 @@ func TestReportBudgetFollowsTheShutdownChannel(t *testing.T) {
81		cl := &stubClient{}	81		cl := &stubClient{}
82		ctx, cancel := context.WithCancel(context.Background())	82		ctx, cancel := context.WithCancel(context.Background())
83		defer cancel()	83		defer cancel()
84	-	j := &jobRun{client: cl, t: tm, ctx: ctx, job: &ermite.Job{JobId: "j1"}, steps: map[int32]*ermite.StepUpdate{},	84	+	j := &jobRun{client: cl, t: tm, ctx: ctx, job: &ermite.Job{JobId: "j1"}, steps: map[int32]*ermite.StepUpdate{}, timeline: timeline{},
85		cancelCh: make(chan *execpb.Cancel, 1), log: zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &logBuf{}})}	85		cancelCh: make(chan *execpb.Cancel, 1), log: zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &logBuf{}})}
86		j.outbox = newOutbox(cl, "j1", tm, func(error) {}, j.log)	86		j.outbox = newOutbox(cl, "j1", tm, func(error) {}, j.log)
87		j.outbox.start(ctx)	87		j.outbox.start(ctx)

A internal/host/timeline.go +52 -0

@@ -0,0 +1,52 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import "time"
	6	+
	7	+	// timeline is the per-phase timing of a job, logged on its "job finished"
	8	+	// line: durations in milliseconds (the *_ms keys) and counters. A jobRun
	9	+	// creates it once, in startJob; it is guarded by jobRun.mu.
	10	+	type timeline map[string]int64
	11	+
	12	+	// setMs records d as the duration of a phase, in whole milliseconds.
	13	+	func (t timeline) setMs(key string, d time.Duration) { t[key] = max(0, d.Milliseconds()) }
	14	+
	15	+	// addMs adds d to the summed duration of a phase that may run several times.
	16	+	func (t timeline) addMs(key string, d time.Duration) { t[key] += max(0, d.Milliseconds()) }
	17	+
	18	+	// add adds n to a counter.
	19	+	func (t timeline) add(key string, n int64) { t[key] += n }
	20	+
	21	+	// guestBootKeys are the boot phases the guest may report in its Hello: the
	22	+	// host logs these as guest_<key>_ms and ignores any other key, as it does not
	23	+	// trust the guest.
	24	+	var guestBootKeys = []string{"kernel", "setup", "containerd", "dockerd"}
	25	+
	26	+	// addGuestBoot records the guest's boot phases: known keys with a value of
	27	+	// at least 0.
	28	+	func (t timeline) addGuestBoot(ms map[string]int64) {
	29	+	for _, k := range guestBootKeys {
	30	+	if v, ok := ms[k]; ok && v >= 0 {
	31	+	t["guest_"+k+"_ms"] = v
	32	+	}
	33	+	}
	34	+	}
	35	+
	36	+	func (j *jobRun) timeSet(key string, d time.Duration) {
	37	+	j.mu.Lock()
	38	+	defer j.mu.Unlock()
	39	+	j.timeline.setMs(key, d)
	40	+	}
	41	+
	42	+	// timingFields sets total_ms and returns a copy of the timeline for the log.
	43	+	func (j *jobRun) timingFields() map[string]any {
	44	+	j.mu.Lock()
	45	+	defer j.mu.Unlock()
	46	+	j.timeline.setMs("total_ms", time.Since(j.receivedAt))
	47	+	fields := make(map[string]any, len(j.timeline))
	48	+	for k, v := range j.timeline {
	49	+	fields[k] = v
	50	+	}
	51	+	return fields
	52	+	}

A internal/host/timeline_test.go +74 -0

@@ -0,0 +1,74 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import (
	6	+	"encoding/json"
	7	+	"fmt"
	8	+	"strings"
	9	+	"testing"
	10	+
	11	+	ermite "bnema.dev/ermite-api/gen/ermite"
	12	+	)
	13	+
	14	+	// jobFinished returns the fields of the one "job finished" line of logs.
	15	+	func jobFinished(t *testing.T, logs string) map[string]any {
	16	+	t.Helper()
	17	+	var found map[string]any
	18	+	for _, line := range strings.Split(logs, "\n") {
	19	+	var fields map[string]any
	20	+	if json.Unmarshal([]byte(line), &fields) != nil \|\| fields["message"] != "job finished" {
	21	+	continue
	22	+	}
	23	+	if found != nil {
	24	+	t.Fatal("two job finished lines")
	25	+	}
	26	+	found = fields
	27	+	}
	28	+	if found == nil {
	29	+	t.Fatalf("no job finished line: %s", logs)
	30	+	}
	31	+	return found
	32	+	}
	33	+
	34	+	// The guest is untrusted: of its Hello.boot_ms, the job finished line keeps
	35	+	// only the known phases with a value of at least 0, whatever else it sends.
	36	+	func TestHostileGuestBootTimings(t *testing.T) {
	37	+	h := newHarness(t, simpleScript("hello"))
	38	+	hostile := map[string]int64{
	39	+	"kernel": 5,
	40	+	"dockerd": -7, // negative: dropped
	41	+	"setup": 0,
	42	+	"total": 1, // would overwrite a host field as guest_total_ms
	43	+	"": 3,
	44	+	"x\"y": 4,
	45	+	"../../etc": 5,
	46	+	"containerd": 9,
	47	+	}
	48	+	for i := range 500 {
	49	+	hostile[fmt.Sprint("junk", i)] = int64(i)
	50	+	}
	51	+	h.driver.bootMs = hostile
	52	+	h.srv.jobs = []*ermite.Job{testJob("j1")}
	53	+	stop := h.run(t)
	54	+	eventually(t, "CompleteJob", func() bool { return h.srv.completeCount() == 1 })
	55	+	if err := stop(); err != nil {
	56	+	t.Fatal(err)
	57	+	}
	58	+	fields := jobFinished(t, h.logs.String())
	59	+	var guest []string
	60	+	for k := range fields {
	61	+	if strings.HasPrefix(k, "guest_") {
	62	+	guest = append(guest, k)
	63	+	}
	64	+	}
	65	+	want := map[string]float64{"guest_kernel_ms": 5, "guest_setup_ms": 0, "guest_containerd_ms": 9}
	66	+	if len(guest) != len(want) {
	67	+	t.Fatalf("guest fields %v, want %v", guest, want)
	68	+	}
	69	+	for k, v := range want {
	70	+	if got, ok := fields[k].(float64); !ok \|\| got != v {
	71	+	t.Errorf("%s = %v, want %v", k, fields[k], v)
	72	+	}
	73	+	}
	74	+	}

A internal/registryproxy/accept.go +41 -0

@@ -0,0 +1,41 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"sort"
	7	+	"strings"
	8	+	)
	9	+
	10	+	var manifestTypes = []string{
	11	+	"application/vnd.docker.distribution.manifest.v2+json",
	12	+	"application/vnd.docker.distribution.manifest.list.v2+json",
	13	+	"application/vnd.oci.image.manifest.v1+json",
	14	+	"application/vnd.oci.image.index.v1+json",
	15	+	}
	16	+
	17	+	// normalizeAccept bounds both negotiation and metadata cardinality to the
	18	+	// fifteen nonempty subsets of the supported manifest types.
	19	+	func normalizeAccept(raw string) string {
	20	+	seen := map[string]bool{}
	21	+	for _, part := range strings.Split(raw, ",") {
	22	+	typ, _, _ := strings.Cut(part, ";")
	23	+	typ = strings.ToLower(strings.TrimSpace(typ))
	24	+	for _, known := range manifestTypes {
	25	+	if typ == known {
	26	+	seen[typ] = true
	27	+	}
	28	+	}
	29	+	}
	30	+	if len(seen) == 0 {
	31	+	for _, typ := range manifestTypes {
	32	+	seen[typ] = true
	33	+	}
	34	+	}
	35	+	types := make([]string, 0, len(seen))
	36	+	for typ := range seen {
	37	+	types = append(types, typ)
	38	+	}
	39	+	sort.Strings(types)
	40	+	return strings.Join(types, ",")
	41	+	}

A internal/registryproxy/accept_test.go +112 -0

@@ -0,0 +1,112 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"fmt"
	7	+	"io"
	8	+	"net/http"
	9	+	"net/http/httptest"
	10	+	"strings"
	11	+	"sync"
	12	+	"testing"
	13	+	)
	14	+
	15	+	// Accept is reduced to the known manifest types, so its variants map to
	16	+	// a bounded set of keys.
	17	+	func TestNormalizeAccept(t *testing.T) {
	18	+	const index, v2 = "application/vnd.oci.image.index.v1+json", "application/vnd.docker.distribution.manifest.v2+json"
	19	+	all := normalizeAccept("")
	20	+	if strings.Count(all, ",") != len(manifestTypes)-1 {
	21	+	t.Fatalf("default key %q", all)
	22	+	}
	23	+	for _, tc := range []struct{ in, want string }{
	24	+	{index + ";q=0.9, " + strings.ToUpper(v2) + " , " + index, v2 + "," + index},
	25	+	{" " + index + " ;q=0.1", index},
	26	+	{"text/html, /", all},
	27	+	{"", all},
	28	+	} {
	29	+	if got := normalizeAccept(tc.in); got != tc.want {
	30	+	t.Errorf("normalizeAccept(%q) = %q, want %q", tc.in, got, tc.want)
	31	+	}
	32	+	}
	33	+	}
	34	+
	35	+	// The Accept variants a job sends for one tag reach upstream with every known
	36	+	// type they name, and make at most one tag file per subset of the known types.
	37	+	// dockerd's legacy client sends one Accept line per type; the 8 KiB bound
	38	+	// applies to the joined lines.
	39	+	func TestAcceptTagFiles(t *testing.T) {
	40	+	types := []string{
	41	+	"application/vnd.oci.image.index.v1+json",
	42	+	"application/vnd.docker.distribution.manifest.list.v2+json",
	43	+	"application/vnd.docker.distribution.manifest.v2+json",
	44	+	}
	45	+	for _, tc := range []struct {
	46	+	name string
	47	+	accepts func(i int) []string // the Accept lines of request i
	48	+	requests int
	49	+	maxTags int
	50	+	code int
	51	+	}{
	52	+	{"multi-line", func(int) []string { return types }, 2, 1, http.StatusOK},
	53	+	{"variants", func(i int) []string {
	54	+	switch i % 3 {
	55	+	case 1:
	56	+	return []string{fmt.Sprintf("x/only-junk-%d", i)}
	57	+	case 2:
	58	+	return []string{fmt.Sprintf("%s;q=0.%d, x/junk-%d, %s", types[0], i%10, i, types[1])}
	59	+	}
	60	+	return []string{fmt.Sprintf("%s;q=0.%d, x/junk-%d", types[0], i%10, i)}
	61	+	}, 300, 3, http.StatusOK},
	62	+	{"oversized", func(int) []string {
	63	+	lines := make([]string, 200)
	64	+	for i := range lines {
	65	+	lines[i] = strings.Repeat("x", 50)
	66	+	}
	67	+	return lines
	68	+	}, 1, 0, http.StatusNotFound},
	69	+	} {
	70	+	t.Run(tc.name, func(t *testing.T) {
	71	+	var mu sync.Mutex
	72	+	var seen []string
	73	+	srv := upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	74	+	mu.Lock()
	75	+	seen = append(seen, strings.Join(r.Header.Values("Accept"), ","))
	76	+	mu.Unlock()
	77	+	w.Header().Set("Content-Type", types[0])
	78	+	w.Header().Set("Docker-Content-Digest", sum(manifestBody))
	79	+	if r.Method == http.MethodGet {
	80	+	_, _ = io.WriteString(w, manifestBody)
	81	+	}
	82	+	})
	83	+	p := proxyWith(t, srv, Config{})
	84	+	for i := range tc.requests {
	85	+	r := httptest.NewRequest(http.MethodGet, "/v2/library/alpine/manifests/3", nil)
	86	+	lines := tc.accepts(i)
	87	+	for _, line := range lines {
	88	+	r.Header.Add("Accept", line)
	89	+	}
	90	+	w := httptest.NewRecorder()
	91	+	p.ServeHTTP(w, r)
	92	+	if w.Code != tc.code {
	93	+	t.Fatalf("request %d: %d", i, w.Code)
	94	+	}
	95	+	if tc.code != http.StatusOK {
	96	+	continue
	97	+	}
	98	+	mu.Lock()
	99	+	got := seen[len(seen)-1]
	100	+	mu.Unlock()
	101	+	for _, typ := range types {
	102	+	if strings.Contains(strings.Join(lines, ","), typ) && !strings.Contains(got, typ) {
	103	+	t.Errorf("upstream Accept %q lacks %s", got, typ)
	104	+	}
	105	+	}
	106	+	}
	107	+	if n := accounted(t, p.s); n > tc.maxTags \|\| (tc.maxTags > 0 && n == 0) {
	108	+	t.Fatalf("%d tag files for %d requests", n, tc.requests)
	109	+	}
	110	+	})
	111	+	}
	112	+	}

A internal/registryproxy/clients.go +105 -0

@@ -0,0 +1,105 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"context"
	7	+	"errors"
	8	+	"io"
	9	+	"net/http"
	10	+	"sync"
	11	+	"time"
	12	+	)
	13	+
	14	+	// upstreamClients returns the metadata client (auth, manifests: a total
	15	+	// timeout and no redirects) and the blob client (no total timeout, a response
	16	+	// header timeout, and redirects that drop the bearer when leaving the host).
	17	+	func upstreamClients(requestTimeout time.Duration) (metadata, blobs *http.Client) {
	18	+	metadata = &http.Client{
	19	+	Timeout: requestTimeout,
	20	+	CheckRedirect: func(http.Request, []http.Request) error { return http.ErrUseLastResponse },
	21	+	}
	22	+	blobs = &http.Client{
	23	+	CheckRedirect: func(req http.Request, via []http.Request) error {
	24	+	if len(via) >= 10 {
	25	+	return errors.New("too many registry redirects")
	26	+	}
	27	+	if len(via) > 0 && req.URL.Host != via[0].URL.Host {
	28	+	req.Header.Del("Authorization")
	29	+	}
	30	+	return nil
	31	+	},
	32	+	}
	33	+	if tr, ok := http.DefaultTransport.(*http.Transport); ok {
	34	+	tr = tr.Clone()
	35	+	tr.ResponseHeaderTimeout = requestTimeout
	36	+	blobs.Transport = tr
	37	+	}
	38	+	return metadata, blobs
	39	+	}
	40	+
	41	+	// idleBody serializes timer reset/stop against expiry. Cancellation interrupts
	42	+	// even a blocked transport read; only completed, nonempty reads renew the lease.
	43	+	type idleBody struct {
	44	+	io.ReadCloser
	45	+	mu sync.Mutex
	46	+	timer *time.Timer
	47	+	cancel context.CancelFunc
	48	+	idle time.Duration
	49	+	expired bool
	50	+	}
	51	+
	52	+	func (b *idleBody) Read(p []byte) (int, error) {
	53	+	n, err := b.ReadCloser.Read(p)
	54	+	if n > 0 {
	55	+	b.mu.Lock()
	56	+	if !b.expired {
	57	+	b.timer.Reset(b.idle)
	58	+	}
	59	+	b.mu.Unlock()
	60	+	}
	61	+	return n, err
	62	+	}
	63	+
	64	+	func (b *idleBody) Close() error {
	65	+	b.mu.Lock()
	66	+	b.expired = true
	67	+	b.timer.Stop()
	68	+	b.mu.Unlock()
	69	+	b.cancel()
	70	+	return b.ReadCloser.Close()
	71	+	}
	72	+
	73	+	// blob GETs a blob. Each attempt has only a header deadline (RequestTimeout)
	74	+	// and then a body progress deadline (BlobIdleTimeout), and no total transfer
	75	+	// deadline: the response body is an idleBody that owns the attempt's context.
	76	+	func (u upstream) blob(ctx context.Context, name, digest string) (http.Response, error) {
	77	+	return u.authorized(ctx, name, func(tok string) (*http.Response, error) {
	78	+	bodyCtx, cancel := context.WithCancel(ctx)
	79	+	lease := &idleBody{cancel: cancel, idle: u.blobIdle}
	80	+	lease.timer = time.AfterFunc(u.requestTimeout, func() { lease.mu.Lock(); lease.expired = true; cancel(); lease.mu.Unlock() })
	81	+	req, err := http.NewRequestWithContext(bodyCtx, http.MethodGet, u.base+"/v2/"+name+"/"+kindBlob.dir()+"/"+digest, nil)
	82	+	if err != nil {
	83	+	lease.timer.Stop()
	84	+	cancel()
	85	+	return nil, err
	86	+	}
	87	+	req.Header.Set("Authorization", "Bearer "+tok)
	88	+	resp, err := u.blobClient.Do(req)
	89	+	if err != nil {
	90	+	lease.timer.Stop()
	91	+	cancel()
	92	+	return nil, err
	93	+	}
	94	+	lease.ReadCloser = resp.Body
	95	+	resp.Body = lease
	96	+	if resp.StatusCode == http.StatusOK {
	97	+	lease.mu.Lock()
	98	+	if !lease.expired {
	99	+	lease.timer.Reset(u.blobIdle)
	100	+	}
	101	+	lease.mu.Unlock()
	102	+	}
	103	+	return resp, nil
	104	+	})
	105	+	}

A internal/registryproxy/flights_test.go +248 -0

@@ -0,0 +1,248 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"context"
	7	+	"fmt"
	8	+	"io"
	9	+	"net/http"
	10	+	"net/http/httptest"
	11	+	"os"
	12	+	"path/filepath"
	13	+	"strings"
	14	+	"sync"
	15	+	"sync/atomic"
	16	+	"testing"
	17	+	"time"
	18	+
	19	+	"github.com/bnema/zerowrap"
	20	+	)
	21	+
	22	+	// Concurrent requests for one digest share a single fetch.
	23	+	func TestSingleFlight(t *testing.T) {
	24	+	s := mustOpen(t, storeCfg(t.TempDir(), 1<<20))
	25	+	var calls atomic.Int32
	26	+	var wg sync.WaitGroup
	27	+	start := make(chan struct{})
	28	+	for range 20 {
	29	+	wg.Go(func() {
	30	+	<-start
	31	+	f, _, _, err := s.ensure(context.Background(), kindBlob, sum("content"), func(_ context.Context, w io.Writer) (string, error) {
	32	+	calls.Add(1)
	33	+	_, err := io.WriteString(w, "content")
	34	+	return "", err
	35	+	}, keepalive{})
	36	+	if err != nil {
	37	+	t.Error(err)
	38	+	return
	39	+	}
	40	+	_ = f.Close()
	41	+	})
	42	+	}
	43	+	close(start)
	44	+	wg.Wait()
	45	+	if calls.Load() != 1 {
	46	+	t.Fatalf("fetches %d", calls.Load())
	47	+	}
	48	+	}
	49	+
	50	+	// A guest that requests many digests and disconnects leaves no download
	51	+	// behind: once a flight has no waiter for the grace period, it is cancelled
	52	+	// upstream and its temporary file removed.
	53	+	func TestAbandonedDownloadsCancelled(t *testing.T) {
	54	+	u := newStallingUpstream(t)
	55	+	const n = 20
	56	+	p := proxyWith(t, u.srv, Config{AbandonGrace: 20 * time.Millisecond, MaxDownloads: n})
	57	+	for i := range n {
	58	+	serveCancelled(t, p, u, blobPath(i), int32(i+1))
	59	+	}
	60	+	waitFor(t, p.s, "every flight to end", func() bool { return len(p.s.flights) == 0 && p.s.downloads == 0 && p.s.pending == 0 })
	61	+	for end := time.Now().Add(5 * time.Second); u.cancelled.Load() != n; {
	62	+	if time.Now().After(end) {
	63	+	t.Fatalf("upstream saw %d cancellations of %d", u.cancelled.Load(), n)
	64	+	}
	65	+	time.Sleep(time.Millisecond)
	66	+	}
	67	+	waitFor(t, p.s, "tmp/ to be empty", func() bool {
	68	+	ds, _ := os.ReadDir(filepath.Join(p.s.dir, "tmp"))
	69	+	return len(ds) == 0
	70	+	})
	71	+	}
	72	+
	73	+	// A request that joins within the grace period keeps the download.
	74	+	func TestRejoinWithinGraceKeepsDownload(t *testing.T) {
	75	+	body := strings.Repeat("layer", 4000)
	76	+	release := make(chan struct{})
	77	+	var gets, cancelled atomic.Int32
	78	+	srv := upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	79	+	gets.Add(1)
	80	+	w.Header().Set("Content-Length", fmt.Sprint(len(body)))
	81	+	_, _ = io.WriteString(w, body[:10])
	82	+	w.(http.Flusher).Flush()
	83	+	select {
	84	+	case <-release:
	85	+	_, _ = io.WriteString(w, body[10:])
	86	+	case <-r.Context().Done():
	87	+	cancelled.Add(1)
	88	+	}
	89	+	})
	90	+	var once sync.Once
	91	+	t.Cleanup(func() { once.Do(func() { close(release) }) })
	92	+	p := proxyWith(t, srv, Config{AbandonGrace: time.Hour})
	93	+	path := "/v2/library/alpine/blobs/" + sum(body)
	94	+	ctx, cancel := context.WithCancel(context.Background())
	95	+	first := make(chan struct{})
	96	+	go func() {
	97	+	defer close(first)
	98	+	p.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, path, nil).WithContext(ctx))
	99	+	}()
	100	+	key := kindBlob.key(sum(body)[7:])
	101	+	waitFor(t, p.s, "the first waiter", func() bool { return waiters(p.s, key) == 1 })
	102	+	cancel()
	103	+	<-first
	104	+	w := httptest.NewRecorder()
	105	+	second := make(chan struct{})
	106	+	go func() { defer close(second); p.ServeHTTP(w, httptest.NewRequest(http.MethodGet, path, nil)) }()
	107	+	waitFor(t, p.s, "the second waiter", func() bool { return waiters(p.s, key) == 1 })
	108	+	once.Do(func() { close(release) })
	109	+	<-second
	110	+	if w.Code != http.StatusOK \|\| w.Body.String() != body \|\| gets.Load() != 1 \|\| cancelled.Load() != 0 {
	111	+	t.Fatalf("code %d, %d fetches, %d cancelled", w.Code, gets.Load(), cancelled.Load())
	112	+	}
	113	+	}
	114	+
	115	+	// The shared download does not belong to the client that started it. That
	116	+	// client disconnects mid-download; a second client, joining within the grace
	117	+	// period, still gets the blob and the blob is committed, from one upstream
	118	+	// fetch.
	119	+	func TestBlobFlightSurvivesInitiatorDisconnect(t *testing.T) {
	120	+	body := strings.Repeat("layer", 4000)
	121	+	half, release := make(chan struct{}), make(chan struct{})
	122	+	var releaseOnce sync.Once
	123	+	unblock := func() { releaseOnce.Do(func() { close(release) }) }
	124	+	var gets atomic.Int32
	125	+	srv := upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	126	+	gets.Add(1)
	127	+	w.Header().Set("Content-Length", fmt.Sprint(len(body)))
	128	+	_, _ = io.WriteString(w, body[:len(body)/2])
	129	+	w.(http.Flusher).Flush()
	130	+	close(half)
	131	+	<-release
	132	+	_, _ = io.WriteString(w, body[len(body)/2:])
	133	+	})
	134	+	t.Cleanup(unblock) // before srv.Close, which waits for the handler
	135	+	p := proxyWith(t, srv, Config{})
	136	+	path := "/v2/library/alpine/blobs/" + sum(body)
	137	+
	138	+	ctx, cancel := context.WithCancel(context.Background())
	139	+	first := httptest.NewRecorder()
	140	+	done := make(chan struct{})
	141	+	go func() {
	142	+	defer close(done)
	143	+	p.ServeHTTP(first, httptest.NewRequest(http.MethodGet, path, nil).WithContext(ctx))
	144	+	}()
	145	+	<-half
	146	+	cancel()
	147	+	<-done
	148	+	if strings.Contains(first.Body.String(), "layer") {
	149	+	t.Fatal("unverified bytes sent to the initiator")
	150	+	}
	151	+	key := kindBlob.key(sum(body)[7:])
	152	+	p.s.mu.Lock()
	153	+	left := waiters(p.s, key)
	154	+	p.s.mu.Unlock()
	155	+	if left != 0 {
	156	+	t.Fatalf("waiters after the disconnect: %d", left)
	157	+	}
	158	+
	159	+	second := httptest.NewRecorder()
	160	+	done = make(chan struct{})
	161	+	go func() {
	162	+	defer close(done)
	163	+	p.ServeHTTP(second, httptest.NewRequest(http.MethodGet, path, nil))
	164	+	}()
	165	+	waitFor(t, p.s, "the second client to join", func() bool { return waiters(p.s, key) == 1 })
	166	+	unblock()
	167	+	<-done
	168	+	if second.Code != http.StatusOK \|\| second.Body.String() != body {
	169	+	t.Fatalf("second client: %d", second.Code)
	170	+	}
	171	+	if _, err := os.Stat(filepath.Join(p.s.dir, key)); err != nil {
	172	+	t.Fatalf("blob not committed: %v", err)
	173	+	}
	174	+	if gets.Load() != 1 {
	175	+	t.Fatalf("%d upstream fetches", gets.Load())
	176	+	}
	177	+	}
	178	+
	179	+	// A client waiting for a progressing download is kept alive, so the cache
	180	+	// channel's progress deadline follows the download.
	181	+	func TestWaiterKeepAlive(t *testing.T) {
	182	+	body := strings.Repeat("layer", 4000)
	183	+	srv := upstreamWith(t, slowBlob(body, 10, 30*time.Millisecond))
	184	+	p := proxyWith(t, srv, Config{KeepAliveInterval: 10 * time.Millisecond})
	185	+	w := &keepAliveRecorder{ResponseRecorder: httptest.NewRecorder()}
	186	+	p.ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/v2/library/alpine/blobs/"+sum(body), nil))
	187	+	if w.Code != http.StatusOK \|\| w.calls.Load() == 0 {
	188	+	t.Fatalf("code %d, %d keepalives", w.Code, w.calls.Load())
	189	+	}
	190	+	}
	191	+
	192	+	// A panic in a download fails its flight and frees its slots; it does not
	193	+	// leave the waiters hanging.
	194	+	func TestPanickingFetchFailsFlight(t *testing.T) {
	195	+	c := storeCfg(t.TempDir(), 1<<20)
	196	+	c.maxDownloads = 1
	197	+	s := mustOpen(t, c)
	198	+	q := NewQuota(1)
	199	+	ctx, cancel := context.WithTimeout(WithQuota(context.Background(), q), 5*time.Second)
	200	+	defer cancel()
	201	+	_, _, _, err := s.ensure(ctx, kindBlob, sum("x"), func(context.Context, io.Writer) (string, error) {
	202	+	panic("boom")
	203	+	}, keepalive{})
	204	+	if err == nil \|\| !strings.Contains(err.Error(), "panicked") {
	205	+	t.Fatalf("err %v", err)
	206	+	}
	207	+	s.mu.Lock()
	208	+	defer s.mu.Unlock()
	209	+	if s.downloads != 0 \|\| len(s.flights) != 0 \|\| q.used.Load() != 0 \|\| s.pending != 0 {
	210	+	t.Fatalf("leaked: downloads=%d flights=%d quota=%d pending=%d", s.downloads, len(s.flights), q.used.Load(), s.pending)
	211	+	}
	212	+	if ds, _ := os.ReadDir(filepath.Join(s.dir, "tmp")); len(ds) != 0 {
	213	+	t.Fatal("temp file kept")
	214	+	}
	215	+	}
	216	+
	217	+	// A request that joins a manifest flight logs hit=false, with its job.
	218	+	func TestJoinerLogsMiss(t *testing.T) {
	219	+	release := make(chan struct{})
	220	+	srv := upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	221	+	w.Header().Set("Content-Type", "application/vnd.oci.image.index.v1+json")
	222	+	w.Header().Set("Docker-Content-Digest", sum(manifestBody))
	223	+	if r.Method == http.MethodGet {
	224	+	<-release
	225	+	_, _ = io.WriteString(w, manifestBody)
	226	+	}
	227	+	})
	228	+	var logs syncBuffer
	229	+	p := proxyWith(t, srv, Config{Log: zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &logs})})
	230	+	var wg sync.WaitGroup
	231	+	for i := range 2 {
	232	+	wg.Go(func() {
	233	+	ctx := WithJob(context.Background(), fmt.Sprint("job-", i))
	234	+	p.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/v2/library/alpine/manifests/3", nil).WithContext(ctx))
	235	+	})
	236	+	}
	237	+	key := kindManifest.key(sum(manifestBody)[7:])
	238	+	waitFor(t, p.s, "two waiters", func() bool { return waiters(p.s, key) == 2 })
	239	+	close(release)
	240	+	wg.Wait()
	241	+	out := logs.String()
	242	+	if strings.Count(out, `"hit":false`) != 2 \|\| strings.Contains(out, `"hit":true`) {
	243	+	t.Fatalf("logs: %s", out)
	244	+	}
	245	+	if !strings.Contains(out, `"job_id":"job-0"`) \|\| !strings.Contains(out, `"job_id":"job-1"`) {
	246	+	t.Fatalf("no job_id on the registry lines: %s", out)
	247	+	}
	248	+	}

A internal/registryproxy/helpers_test.go +375 -0

@@ -0,0 +1,375 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"bytes"
	7	+	"context"
	8	+	"crypto/sha256"
	9	+	"fmt"
	10	+	"io"
	11	+	"net/http"
	12	+	"net/http/httptest"
	13	+	"os"
	14	+	"path/filepath"
	15	+	"strings"
	16	+	"sync"
	17	+	"sync/atomic"
	18	+	"testing"
	19	+	"time"
	20	+	)
	21	+
	22	+	// TestMain fails the run if any store hit an accounting bug (unpinLocked of
	23	+	// an unpinned entry), whichever test caused it.
	24	+	func TestMain(m *testing.M) {
	25	+	var bugs atomic.Int32
	26	+	defaultBugHook = func(msg string) {
	27	+	bugs.Add(1)
	28	+	fmt.Fprintln(os.Stderr, "registry cache bug:", msg)
	29	+	}
	30	+	code := m.Run()
	31	+	if n := bugs.Load(); n > 0 && code == 0 {
	32	+	fmt.Fprintf(os.Stderr, "FAIL: %d registry cache accounting bugs\n", n)
	33	+	code = 1
	34	+	}
	35	+	os.Exit(code)
	36	+	}
	37	+
	38	+	const manifestBody = `{"schemaVersion":2}`
	39	+	const blobBody = "a layer of bytes"
	40	+
	41	+	func sum(b string) string { return fmt.Sprintf("sha256:%x", sha256.Sum256([]byte(b))) }
	42	+
	43	+	// storeCfg is a complete configuration for a test that opens a store directly.
	44	+	func storeCfg(dir string, max int64) storeConfig {
	45	+	return storeConfig{dir: dir, max: max, now: time.Now, grace: time.Second, maxDownloads: 16, slotWait: time.Second}
	46	+	}
	47	+
	48	+	func mustOpen(t testing.T, c storeConfig) store {
	49	+	t.Helper()
	50	+	s, err := openStore(c)
	51	+	if err != nil {
	52	+	t.Fatal(err)
	53	+	}
	54	+	return s
	55	+	}
	56	+
	57	+	// put stores b as a blob.
	58	+	func put(t testing.T, s store, b string) {
	59	+	t.Helper()
	60	+	f, _, _, err := s.ensure(context.Background(), kindBlob, sum(b), func(_ context.Context, w io.Writer) (string, error) { _, err := io.WriteString(w, b); return "", err }, keepalive{})
	61	+	if err != nil {
	62	+	t.Fatal(err)
	63	+	}
	64	+	_ = f.Close()
	65	+	}
	66	+
	67	+	// putManifest stores m as a manifest of media type media.
	68	+	func putManifest(t testing.T, s store, m, media string) {
	69	+	t.Helper()
	70	+	f, _, _, err := s.ensure(context.Background(), kindManifest, sum(m), func(_ context.Context, w io.Writer) (string, error) {
	71	+	_, err := io.WriteString(w, m)
	72	+	return media, err
	73	+	}, keepalive{})
	74	+	if err != nil {
	75	+	t.Fatal(err)
	76	+	}
	77	+	_ = f.Close()
	78	+	}
	79	+
	80	+	// accounted checks that the store's total is exactly the sum of its entries and
	81	+	// within Max, and returns the number of tag files on disk.
	82	+	func accounted(t testing.T, s store) int {
	83	+	t.Helper()
	84	+	s.mu.Lock()
	85	+	defer s.mu.Unlock()
	86	+	var sum int64
	87	+	tags := 0
	88	+	for k, e := range s.entries {
	89	+	sum += e.size
	90	+	if e.size < minCharge {
	91	+	t.Errorf("%s charged %d, under the minimum", k, e.size)
	92	+	}
	93	+	if e.kind == kindTag {
	94	+	tags++
	95	+	if e.size != minCharge {
	96	+	t.Errorf("tag %s charged %d", k, e.size)
	97	+	}
	98	+	}
	99	+	}
	100	+	if sum != s.total \|\| s.total+s.pending > s.max {
	101	+	t.Fatalf("accounting: sum=%d total=%d pending=%d max=%d", sum, s.total, s.pending, s.max)
	102	+	}
	103	+	files, err := os.ReadDir(filepath.Join(s.dir, kindTag.dir()))
	104	+	if err != nil {
	105	+	t.Fatal(err)
	106	+	}
	107	+	if len(files) != tags {
	108	+	t.Fatalf("%d tag files, %d tag entries", len(files), tags)
	109	+	}
	110	+	return tags
	111	+	}
	112	+
	113	+	// waitFor polls cond (under the store lock) until it holds.
	114	+	func waitFor(t testing.T, s store, what string, cond func() bool) {
	115	+	t.Helper()
	116	+	for end := time.Now().Add(5 * time.Second); ; {
	117	+	s.mu.Lock()
	118	+	ok := cond()
	119	+	s.mu.Unlock()
	120	+	if ok {
	121	+	return
	122	+	}
	123	+	if time.Now().After(end) {
	124	+	t.Fatalf("timed out waiting for %s", what)
	125	+	}
	126	+	time.Sleep(time.Millisecond)
	127	+	}
	128	+	}
	129	+
	130	+	// waiters is the number of requests waiting for the flight of key (-1: none).
	131	+	// The caller holds the store lock.
	132	+	func waiters(s *store, key string) int {
	133	+	if fl, ok := s.flights[key]; ok {
	134	+	return fl.waiters
	135	+	}
	136	+	return -1
	137	+	}
	138	+
	139	+	// upstreamWith fakes Docker Hub: /token answers an anonymous token and h serves
	140	+	// everything else.
	141	+	func upstreamWith(t testing.T, h http.HandlerFunc) httptest.Server {
	142	+	t.Helper()
	143	+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	144	+	if r.URL.Path == "/token" {
	145	+	_, _ = io.WriteString(w, `{"token":"public","expires_in":300}`)
	146	+	return
	147	+	}
	148	+	h(w, r)
	149	+	}))
	150	+	t.Cleanup(srv.Close)
	151	+	return srv
	152	+	}
	153	+
	154	+	func proxyWith(t testing.T, srv httptest.Server, c Config) *Proxy {
	155	+	t.Helper()
	156	+	if c.Dir == "" {
	157	+	c.Dir = t.TempDir()
	158	+	}
	159	+	if c.Max == 0 {
	160	+	c.Max = 8 << 20
	161	+	}
	162	+	c.Upstream, c.AuthURL = srv.URL, srv.URL+"/token"
	163	+	p, err := New(c)
	164	+	if err != nil {
	165	+	t.Fatal(err)
	166	+	}
	167	+	return p
	168	+	}
	169	+
	170	+	// fakeRegistry is a Docker Hub with one manifest and one blob, served from a
	171	+	// CDN behind a redirect. It counts the requests it gets.
	172	+	type fakeRegistry struct {
	173	+	server *httptest.Server
	174	+	heads, gets, blobs, tokens atomic.Int32
	175	+	status atomic.Int32
	176	+	corrupt atomic.Bool
	177	+	}
	178	+
	179	+	func fake(t testing.T) fakeRegistry {
	180	+	t.Helper()
	181	+	f := &fakeRegistry{}
	182	+	cdn := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	183	+	if r.Header.Get("Authorization") != "" {
	184	+	t.Error("bearer leaked to CDN")
	185	+	}
	186	+	w.Header().Set("Content-Length", fmt.Sprint(len(blobBody)))
	187	+	if r.Method != http.MethodHead {
	188	+	b := blobBody
	189	+	if f.corrupt.Load() {
	190	+	b = strings.Repeat("x", len(b))
	191	+	}
	192	+	_, _ = io.WriteString(w, b)
	193	+	}
	194	+	}))
	195	+	t.Cleanup(cdn.Close)
	196	+	f.server = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	197	+	if r.URL.Path == "/token" {
	198	+	f.tokens.Add(1)
	199	+	if r.Header.Get("Authorization") != "" {
	200	+	t.Error("guest credentials forwarded to auth")
	201	+	}
	202	+	if r.URL.Query().Get("scope") != "repository:library/alpine:pull" {
	203	+	t.Error("wrong scope")
	204	+	}
	205	+	_, _ = io.WriteString(w, `{"token":"public","expires_in":300}`)
	206	+	return
	207	+	}
	208	+	if r.Header.Get("Authorization") != "Bearer public" {
	209	+	t.Errorf("wrong bearer %q", r.Header.Get("Authorization"))
	210	+	}
	211	+	if s := f.status.Load(); s != 0 {
	212	+	w.WriteHeader(int(s))
	213	+	return
	214	+	}
	215	+	if strings.Contains(r.URL.Path, "/manifests/") {
	216	+	w.Header().Set("Content-Type", "application/vnd.oci.image.index.v1+json")
	217	+	w.Header().Set("Docker-Content-Digest", sum(manifestBody))
	218	+	w.Header().Set("Content-Length", fmt.Sprint(len(manifestBody)))
	219	+	if r.Method == http.MethodHead {
	220	+	f.heads.Add(1)
	221	+	} else {
	222	+	f.gets.Add(1)
	223	+	_, _ = io.WriteString(w, manifestBody)
	224	+	}
	225	+	return
	226	+	}
	227	+	if strings.Contains(r.URL.Path, "/blobs/") {
	228	+	if r.Method == http.MethodGet {
	229	+	f.blobs.Add(1)
	230	+	}
	231	+	http.Redirect(w, r, cdn.URL+"/layer", http.StatusTemporaryRedirect)
	232	+	return
	233	+	}
	234	+	http.NotFound(w, r)
	235	+	}))
	236	+	t.Cleanup(f.server.Close)
	237	+	return f
	238	+	}
	239	+
	240	+	func proxyFor(t testing.T, f fakeRegistry) *Proxy {
	241	+	t.Helper()
	242	+	p, err := New(Config{Dir: t.TempDir(), Max: 8 << 20, Upstream: f.server.URL, AuthURL: f.server.URL + "/token"})
	243	+	if err != nil {
	244	+	t.Fatal(err)
	245	+	}
	246	+	return p
	247	+	}
	248	+
	249	+	// request serves one request with guest credentials that must never reach
	250	+	// upstream; headers are name, value pairs.
	251	+	func request(t testing.T, p http.Handler, method, path string, headers ...string) httptest.ResponseRecorder {
	252	+	t.Helper()
	253	+	r := httptest.NewRequest(method, path, nil)
	254	+	r.Header.Set("Authorization", "Bearer guest-secret")
	255	+	for i := 0; i < len(headers); i += 2 {
	256	+	r.Header.Set(headers[i], headers[i+1])
	257	+	}
	258	+	w := httptest.NewRecorder()
	259	+	p.ServeHTTP(w, r)
	260	+	return w
	261	+	}
	262	+
	263	+	// stallingUpstream serves a blob's first bytes and then holds the body until
	264	+	// the request is cancelled; it counts started and cancelled downloads.
	265	+	type stallingUpstream struct {
	266	+	srv *httptest.Server
	267	+	started, cancelled atomic.Int32
	268	+	}
	269	+
	270	+	func newStallingUpstream(t testing.T) stallingUpstream {
	271	+	t.Helper()
	272	+	u := &stallingUpstream{}
	273	+	u.srv = upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	274	+	u.started.Add(1)
	275	+	w.Header().Set("Content-Length", "1000000")
	276	+	_, _ = io.WriteString(w, "partial")
	277	+	w.(http.Flusher).Flush()
	278	+	select {
	279	+	case <-r.Context().Done():
	280	+	u.cancelled.Add(1)
	281	+	case <-time.After(10 * time.Second):
	282	+	}
	283	+	})
	284	+	return u
	285	+	}
	286	+
	287	+	func blobPath(i int) string { return "/v2/library/alpine/blobs/" + sum(fmt.Sprint("blob-", i)) }
	288	+
	289	+	// serveCancelled starts a request and cancels it once its download has begun.
	290	+	func serveCancelled(t testing.T, p Proxy, u *stallingUpstream, path string, started int32) {
	291	+	t.Helper()
	292	+	ctx, cancel := context.WithCancel(context.Background())
	293	+	done := make(chan struct{})
	294	+	go func() {
	295	+	defer close(done)
	296	+	p.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, path, nil).WithContext(ctx))
	297	+	}()
	298	+	waitFor(t, p.s, "the download to start", func() bool { return u.started.Load() >= started })
	299	+	cancel()
	300	+	<-done
	301	+	}
	302	+
	303	+	// serveAsync serves path with ctx on its own goroutine, into w (a new
	304	+	// recorder when nil); the status code comes on the returned channel.
	305	+	func serveAsync(p Proxy, ctx context.Context, path string, w keepAliveRecorder) <-chan int {
	306	+	if w == nil {
	307	+	w = &keepAliveRecorder{ResponseRecorder: httptest.NewRecorder()}
	308	+	}
	309	+	code := make(chan int, 1)
	310	+	go func() {
	311	+	p.ServeHTTP(w, httptest.NewRequest(http.MethodGet, path, nil).WithContext(ctx))
	312	+	code <- w.Code
	313	+	}()
	314	+	return code
	315	+	}
	316	+
	317	+	type keepAliveRecorder struct {
	318	+	*httptest.ResponseRecorder
	319	+	calls atomic.Int32
	320	+	}
	321	+
	322	+	func (k *keepAliveRecorder) KeepAlive() { k.calls.Add(1) }
	323	+
	324	+	// waitKeptAlive waits until w has been kept alive at least once.
	325	+	func waitKeptAlive(t testing.T, w keepAliveRecorder) {
	326	+	t.Helper()
	327	+	for end := time.Now().Add(5 * time.Second); w.calls.Load() == 0; time.Sleep(time.Millisecond) {
	328	+	if time.Now().After(end) {
	329	+	t.Fatal("request never kept alive")
	330	+	}
	331	+	}
	332	+	}
	333	+
	334	+	// blockingWriter holds a response in its first Write until release is closed.
	335	+	type blockingWriter struct {
	336	+	*httptest.ResponseRecorder
	337	+	started, release chan struct{}
	338	+	once sync.Once
	339	+	}
	340	+
	341	+	func (b *blockingWriter) Write(p []byte) (int, error) {
	342	+	b.once.Do(func() { close(b.started) })
	343	+	<-b.release
	344	+	return b.ResponseRecorder.Write(p)
	345	+	}
	346	+
	347	+	// slowBlob streams body in chunks, one every gap.
	348	+	func slowBlob(body string, chunks int, gap time.Duration) http.HandlerFunc {
	349	+	return func(w http.ResponseWriter, r *http.Request) {
	350	+	w.Header().Set("Content-Length", fmt.Sprint(len(body)))
	351	+	size := len(body) / chunks
	352	+	for i := 0; i < len(body); i += size {
	353	+	_, _ = io.WriteString(w, body[i:min(i+size, len(body))])
	354	+	w.(http.Flusher).Flush()
	355	+	select {
	356	+	case <-time.After(gap):
	357	+	case <-r.Context().Done():
	358	+	return
	359	+	}
	360	+	}
	361	+	}
	362	+	}
	363	+
	364	+	type syncBuffer struct {
	365	+	mu sync.Mutex
	366	+	b bytes.Buffer
	367	+	}
	368	+
	369	+	func (s *syncBuffer) Write(p []byte) (int, error) {
	370	+	s.mu.Lock()
	371	+	defer s.mu.Unlock()
	372	+	return s.b.Write(p)
	373	+	}
	374	+
	375	+	func (s *syncBuffer) String() string { s.mu.Lock(); defer s.mu.Unlock(); return s.b.String() }

A internal/registryproxy/hub_test.go +80 -0

@@ -0,0 +1,80 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"bytes"
	7	+	"encoding/json"
	8	+	"net/http/httptest"
	9	+	"os"
	10	+	"os/exec"
	11	+	"strings"
	12	+	"testing"
	13	+
	14	+	"github.com/bnema/zerowrap"
	15	+	)
	16	+
	17	+	// An opt-in manual check using curl against a real local HTTP listener, with
	18	+	// Docker Hub as upstream. No daemon is required.
	19	+	func TestDockerHubCurl(t *testing.T) {
	20	+	if os.Getenv("ERMITE_RUNNER_IT_REGISTRY") != "1" {
	21	+	t.Skip("set ERMITE_RUNNER_IT_REGISTRY=1 for live Docker Hub curl check")
	22	+	}
	23	+	var logs bytes.Buffer
	24	+	p, err := New(Config{Dir: t.TempDir(), Max: 64 << 20, Log: zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &logs})})
	25	+	if err != nil {
	26	+	t.Fatal(err)
	27	+	}
	28	+	srv := httptest.NewServer(p)
	29	+	defer srv.Close()
	30	+	curl := func(path string) []byte {
	31	+	t.Helper()
	32	+	out, err := exec.Command("curl", "--max-time", "20", "-fsS", "-H", "Accept: application/vnd.oci.image.index.v1+json, application/vnd.oci.image.manifest.v1+json", srv.URL+path).CombinedOutput()
	33	+	if err != nil {
	34	+	t.Fatalf("curl %s: %v: %s", path, err, out)
	35	+	}
	36	+	t.Logf("curl %s: HTTP 200, %d bytes", path, len(out))
	37	+	return out
	38	+	}
	39	+	var idx struct {
	40	+	Manifests []struct {
	41	+	Digest string
	42	+	Platform struct{ Architecture, OS string }
	43	+	}
	44	+	}
	45	+	b := curl("/v2/library/alpine/manifests/3")
	46	+	if err := json.Unmarshal(b, &idx); err != nil {
	47	+	t.Fatal(err)
	48	+	}
	49	+	if !bytes.Equal(b, curl("/v2/library/alpine/manifests/3")) {
	50	+	t.Fatal("tag changed during check")
	51	+	}
	52	+	var digest string
	53	+	for _, m := range idx.Manifests {
	54	+	if m.Platform.Architecture == "amd64" && m.Platform.OS == "linux" {
	55	+	digest = m.Digest
	56	+	break
	57	+	}
	58	+	}
	59	+	if !validDigest(digest) {
	60	+	t.Fatal("no linux/amd64 manifest")
	61	+	}
	62	+	var manifest struct{ Config struct{ Digest string } }
	63	+	if err := json.Unmarshal(curl("/v2/library/alpine/manifests/"+digest), &manifest); err != nil {
	64	+	t.Fatal(err)
	65	+	}
	66	+	if !validDigest(manifest.Config.Digest) {
	67	+	t.Fatal("no config blob")
	68	+	}
	69	+	path := "/v2/library/alpine/blobs/" + manifest.Config.Digest
	70	+	first := curl(path)
	71	+	second := curl(path)
	72	+	if !bytes.Equal(first, second) {
	73	+	t.Fatal("blob differs")
	74	+	}
	75	+	all := logs.String()
	76	+	t.Log(all)
	77	+	if !strings.Contains(all, `"hit":true`) \|\| strings.Count(all, `"message":"registry blob"`) != 1 {
	78	+	t.Fatal("missing cache hits or repeated blob miss")
	79	+	}
	80	+	}

A internal/registryproxy/proxy.go +338 -0

@@ -0,0 +1,338 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	// Package registryproxy provides an anonymous, pull-only Docker Hub mirror.
	4	+	// Its handler belongs on a sandbox's private runtime channel, not a public port.
	5	+	package registryproxy
	6	+
	7	+	import (
	8	+	"context"
	9	+	"encoding/hex"
	10	+	"errors"
	11	+	"io"
	12	+	"net/http"
	13	+	"net/url"
	14	+	"regexp"
	15	+	"strconv"
	16	+	"strings"
	17	+	"time"
	18	+
	19	+	"github.com/bnema/zerowrap"
	20	+	)
	21	+
	22	+	const manifestLimit = 4 << 20
	23	+
	24	+	// Config configures a Proxy. Max must be positive. The directory is exclusively
	25	+	// owned by one Proxy; opening it clears incomplete downloads from tmp/.
	26	+	type Config struct {
	27	+	Dir string
	28	+	Max int64
	29	+	Upstream string // default https://registry-1.docker.io
	30	+	AuthURL string // default https://auth.docker.io/token
	31	+	Log zerowrap.Logger
	32	+	// RequestTimeout bounds auth, manifests and HEAD (default 10s).
	33	+	RequestTimeout time.Duration
	34	+	// BlobIdleTimeout bounds time without upstream body progress (default 30s).
	35	+	// A blob body has no total timeout.
	36	+	BlobIdleTimeout time.Duration
	37	+	// KeepAliveInterval is how often a client waiting for a cold blob is kept
	38	+	// alive while the download progresses (default 1s), when its
	39	+	// ResponseWriter is a KeepAliver.
	40	+	KeepAliveInterval time.Duration
	41	+	// AbandonGrace is how long a download nobody waits for any more keeps
	42	+	// running in case another request joins it; then it is cancelled and its
	43	+	// temporary file removed (default 5s).
	44	+	AbandonGrace time.Duration
	45	+	// MaxDownloads caps the concurrent cold blob downloads across all jobs
	46	+	// (default 16). A request may also carry a per-client Quota (WithQuota).
	47	+	MaxDownloads int
	48	+	// SlotWait is how long a request that would start a download waits for a
	49	+	// free slot, global or of its quota, before it gets 503 (default 30s).
	50	+	SlotWait time.Duration
	51	+	}
	52	+
	53	+	// KeepAliver is a ResponseWriter that can move its connection's deadlines
	54	+	// without writing. While a request waits for a cold blob, the Proxy calls
	55	+	// KeepAlive every KeepAliveInterval as long as the download progresses, so
	56	+	// that a slow but moving download does not time the client out before the
	57	+	// first byte of the reply.
	58	+	type KeepAliver interface {
	59	+	KeepAlive()
	60	+	}
	61	+
	62	+	// Proxy implements http.Handler for GET and HEAD under /v2/.
	63	+	type Proxy struct {
	64	+	s *store
	65	+	u *upstream
	66	+	log zerowrap.Logger
	67	+	keepEvery time.Duration
	68	+	}
	69	+
	70	+	// New opens the persistent cache. It starts no goroutines or listeners.
	71	+	func New(c Config) (*Proxy, error) {
	72	+	if c.Upstream == "" {
	73	+	c.Upstream = "https://registry-1.docker.io"
	74	+	}
	75	+	if c.AuthURL == "" {
	76	+	c.AuthURL = "https://auth.docker.io/token"
	77	+	}
	78	+	for _, s := range []string{c.Upstream, c.AuthURL} {
	79	+	u, err := url.Parse(s)
	80	+	if err != nil \|\| u.Host == "" \|\| u.User != nil \|\| (u.Scheme != "http" && u.Scheme != "https") {
	81	+	return nil, errors.New("invalid registry upstream URL")
	82	+	}
	83	+	}
	84	+	if c.RequestTimeout <= 0 {
	85	+	c.RequestTimeout = 10 * time.Second
	86	+	}
	87	+	if c.BlobIdleTimeout <= 0 {
	88	+	c.BlobIdleTimeout = 30 * time.Second
	89	+	}
	90	+	if c.KeepAliveInterval <= 0 {
	91	+	c.KeepAliveInterval = time.Second
	92	+	}
	93	+	if c.AbandonGrace <= 0 {
	94	+	c.AbandonGrace = 5 * time.Second
	95	+	}
	96	+	if c.MaxDownloads <= 0 {
	97	+	c.MaxDownloads = 16
	98	+	}
	99	+	if c.SlotWait <= 0 {
	100	+	c.SlotWait = 30 * time.Second
	101	+	}
	102	+	st, err := openStore(storeConfig{dir: c.Dir, max: c.Max, now: time.Now, grace: c.AbandonGrace,
	103	+	maxDownloads: c.MaxDownloads, slotWait: c.SlotWait, log: c.Log})
	104	+	if err != nil {
	105	+	return nil, err
	106	+	}
	107	+	client, blobs := upstreamClients(c.RequestTimeout)
	108	+	return &Proxy{s: st, u: &upstream{base: strings.TrimRight(c.Upstream, "/"), auth: c.AuthURL, client: client, blobClient: blobs,
	109	+	requestTimeout: c.RequestTimeout, blobIdle: c.BlobIdleTimeout, tokens: map[string]bearer{}}, log: c.Log, keepEvery: c.KeepAliveInterval}, nil
	110	+	}
	111	+
	112	+	var namePattern = regexp.MustCompile(`^[a-z0-9]+(?:[._-][a-z0-9]+)(?:/[a-z0-9]+(?:[._-][a-z0-9]+))*$`)
	113	+	var tagPattern = regexp.MustCompile(`^[A-Za-z0-9_][A-Za-z0-9_.-]{0,127}$`)
	114	+
	115	+	func validDigest(s string) bool {
	116	+	if len(s) != 71 \|\| !strings.HasPrefix(s, "sha256:") {
	117	+	return false
	118	+	}
	119	+	_, err := hex.DecodeString(s[7:])
	120	+	return err == nil && s == strings.ToLower(s)
	121	+	}
	122	+
	123	+	func (p Proxy) ServeHTTP(w http.ResponseWriter, r http.Request) {
	124	+	if r.Method != http.MethodGet && r.Method != http.MethodHead {
	125	+	w.WriteHeader(http.StatusMethodNotAllowed)
	126	+	return
	127	+	}
	128	+	w.Header().Set("Docker-Distribution-Api-Version", "registry/2.0")
	129	+	if r.URL.Path == "/v2/" {
	130	+	w.Header().Set("Content-Type", "application/json")
	131	+	w.Header().Set("Content-Length", "2")
	132	+	if r.Method == http.MethodGet {
	133	+	_, _ = io.WriteString(w, "{}")
	134	+	}
	135	+	return
	136	+	}
	137	+	if !strings.HasPrefix(r.URL.Path, "/v2/") {
	138	+	http.NotFound(w, r)
	139	+	return
	140	+	}
	141	+	path := strings.TrimPrefix(r.URL.Path, "/v2/")
	142	+	i := strings.LastIndex(path, "/")
	143	+	if i < 0 {
	144	+	http.NotFound(w, r)
	145	+	return
	146	+	}
	147	+	ref := path[i+1:]
	148	+	path = path[:i]
	149	+	i = strings.LastIndex(path, "/")
	150	+	if i < 0 {
	151	+	http.NotFound(w, r)
	152	+	return
	153	+	}
	154	+	name, route := path[:i], path[i+1:]
	155	+	// dockerd's legacy client sends one Accept line per media type.
	156	+	accept := strings.Join(r.Header.Values("Accept"), ",")
	157	+	if len(name) > 255 \|\| !namePattern.MatchString(name) \|\| len(accept) > 8192 {
	158	+	http.NotFound(w, r)
	159	+	return
	160	+	}
	161	+	if route == kindManifest.dir() && (validDigest(ref) \|\| tagPattern.MatchString(ref)) {
	162	+	p.manifest(w, r, name, ref, normalizeAccept(accept))
	163	+	return
	164	+	}
	165	+	if route == kindBlob.dir() && validDigest(ref) {
	166	+	p.blob(w, r, name, ref)
	167	+	return
	168	+	}
	169	+	http.NotFound(w, r)
	170	+	}
	171	+
	172	+	// logFor is the Proxy's logger, with the job_id of the request (WithJob).
	173	+	func (p *Proxy) logFor(ctx context.Context) zerowrap.Logger {
	174	+	if job := jobFrom(ctx); job != "" {
	175	+	return zerowrap.Logger{Logger: p.log.With().Str("job_id", job).Logger()}
	176	+	}
	177	+	return p.log
	178	+	}
	179	+
	180	+	func serveFile(w http.ResponseWriter, r http.Request, f storedFile, media, digest string) {
	181	+	defer func() { _ = f.Close() }()
	182	+	fi, err := f.Stat()
	183	+	if err != nil {
	184	+	http.Error(w, "registry cache read failed", http.StatusBadGateway)
	185	+	return
	186	+	}
	187	+	w.Header().Set("Content-Type", media)
	188	+	w.Header().Set("Docker-Content-Digest", digest)
	189	+	http.ServeContent(w, r, "", fi.ModTime(), f)
	190	+	}
	191	+
	192	+	// serveStaleTag serves the manifest a tag pointed to when upstream could not
	193	+	// answer, if that manifest is still stored. It reports whether it served one.
	194	+	func (p Proxy) serveStaleTag(w http.ResponseWriter, r http.Request, name, tag, accept string) bool {
	195	+	digest := p.s.tag(name, tag, accept)
	196	+	if !validDigest(digest) {
	197	+	return false
	198	+	}
	199	+	f, media, err := p.s.open(kindManifest, digest)
	200	+	if err != nil {
	201	+	return false
	202	+	}
	203	+	serveFile(w, r, f, media, digest)
	204	+	return true
	205	+	}
	206	+
	207	+	// manifest serves a manifest by tag or digest. accept is normalized.
	208	+	func (p Proxy) manifest(w http.ResponseWriter, r http.Request, name, ref, accept string) {
	209	+	start := time.Now()
	210	+	hit := false
	211	+	log := p.logFor(r.Context())
	212	+	defer func() {
	213	+	log.Info().Str("repo", name).Str("ref", ref).Bool("hit", hit).Int64("ms", time.Since(start).Milliseconds()).Msg("registry manifest")
	214	+	}()
	215	+	ctx, cancel := context.WithTimeout(r.Context(), p.u.requestTimeout)
	216	+	defer cancel()
	217	+	digest := ref
	218	+	tag := !validDigest(ref)
	219	+	if tag {
	220	+	resp, err := p.u.request(ctx, http.MethodHead, name, kindManifest, ref, accept)
	221	+	if err != nil {
	222	+	if unavailable(err) && p.serveStaleTag(w, r, name, ref, accept) {
	223	+	hit = true
	224	+	return
	225	+	}
	226	+	http.Error(w, "registry upstream unavailable", proxyStatus(err))
	227	+	return
	228	+	}
	229	+	digest = resp.Header.Get("Docker-Content-Digest")
	230	+	_ = resp.Body.Close()
	231	+	if !validDigest(digest) {
	232	+	http.Error(w, "invalid upstream digest", http.StatusBadGateway)
	233	+	return
	234	+	}
	235	+	}
	236	+	// Shared flight, as for blobs: it must not end with the initiator's request.
	237	+	f, media, cached, err := p.s.ensure(ctx, kindManifest, digest, func(flightCtx context.Context, dst io.Writer) (string, error) {
	238	+	fillCtx, fillCancel := context.WithTimeout(flightCtx, p.u.requestTimeout)
	239	+	defer fillCancel()
	240	+	resp, err := p.u.request(fillCtx, http.MethodGet, name, kindManifest, digest, accept)
	241	+	if err != nil {
	242	+	return "", err
	243	+	}
	244	+	defer func() { _ = resp.Body.Close() }()
	245	+	b, err := io.ReadAll(io.LimitReader(resp.Body, manifestLimit+1))
	246	+	if err != nil {
	247	+	return "", err
	248	+	}
	249	+	if len(b) > manifestLimit {
	250	+	return "", errTooLarge
	251	+	}
	252	+	_, err = dst.Write(b)
	253	+	return resp.Header.Get("Content-Type"), err
	254	+	}, keepalive{})
	255	+	hit = cached
	256	+	if err != nil {
	257	+	if tag && unavailable(err) && p.serveStaleTag(w, r, name, ref, accept) {
	258	+	hit = true
	259	+	return
	260	+	}
	261	+	http.Error(w, "registry fetch failed", proxyStatus(err))
	262	+	return
	263	+	}
	264	+	if tag {
	265	+	_ = p.s.setTag(name, ref, accept, digest)
	266	+	}
	267	+	serveFile(w, r, f, media, digest)
	268	+	}
	269	+
	270	+	func (p Proxy) blob(w http.ResponseWriter, r http.Request, name, digest string) {
	271	+	if f, media, err := p.s.open(kindBlob, digest); err == nil {
	272	+	serveFile(w, r, f, media, digest)
	273	+	return
	274	+	}
	275	+	// A cold HEAD is metadata-only and retains the short total timeout.
	276	+	if r.Method == http.MethodHead {
	277	+	ctx, cancel := context.WithTimeout(r.Context(), p.u.requestTimeout)
	278	+	defer cancel()
	279	+	resp, err := p.u.request(ctx, http.MethodHead, name, kindBlob, digest, "")
	280	+	if err != nil {
	281	+	http.Error(w, "registry fetch failed", proxyStatus(err))
	282	+	return
	283	+	}
	284	+	defer func() { _ = resp.Body.Close() }()
	285	+	if resp.ContentLength < 0 {
	286	+	http.Error(w, "unknown blob length", http.StatusBadGateway)
	287	+	return
	288	+	}
	289	+	w.Header().Set("Content-Type", "application/octet-stream")
	290	+	w.Header().Set("Content-Length", strconv.FormatInt(resp.ContentLength, 10))
	291	+	w.Header().Set("Docker-Content-Digest", digest)
	292	+	return
	293	+	}
	294	+	// The flight is shared by every client that asks for this blob, so no client
	295	+	// may own it: it downloads on a context of its own, into the temporary file
	296	+	// only, and is bounded by Max and the upstream idle timeout. Every client,
	297	+	// the initiator included, waits for the verified commit and then reads the
	298	+	// stored file (simplest correct option: no client streams unverified bytes,
	299	+	// and a client that disconnects fails only itself). The flight is cancelled
	300	+	// when no client has waited for it for AbandonGrace. At most MaxDownloads
	301	+	// run at once, and at most its Quota per client: a request over either
	302	+	// waits up to SlotWait for a slot, then gets 503, which dockerd retries
	303	+	// (about 50 s) before pulling from Docker Hub. While it waits, a
	304	+	// KeepAliver writer (the cache channel's progress deadline) is kept alive
	305	+	// as long as the download moves.
	306	+	keep := keepalive{every: p.keepEvery}
	307	+	if k, ok := w.(KeepAliver); ok {
	308	+	keep.fn = k.KeepAlive
	309	+	}
	310	+	log := p.logFor(r.Context())
	311	+	f, media, _, err := p.s.ensure(r.Context(), kindBlob, digest, func(downloadCtx context.Context, dst io.Writer) (string, error) {
	312	+	start := time.Now()
	313	+	var size int64
	314	+	defer func() {
	315	+	log.Debug().Str("digest", digest).Int64("bytes", size).Int64("ms", time.Since(start).Milliseconds()).Msg("registry blob")
	316	+	}()
	317	+	resp, err := p.u.blob(downloadCtx, name, digest)
	318	+	if err != nil {
	319	+	return "", err
	320	+	}
	321	+	defer func() { _ = resp.Body.Close() }()
	322	+	if resp.ContentLength > p.s.max {
	323	+	return "", errTooLarge
	324	+	}
	325	+	size, err = io.Copy(dst, resp.Body)
	326	+	return "application/octet-stream", err
	327	+	}, keep)
	328	+	if errors.Is(err, errBusy) {
	329	+	w.Header().Set("Retry-After", "1")
	330	+	http.Error(w, "registry downloads busy", http.StatusServiceUnavailable)
	331	+	return
	332	+	}
	333	+	if err != nil {
	334	+	http.Error(w, "registry fetch failed", proxyStatus(err))
	335	+	return
	336	+	}
	337	+	serveFile(w, r, f, media, digest)
	338	+	}

A internal/registryproxy/proxy_test.go +117 -0

@@ -0,0 +1,117 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"fmt"
	7	+	"io"
	8	+	"net/http"
	9	+	"net/http/httptest"
	10	+	"os"
	11	+	"path/filepath"
	12	+	"strings"
	13	+	"testing"
	14	+	)
	15	+
	16	+	// A pulled manifest and blob are served from the store the second time: a tag
	17	+	// is revalidated by HEAD, a digest is not fetched again.
	18	+	func TestPullCached(t *testing.T) {
	19	+	f := fake(t)
	20	+	p := proxyFor(t, f)
	21	+	for range 2 {
	22	+	w := request(t, p, http.MethodGet, "/v2/library/alpine/manifests/3")
	23	+	if w.Code != http.StatusOK \|\| w.Body.String() != manifestBody {
	24	+	t.Fatalf("manifest: %d %s", w.Code, w.Body)
	25	+	}
	26	+	w = request(t, p, http.MethodGet, "/v2/library/alpine/blobs/"+sum(blobBody))
	27	+	if w.Code != http.StatusOK \|\| w.Body.String() != blobBody {
	28	+	t.Fatalf("blob: %d %s", w.Code, w.Body)
	29	+	}
	30	+	}
	31	+	if f.heads.Load() != 2 \|\| f.gets.Load() != 1 \|\| f.blobs.Load() != 1 \|\| f.tokens.Load() != 1 {
	32	+	t.Fatalf("counts HEAD=%d GET=%d blobs=%d tokens=%d", f.heads.Load(), f.gets.Load(), f.blobs.Load(), f.tokens.Load())
	33	+	}
	34	+	}
	35	+
	36	+	// HEAD of a blob answers its length, cold or stored, with no body; a stored
	37	+	// blob serves ranges.
	38	+	func TestBlobHeadAndRange(t *testing.T) {
	39	+	f := fake(t)
	40	+	p := proxyFor(t, f)
	41	+	path := "/v2/library/alpine/blobs/" + sum(blobBody)
	42	+	for _, cached := range []bool{false, true} {
	43	+	if cached {
	44	+	if w := request(t, p, http.MethodGet, path); w.Code != http.StatusOK {
	45	+	t.Fatal(w.Code)
	46	+	}
	47	+	}
	48	+	w := request(t, p, http.MethodHead, path)
	49	+	if w.Code != http.StatusOK \|\| w.Body.Len() != 0 \|\| w.Header().Get("Content-Length") != fmt.Sprint(len(blobBody)) {
	50	+	t.Fatalf("HEAD %d %v %q", w.Code, w.Header(), w.Body.String())
	51	+	}
	52	+	}
	53	+	w := request(t, p, http.MethodGet, path, "Range", "bytes=2-5")
	54	+	if w.Code != http.StatusPartialContent \|\| w.Body.String() != blobBody[2:6] {
	55	+	t.Fatalf("range: %d %s", w.Code, w.Body)
	56	+	}
	57	+	}
	58	+
	59	+	// A blob is verified before any byte of it is sent: a corrupt one is a 502
	60	+	// with no body, and is not stored.
	61	+	func TestCorruptBlobRejected(t *testing.T) {
	62	+	f := fake(t)
	63	+	f.corrupt.Store(true)
	64	+	p := proxyFor(t, f)
	65	+	w := request(t, p, http.MethodGet, "/v2/library/alpine/blobs/"+sum(blobBody))
	66	+	if w.Code != http.StatusBadGateway \|\| strings.Contains(w.Body.String(), "xxxx") {
	67	+	t.Fatalf("corrupt blob: %d %q", w.Code, w.Body)
	68	+	}
	69	+	if _, err := os.Stat(filepath.Join(p.s.dir, kindBlob.key(sum(blobBody)[7:]))); !os.IsNotExist(err) {
	70	+	t.Fatal("corrupt blob stored")
	71	+	}
	72	+	if ds, _ := os.ReadDir(filepath.Join(p.s.dir, "tmp")); len(ds) != 0 {
	73	+	t.Fatal("partial temp retained")
	74	+	}
	75	+	}
	76	+
	77	+	// Only GET and HEAD of valid names, tags and digests under /v2/ are served.
	78	+	func TestRouteValidation(t *testing.T) {
	79	+	p := proxyFor(t, fake(t))
	80	+	for _, path := range []string{"/v2/../library/alpine/manifests/3", "/v2/Library/alpine/manifests/3", "/v2/library/alpine/manifests/.bad", "/v2/library/alpine/manifests/sha256:bad", "/v2/library/alpine/blobs/sha256:bad", "/v2/library/alpine/tags/list", "/v3/library/alpine/manifests/3"} {
	81	+	if w := request(t, p, http.MethodGet, path); w.Code != http.StatusNotFound {
	82	+	t.Errorf("%s: %d", path, w.Code)
	83	+	}
	84	+	}
	85	+	if w := request(t, p, http.MethodPut, "/v2/"); w.Code != http.StatusMethodNotAllowed {
	86	+	t.Fatal(w.Code)
	87	+	}
	88	+	if w := request(t, p, http.MethodGet, "/v2/"); w.Code != http.StatusOK \|\| w.Body.String() != "{}" {
	89	+	t.Fatalf("/v2/: %d %s", w.Code, w.Body)
	90	+	}
	91	+	}
	92	+
	93	+	// A manifest whose bytes do not match its digest, or over the size limit, is
	94	+	// a 502 and is not stored.
	95	+	func TestManifestLimitsAndDigest(t *testing.T) {
	96	+	for _, body := range []string{"tampered", strings.Repeat("x", manifestLimit+1)} {
	97	+	up := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	98	+	if r.URL.Path == "/token" {
	99	+	_, _ = io.WriteString(w, `{"token":"public"}`)
	100	+	return
	101	+	}
	102	+	_, _ = io.WriteString(w, body)
	103	+	}))
	104	+	p, err := New(Config{Dir: t.TempDir(), Max: 8 << 20, Upstream: up.URL, AuthURL: up.URL + "/token"})
	105	+	if err != nil {
	106	+	t.Fatal(err)
	107	+	}
	108	+	w := request(t, p, http.MethodGet, "/v2/library/alpine/manifests/"+sum(manifestBody))
	109	+	up.Close()
	110	+	if w.Code != http.StatusBadGateway {
	111	+	t.Fatal(w.Code)
	112	+	}
	113	+	if _, _, err := p.s.open(kindManifest, sum(manifestBody)); err == nil {
	114	+	t.Fatal("invalid manifest stored")
	115	+	}
	116	+	}
	117	+	}

A internal/registryproxy/quota.go +61 -0

@@ -0,0 +1,61 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"context"
	7	+	"sync/atomic"
	8	+	)
	9	+
	10	+	// Quota bounds the cold blob downloads started on behalf of one client, such as
	11	+	// the channel of one sandbox, so that no client can take every download slot of
	12	+	// the Proxy. A download counts against the quota of the request that started it
	13	+	// until it really ends, even when only other clients still wait for it;
	14	+	// requests that join a download in progress take none.
	15	+	type Quota struct {
	16	+	max int64
	17	+	used atomic.Int64
	18	+	}
	19	+
	20	+	// NewQuota returns a quota of n concurrent downloads; n must be positive.
	21	+	func NewQuota(n int) *Quota { return &Quota{max: int64(max(n, 1))} }
	22	+
	23	+	// WithQuota attaches q to the context of a request to the Proxy. A request
	24	+	// without a quota is bound by the Proxy's global cap only.
	25	+	func WithQuota(ctx context.Context, q *Quota) context.Context {
	26	+	return context.WithValue(ctx, quotaKey{}, q)
	27	+	}
	28	+
	29	+	type quotaKey struct{}
	30	+
	31	+	func quotaFrom(ctx context.Context) *Quota {
	32	+	q, _ := ctx.Value(quotaKey{}).(*Quota)
	33	+	return q
	34	+	}
	35	+
	36	+	// WithJob attaches the id of the job a request serves to its context: the
	37	+	// Proxy logs it as job_id on its registry lines.
	38	+	func WithJob(ctx context.Context, job string) context.Context {
	39	+	return context.WithValue(ctx, jobKey{}, job)
	40	+	}
	41	+
	42	+	type jobKey struct{}
	43	+
	44	+	func jobFrom(ctx context.Context) string {
	45	+	job, _ := ctx.Value(jobKey{}).(string)
	46	+	return job
	47	+	}
	48	+
	49	+	func (q *Quota) tryAcquire() bool {
	50	+	for {
	51	+	n := q.used.Load()
	52	+	if n >= q.max {
	53	+	return false
	54	+	}
	55	+	if q.used.CompareAndSwap(n, n+1) {
	56	+	return true
	57	+	}
	58	+	}
	59	+	}
	60	+
	61	+	func (q *Quota) release() { q.used.Add(-1) }

A internal/registryproxy/slots_test.go +215 -0

@@ -0,0 +1,215 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"context"
	7	+	"io"
	8	+	"net/http"
	9	+	"net/http/httptest"
	10	+	"strings"
	11	+	"sync"
	12	+	"testing"
	13	+	"time"
	14	+	)
	15	+
	16	+	// At most MaxDownloads cold blobs download at once; one more waits for
	17	+	// SlotWait and then gets 503 (dockerd retries or pulls from Docker Hub), a
	18	+	// joiner of a running download takes no slot, and a slot frees once a
	19	+	// download ends.
	20	+	func TestColdDownloadCap(t *testing.T) {
	21	+	u := newStallingUpstream(t)
	22	+	const limit = 3
	23	+	const wait = 50 * time.Millisecond
	24	+	p := proxyWith(t, u.srv, Config{AbandonGrace: 10 * time.Millisecond, MaxDownloads: limit, SlotWait: wait})
	25	+	ctx, cancel := context.WithCancel(context.Background())
	26	+	var wg sync.WaitGroup
	27	+	for i := range limit {
	28	+	wg.Go(func() {
	29	+	p.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, blobPath(i), nil).WithContext(ctx))
	30	+	})
	31	+	}
	32	+	waitFor(t, p.s, "the cap to fill", func() bool { return p.s.downloads == limit })
	33	+	start := time.Now()
	34	+	w := request(t, p, http.MethodGet, blobPath(limit))
	35	+	if w.Code != http.StatusServiceUnavailable \|\| w.Header().Get("Retry-After") == "" {
	36	+	t.Fatalf("over the cap: %d", w.Code)
	37	+	}
	38	+	if d := time.Since(start); d < wait {
	39	+	t.Fatalf("503 after %v, before the slot wait", d)
	40	+	}
	41	+	// Joining a running download takes no slot: the joiner is a waiter of the
	42	+	// flight, and the number of downloads does not move.
	43	+	key := kindBlob.key(sum("blob-0")[7:])
	44	+	go p.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, blobPath(0), nil).WithContext(ctx))
	45	+	waitFor(t, p.s, "the joiner", func() bool { return waiters(p.s, key) == 2 })
	46	+	p.s.mu.Lock()
	47	+	downloads := p.s.downloads
	48	+	p.s.mu.Unlock()
	49	+	if downloads != limit {
	50	+	t.Fatalf("%d downloads with a joiner, want %d", downloads, limit)
	51	+	}
	52	+	cancel()
	53	+	wg.Wait()
	54	+	waitFor(t, p.s, "the slots to free", func() bool { return p.s.downloads == 0 })
	55	+	if u.started.Load() != limit {
	56	+	t.Fatalf("%d downloads started", u.started.Load())
	57	+	}
	58	+	}
	59	+
	60	+	// A sandbox that saturates its quota does not hold back another sandbox: its
	61	+	// download starts at once while the global cap still has room.
	62	+	func TestQuotaIsolatesChannels(t *testing.T) {
	63	+	u := newStallingUpstream(t)
	64	+	p := proxyWith(t, u.srv, Config{SlotWait: time.Hour, AbandonGrace: 10 * time.Millisecond})
	65	+	a, b := NewQuota(3), NewQuota(3)
	66	+	ctxA, cancelA := context.WithCancel(WithQuota(context.Background(), a))
	67	+	defer cancelA()
	68	+	for i := range 3 {
	69	+	serveAsync(p, ctxA, blobPath(i), nil)
	70	+	}
	71	+	waitFor(t, p.s, "A's quota to fill", func() bool { return a.used.Load() == 3 })
	72	+	// A's fourth waits for its own quota and starts nothing.
	73	+	serveAsync(p, ctxA, blobPath(3), nil)
	74	+	ctxB, cancelB := context.WithCancel(WithQuota(context.Background(), b))
	75	+	defer cancelB()
	76	+	start := time.Now()
	77	+	serveAsync(p, ctxB, blobPath(10), nil)
	78	+	waitFor(t, p.s, "B's download to start", func() bool { return b.used.Load() == 1 })
	79	+	if d := time.Since(start); d > time.Second {
	80	+	t.Fatalf("B started after %v", d)
	81	+	}
	82	+	// The quotas are taken before the downloads reach upstream: wait for the
	83	+	// 4 of A and B there, then check under the store lock that A's fourth
	84	+	// took no slot.
	85	+	waitFor(t, p.s, "4 downloads upstream", func() bool { return u.started.Load() == 4 })
	86	+	p.s.mu.Lock()
	87	+	downloads := p.s.downloads
	88	+	p.s.mu.Unlock()
	89	+	if downloads != 4 {
	90	+	t.Fatalf("%d downloads, want A's 3 and B's 1", downloads)
	91	+	}
	92	+	cancelA()
	93	+	cancelB()
	94	+	waitFor(t, p.s, "every slot to free", func() bool { return p.s.downloads == 0 })
	95	+	if a.used.Load() != 0 \|\| b.used.Load() != 0 {
	96	+	t.Fatalf("quota not released: %d %d", a.used.Load(), b.used.Load())
	97	+	}
	98	+	}
	99	+
	100	+	// A request over its quota waits, kept alive, and starts its download as soon
	101	+	// as one of its channel's ends, with no 503.
	102	+	func TestQuotaWaiterGetsFreedSlot(t *testing.T) {
	103	+	body := strings.Repeat("layer", 100)
	104	+	release := make(chan struct{})
	105	+	var once sync.Once
	106	+	unblock := func() { once.Do(func() { close(release) }) }
	107	+	t.Cleanup(unblock)
	108	+	srv := upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	109	+	if strings.HasSuffix(r.URL.Path, sum(body)) {
	110	+	_, _ = io.WriteString(w, body)
	111	+	return
	112	+	}
	113	+	w.Header().Set("Content-Length", "1000")
	114	+	_, _ = io.WriteString(w, "x")
	115	+	w.(http.Flusher).Flush()
	116	+	select {
	117	+	case <-release:
	118	+	case <-r.Context().Done():
	119	+	}
	120	+	})
	121	+	p := proxyWith(t, srv, Config{SlotWait: time.Hour, KeepAliveInterval: 5 * time.Millisecond})
	122	+	q := NewQuota(1)
	123	+	ctx := WithQuota(context.Background(), q)
	124	+	first := serveAsync(p, ctx, blobPath(0), nil)
	125	+	waitFor(t, p.s, "the quota to fill", func() bool { return q.used.Load() == 1 })
	126	+	w := &keepAliveRecorder{ResponseRecorder: httptest.NewRecorder()}
	127	+	second := serveAsync(p, ctx, "/v2/library/alpine/blobs/"+sum(body), w)
	128	+	waitKeptAlive(t, w) // waiting for a slot
	129	+	select {
	130	+	case code := <-second:
	131	+	t.Fatalf("did not wait for a slot: %d", code)
	132	+	default:
	133	+	}
	134	+	unblock() // the first download ends (digest mismatch), freeing the slot
	135	+	if code := <-first; code != http.StatusBadGateway {
	136	+	t.Fatalf("first: %d", code)
	137	+	}
	138	+	if code := <-second; code != http.StatusOK \|\| w.Body.String() != body {
	139	+	t.Fatalf("second: %d", code)
	140	+	}
	141	+	}
	142	+
	143	+	// After SlotWait without a slot, the request gets 503.
	144	+	func TestQuotaWaitTimesOut(t *testing.T) {
	145	+	u := newStallingUpstream(t)
	146	+	const wait = 50 * time.Millisecond
	147	+	p := proxyWith(t, u.srv, Config{SlotWait: wait, AbandonGrace: 10 * time.Millisecond})
	148	+	q := NewQuota(1)
	149	+	ctx, cancel := context.WithCancel(WithQuota(context.Background(), q))
	150	+	defer cancel()
	151	+	serveAsync(p, ctx, blobPath(0), nil)
	152	+	waitFor(t, p.s, "the quota to fill", func() bool { return q.used.Load() == 1 })
	153	+	start := time.Now()
	154	+	code := <-serveAsync(p, ctx, blobPath(1), nil)
	155	+	if code != http.StatusServiceUnavailable {
	156	+	t.Fatalf("over the quota: %d", code)
	157	+	}
	158	+	if d := time.Since(start); d < wait {
	159	+	t.Fatalf("503 after %v", d)
	160	+	}
	161	+	if u.started.Load() != 1 {
	162	+	t.Fatalf("%d downloads started", u.started.Load())
	163	+	}
	164	+	}
	165	+
	166	+	// A request that disconnects while it waits for a slot leaves at once, with no
	167	+	// slot and no 503.
	168	+	func TestQuotaWaiterDisconnects(t *testing.T) {
	169	+	u := newStallingUpstream(t)
	170	+	const wait = time.Hour
	171	+	p := proxyWith(t, u.srv, Config{SlotWait: wait, AbandonGrace: 10 * time.Millisecond, KeepAliveInterval: 5 * time.Millisecond})
	172	+	q := NewQuota(1)
	173	+	ctx, cancel := context.WithCancel(WithQuota(context.Background(), q))
	174	+	defer cancel()
	175	+	serveAsync(p, ctx, blobPath(0), nil)
	176	+	waitFor(t, p.s, "the quota to fill", func() bool { return q.used.Load() == 1 })
	177	+	wctx, wcancel := context.WithCancel(WithQuota(context.Background(), q))
	178	+	w := &keepAliveRecorder{ResponseRecorder: httptest.NewRecorder()}
	179	+	waiting := serveAsync(p, wctx, blobPath(1), w)
	180	+	waitKeptAlive(t, w) // really waiting for a slot
	181	+	start := time.Now()
	182	+	wcancel()
	183	+	code := <-waiting
	184	+	if d := time.Since(start); d > time.Second {
	185	+	t.Fatalf("left after %v", d)
	186	+	}
	187	+	if code == http.StatusServiceUnavailable {
	188	+	t.Fatal("a disconnected waiter got 503")
	189	+	}
	190	+	if u.started.Load() != 1 \|\| q.used.Load() != 1 {
	191	+	t.Fatalf("%d downloads started, quota %d", u.started.Load(), q.used.Load())
	192	+	}
	193	+	}
	194	+
	195	+	// Joining a download in progress takes none of the joiner's quota.
	196	+	func TestQuotaJoinersExempt(t *testing.T) {
	197	+	u := newStallingUpstream(t)
	198	+	p := proxyWith(t, u.srv, Config{SlotWait: 20 * time.Millisecond, AbandonGrace: 10 * time.Millisecond})
	199	+	a, b := NewQuota(1), NewQuota(1)
	200	+	ctxA, cancelA := context.WithCancel(WithQuota(context.Background(), a))
	201	+	defer cancelA()
	202	+	serveAsync(p, ctxA, blobPath(0), nil)
	203	+	waitFor(t, p.s, "A's download", func() bool { return a.used.Load() == 1 })
	204	+	ctxB, cancelB := context.WithCancel(WithQuota(context.Background(), b))
	205	+	defer cancelB()
	206	+	serveAsync(p, ctxB, blobPath(0), nil) // joins A's
	207	+	key := kindBlob.key(sum("blob-0")[7:])
	208	+	waitFor(t, p.s, "B to join", func() bool { return waiters(p.s, key) == 2 })
	209	+	if b.used.Load() != 0 {
	210	+	t.Fatal("a joiner took quota")
	211	+	}
	212	+	// B's quota is still free for a download of its own.
	213	+	serveAsync(p, ctxB, blobPath(1), nil)
	214	+	waitFor(t, p.s, "B's own download", func() bool { return b.used.Load() == 1 })
	215	+	}

A internal/registryproxy/store.go +784 -0

@@ -0,0 +1,784 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"container/list"
	7	+	"context"
	8	+	"crypto/sha256"
	9	+	"encoding/hex"
	10	+	"errors"
	11	+	"fmt"
	12	+	"io"
	13	+	"os"
	14	+	"path/filepath"
	15	+	"sort"
	16	+	"strings"
	17	+	"sync"
	18	+	"sync/atomic"
	19	+	"time"
	20	+
	21	+	"github.com/bnema/zerowrap"
	22	+	)
	23	+
	24	+	var errTooLarge = errors.New("registry cache capacity exceeded")
	25	+	var errDigest = errors.New("registry digest mismatch")
	26	+
	27	+	// errBusy: no download slot came free within the slot wait. The proxy answers
	28	+	// 503, and dockerd retries the layer (about 50 s) before pulling from Docker Hub.
	29	+	var errBusy = errors.New("registry downloads busy")
	30	+
	31	+	// minCharge is the least an entry is charged, whatever its size: about one
	32	+	// disk block and inode. It bounds the number of entries, and so of files, to
	33	+	// Max/minCharge. A tag file is charged exactly that.
	34	+	const minCharge int64 = 4096
	35	+
	36	+	// charge is what an entry of n bytes counts against Max.
	37	+	func charge(n int64) int64 { return max(n, minCharge) }
	38	+
	39	+	// kind is the directory of an entry: content (blobs, manifests) or a tag.
	40	+	type kind uint8
	41	+
	42	+	const (
	43	+	kindBlob kind = iota
	44	+	kindManifest
	45	+	kindTag
	46	+	)
	47	+
	48	+	var kinds = []kind{kindBlob, kindManifest, kindTag}
	49	+
	50	+	// dir is the directory of the kind in the store, and its route in /v2/.
	51	+	func (k kind) dir() string {
	52	+	switch k {
	53	+	case kindBlob:
	54	+	return "blobs"
	55	+	case kindManifest:
	56	+	return "manifests"
	57	+	default:
	58	+	return "tags"
	59	+	}
	60	+	}
	61	+
	62	+	// key is the key of an entry of kind k: its path in the store.
	63	+	func (k kind) key(name string) string { return k.dir() + "/" + name }
	64	+
	65	+	// lowWater bounds the extra room an eviction frees (with 5% of Max), so that a
	66	+	// full store evicts once per that many bytes, not on every write.
	67	+	const lowWater int64 = 64 << 20
	68	+
	69	+	type entry struct {
	70	+	key string
	71	+	kind kind
	72	+	size int64
	73	+	used time.Time
	74	+	pins int
	75	+	digest string // tag target, empty for content
	76	+	elem *list.Element // in store.lru; nil once removed
	77	+	}
	78	+
	79	+	// flight is one download, shared by every request for its digest. Its fields
	80	+	// below written are guarded by store.mu.
	81	+	type flight struct {
	82	+	key string
	83	+	done chan struct{}
	84	+	err error
	85	+	written atomic.Int64 // bytes received so far, for the waiters' keepalive
	86	+
	87	+	waiters int
	88	+	gen int // bumped each time waiters drops to zero
	89	+	finished bool
	90	+	pinned bool // the committed entry holds a pin for the waiters
	91	+	kind kind // a blob flight takes a download slot
	92	+	quota *Quota // the starter's quota, held until the flight ends
	93	+	cancel context.CancelFunc
	94	+	}
	95	+
	96	+	// storeConfig is a store's complete configuration: openStore applies no
	97	+	// defaults.
	98	+	type storeConfig struct {
	99	+	dir string
	100	+	max int64
	101	+	now func() time.Time
	102	+	// grace is how long a blob flight with no waiter left keeps downloading in
	103	+	// case another request joins it; then it is cancelled.
	104	+	grace time.Duration
	105	+	// maxDownloads caps the concurrent blob downloads.
	106	+	maxDownloads int
	107	+	// slotWait is how long a request waits for a download slot before errBusy.
	108	+	slotWait time.Duration
	109	+	log zerowrap.Logger
	110	+	}
	111	+
	112	+	type store struct {
	113	+	storeConfig
	114	+
	115	+	mu sync.Mutex
	116	+	total, pending int64
	117	+	downloads int
	118	+	// slotFreed is closed and replaced each time a download slot frees.
	119	+	slotFreed chan struct{}
	120	+
	121	+	entries map[string]*entry
	122	+	lru list.List // entry, least recently used first
	123	+	tagsOf map[string]map[string]struct{} // manifest digest -> tag keys
	124	+	flights map[string]*flight
	125	+
	126	+	hookCommitted func(key string) // tests: after a commit, before waking waiters
	127	+	hookBug func(msg string) // tests: called on an accounting bug
	128	+	}
	129	+
	130	+	// defaultBugHook is each new store's hookBug. Tests set it in TestMain, before
	131	+	// any store exists, so that an accounting bug fails the run.
	132	+	var defaultBugHook func(msg string)
	133	+
	134	+	// storedFile pins its entry until the descriptor is closed. In particular, an
	135	+	// unlinked-but-open blob cannot silently escape the disk accounting.
	136	+	type storedFile struct {
	137	+	*os.File
	138	+	s *store
	139	+	key string
	140	+	once sync.Once
	141	+	err error
	142	+	}
	143	+
	144	+	func (f *storedFile) Close() error {
	145	+	f.once.Do(func() {
	146	+	f.err = f.File.Close()
	147	+	f.s.mu.Lock()
	148	+	defer f.s.mu.Unlock()
	149	+	f.s.unpinLocked(f.key)
	150	+	})
	151	+	return f.err
	152	+	}
	153	+
	154	+	func openStore(c storeConfig) (*store, error) {
	155	+	if c.max < minCharge {
	156	+	return nil, fmt.Errorf("registry cache cap must be at least %d bytes", minCharge)
	157	+	}
	158	+	if c.now == nil \|\| c.grace <= 0 \|\| c.maxDownloads <= 0 \|\| c.slotWait <= 0 {
	159	+	return nil, errors.New("registry store configuration incomplete")
	160	+	}
	161	+	dir := c.dir
	162	+	s := &store{storeConfig: c, entries: map[string]entry{}, lru: list.New(), tagsOf: map[string]map[string]struct{}{}, flights: map[string]flight{}, slotFreed: make(chan struct{}), hookBug: defaultBugHook}
	163	+	for _, sub := range []string{kindBlob.dir(), kindManifest.dir(), kindTag.dir(), "tmp"} {
	164	+	if err := os.MkdirAll(filepath.Join(dir, sub), 0700); err != nil {
	165	+	return nil, err
	166	+	}
	167	+	}
	168	+	temps, err := os.ReadDir(filepath.Join(dir, "tmp"))
	169	+	if err != nil {
	170	+	return nil, err
	171	+	}
	172	+	for _, de := range temps {
	173	+	if err := os.Remove(filepath.Join(dir, "tmp", de.Name())); err != nil {
	174	+	return nil, err
	175	+	}
	176	+	}
	177	+	var types []string
	178	+	for _, k := range kinds {
	179	+	ds, err := os.ReadDir(filepath.Join(dir, k.dir()))
	180	+	if err != nil {
	181	+	return nil, err
	182	+	}
	183	+	for _, de := range ds {
	184	+	if base, ok := strings.CutSuffix(de.Name(), ".type"); ok && k == kindManifest {
	185	+	types = append(types, base)
	186	+	continue
	187	+	}
	188	+	if !validDigest("sha256:" + de.Name()) {
	189	+	continue
	190	+	}
	191	+	fi, err := de.Info()
	192	+	if err != nil {
	193	+	return nil, err
	194	+	}
	195	+	if !fi.Mode().IsRegular() {
	196	+	continue
	197	+	}
	198	+	key := k.key(de.Name())
	199	+	size := fi.Size()
	200	+	e := &entry{key: key, kind: k, used: fi.ModTime()}
	201	+	switch k {
	202	+	case kindManifest:
	203	+	info, err := os.Stat(filepath.Join(dir, key) + ".type")
	204	+	if err != nil {
	205	+	_ = os.Remove(filepath.Join(dir, key))
	206	+	continue
	207	+	}
	208	+	size += info.Size()
	209	+	case kindTag:
	210	+	digest := s.readTagFile(key)
	211	+	if !validDigest(digest) {
	212	+	_ = os.Remove(filepath.Join(dir, key))
	213	+	continue
	214	+	}
	215	+	if _, ok := s.entries[kindManifest.key(digest[7:])]; !ok {
	216	+	_ = os.Remove(filepath.Join(dir, key))
	217	+	continue
	218	+	}
	219	+	size = 0
	220	+	e.digest = digest
	221	+	}
	222	+	e.size = charge(size)
	223	+	s.addLocked(e)
	224	+	}
	225	+	}
	226	+	// A .type whose manifest is gone (a crash between the two writes).
	227	+	for _, base := range types {
	228	+	if _, ok := s.entries[kindManifest.key(base)]; !ok {
	229	+	_ = os.Remove(filepath.Join(dir, kindManifest.key(base)+".type"))
	230	+	}
	231	+	}
	232	+	// Order the LRU by the access times kept in the mtimes.
	233	+	all := make([]*entry, 0, len(s.entries))
	234	+	for _, e := range s.entries {
	235	+	all = append(all, e)
	236	+	}
	237	+	sort.Slice(all, func(i, j int) bool { return all[i].used.Before(all[j].used) })
	238	+	s.lru.Init()
	239	+	for _, e := range all {
	240	+	e.elem = s.lru.PushBack(e)
	241	+	}
	242	+	s.evictLocked(0)
	243	+	return s, nil
	244	+	}
	245	+
	246	+	func (s store) addLocked(e entry) {
	247	+	s.entries[e.key] = e
	248	+	e.elem = s.lru.PushBack(e)
	249	+	s.total += e.size
	250	+	if e.digest != "" {
	251	+	s.indexTagLocked(e.key, e.digest)
	252	+	}
	253	+	}
	254	+
	255	+	func (s *store) indexTagLocked(key, digest string) {
	256	+	set := s.tagsOf[digest]
	257	+	if set == nil {
	258	+	set = map[string]struct{}{}
	259	+	s.tagsOf[digest] = set
	260	+	}
	261	+	set[key] = struct{}{}
	262	+	}
	263	+
	264	+	func (s *store) unindexTagLocked(key, digest string) {
	265	+	if set := s.tagsOf[digest]; set != nil {
	266	+	delete(set, key)
	267	+	if len(set) == 0 {
	268	+	delete(s.tagsOf, digest)
	269	+	}
	270	+	}
	271	+	}
	272	+
	273	+	func (s store) touchLocked(e entry) {
	274	+	e.used = s.now()
	275	+	s.lru.MoveToBack(e.elem)
	276	+	_ = os.Chtimes(filepath.Join(s.dir, e.key), e.used, e.used)
	277	+	}
	278	+
	279	+	func (s *store) unpinLocked(key string) {
	280	+	e, ok := s.entries[key]
	281	+	if !ok {
	282	+	return
	283	+	}
	284	+	if e.pins <= 0 {
	285	+	// A bug: the entry could have been evicted while open.
	286	+	s.log.Error().Str("key", key).Msg("registry cache unpin of an unpinned entry")
	287	+	if s.hookBug != nil {
	288	+	s.hookBug("unpin of an unpinned entry " + key)
	289	+	}
	290	+	return
	291	+	}
	292	+	e.pins--
	293	+	}
	294	+
	295	+	// removeLocked only releases a charge after the corresponding file is gone.
	296	+	// Failures leave the entry charged so a full or unwritable disk fails closed.
	297	+	func (s *store) removeLocked(key string) bool {
	298	+	e, ok := s.entries[key]
	299	+	if !ok {
	300	+	return true
	301	+	}
	302	+	if e.pins > 0 {
	303	+	return false
	304	+	}
	305	+	if e.kind == kindManifest {
	306	+	// Prune references first. If a tag cannot be removed, retain its target too.
	307	+	for k := range s.tagsOf["sha256:"+strings.TrimPrefix(key, kindManifest.key(""))] {
	308	+	if !s.removeLocked(k) {
	309	+	return false
	310	+	}
	311	+	}
	312	+	if err := os.Remove(filepath.Join(s.dir, key) + ".type"); err != nil && !os.IsNotExist(err) {
	313	+	return false
	314	+	}
	315	+	}
	316	+	if err := os.Remove(filepath.Join(s.dir, key)); err != nil && !os.IsNotExist(err) {
	317	+	return false
	318	+	}
	319	+	s.total -= e.size
	320	+	delete(s.entries, key)
	321	+	s.lru.Remove(e.elem)
	322	+	e.elem = nil
	323	+	if e.digest != "" {
	324	+	s.unindexTagLocked(key, e.digest)
	325	+	}
	326	+	return true
	327	+	}
	328	+
	329	+	// evictLocked makes room for need bytes. Once over the cap, it walks the LRU
	330	+	// (no sort) and evicts unpinned entries until max(need, low water) bytes are
	331	+	// free, so a full store evicts once per low-water bytes, not on every write.
	332	+	func (s *store) evictLocked(need int64) {
	333	+	if s.total+s.pending+need <= s.max {
	334	+	return
	335	+	}
	336	+	target := s.max - max(need, min(lowWater, s.max/20))
	337	+	for el := s.lru.Front(); el != nil && s.total+s.pending > target; {
	338	+	e := el.Value.(*entry)
	339	+	next := el.Next()
	340	+	if e.pins == 0 {
	341	+	removed := s.removeLocked(e.key)
	342	+	if e.kind == kindManifest {
	343	+	// Removing a manifest removes its tags first, even when it then
	344	+	// fails: next may be gone. Start over; only pinned or
	345	+	// unremovable entries are walked again.
	346	+	next = s.lru.Front()
	347	+	if !removed {
	348	+	// Do not walk into it again: it stays where it is, and
	349	+	// the walk resumes after it.
	350	+	next = e.elem.Next()
	351	+	}
	352	+	}
	353	+	}
	354	+	el = next
	355	+	}
	356	+	}
	357	+
	358	+	func (s store) openLocked(key string) (storedFile, string, error) {
	359	+	e, ok := s.entries[key]
	360	+	if !ok {
	361	+	return nil, "", os.ErrNotExist
	362	+	}
	363	+	f, err := os.Open(filepath.Join(s.dir, key))
	364	+	if err != nil {
	365	+	return nil, "", err
	366	+	}
	367	+	media := "application/octet-stream"
	368	+	if e.kind == kindManifest {
	369	+	b, err := os.ReadFile(filepath.Join(s.dir, key) + ".type")
	370	+	if err != nil {
	371	+	_ = f.Close()
	372	+	return nil, "", err
	373	+	}
	374	+	media = string(b)
	375	+	}
	376	+	s.touchLocked(e)
	377	+	e.pins++
	378	+	return &storedFile{File: f, s: s, key: key}, media, nil
	379	+	}
	380	+	func (s store) open(k kind, digest string) (storedFile, string, error) {
	381	+	if !validDigest(digest) {
	382	+	return nil, "", errDigest
	383	+	}
	384	+	s.mu.Lock()
	385	+	defer s.mu.Unlock()
	386	+	return s.openLocked(k.key(digest[7:]))
	387	+	}
	388	+
	389	+	// fetch writes the upstream content to w. ctx belongs to the flight: it ends
	390	+	// when the last waiter has been gone for the grace period.
	391	+	type fetch func(ctx context.Context, w io.Writer) (string, error)
	392	+
	393	+	type keepalive struct {
	394	+	every time.Duration
	395	+	fn func()
	396	+	}
	397	+
	398	+	// ensure returns the stored content, pinned for the caller; hit reports that it
	399	+	// was already stored. Otherwise the request joins or starts the flight of that
	400	+	// digest. The flight runs on its own goroutine and context, so no single
	401	+	// request, the initiator included, can cancel it while another one waits; it is
	402	+	// cancelled once no request has waited for it for the grace period. Every
	403	+	// waiter waits for the verified commit and then reads the stored file. While
	404	+	// waiting, keep.fn is called every keep.every when the download has made
	405	+	// progress, so that the waiter's connection deadlines can follow it.
	406	+	//
	407	+	// Starting a blob flight takes a global download slot and one of the quota
	408	+	// carried by ctx (WithQuota), both held until the flight really ends; joining
	409	+	// one takes neither. When a slot is missing, the request waits for one, kept
	410	+	// alive, for at most the slot wait, and then fails with errBusy.
	411	+	func (s store) ensure(ctx context.Context, k kind, digest string, fetch fetch, keep keepalive) (f storedFile, media string, hit bool, err error) {
	412	+	if !validDigest(digest) {
	413	+	return nil, "", false, errDigest
	414	+	}
	415	+	key := k.key(digest[7:])
	416	+	blob := k == kindBlob
	417	+	quota := quotaFrom(ctx)
	418	+	var slotDeadline <-chan time.Time
	419	+	var fl *flight
	420	+	for {
	421	+	s.mu.Lock()
	422	+	if f, media, err := s.openLocked(key); err == nil {
	423	+	s.mu.Unlock()
	424	+	return f, media, true, nil
	425	+	}
	426	+	var ok bool
	427	+	if fl, ok = s.flights[key]; ok {
	428	+	break // join: no slot needed
	429	+	}
	430	+	if !blob \|\| s.takeSlotLocked(quota) {
	431	+	dctx, cancel := context.WithCancel(context.Background())
	432	+	fl = &flight{key: key, kind: k, done: make(chan struct{}), cancel: cancel}
	433	+	if blob {
	434	+	fl.quota = quota
	435	+	}
	436	+	s.flights[key] = fl
	437	+	go s.run(dctx, fl, digest, fetch)
	438	+	break
	439	+	}
	440	+	freed := s.slotFreed
	441	+	s.mu.Unlock()
	442	+	if slotDeadline == nil {
	443	+	t := time.NewTimer(s.slotWait)
	444	+	defer t.Stop()
	445	+	slotDeadline = t.C
	446	+	}
	447	+	if err := waitSlot(ctx, freed, slotDeadline, keep); err != nil {
	448	+	return nil, "", false, err
	449	+	}
	450	+	}
	451	+	fl.waiters++
	452	+	s.mu.Unlock()
	453	+
	454	+	err = waitFlight(ctx, fl, keep)
	455	+	s.mu.Lock()
	456	+	defer s.mu.Unlock()
	457	+	if err == nil {
	458	+	f, media, err = s.openLocked(key)
	459	+	}
	460	+	s.leaveLocked(fl)
	461	+	return f, media, false, err
	462	+	}
	463	+
	464	+	// leaveLocked drops a waiter. The last one releases the commit pin, or, before
	465	+	// the commit, starts the grace period after which the flight is cancelled.
	466	+	func (s store) leaveLocked(fl flight) {
	467	+	fl.waiters--
	468	+	if fl.waiters > 0 {
	469	+	return
	470	+	}
	471	+	if fl.finished {
	472	+	if fl.pinned {
	473	+	fl.pinned = false
	474	+	s.unpinLocked(fl.key)
	475	+	}
	476	+	return
	477	+	}
	478	+	fl.gen++
	479	+	gen := fl.gen
	480	+	// A manifest is small and bounded by the request timeout: it is cancelled at
	481	+	// once, so its flights never outnumber the requests in progress. A blob
	482	+	// holds a download slot until it really ends, which bounds the abandoned
	483	+	// ones to MaxDownloads.
	484	+	if fl.kind != kindBlob {
	485	+	s.abandonLocked(fl)
	486	+	return
	487	+	}
	488	+	time.AfterFunc(s.grace, func() {
	489	+	s.mu.Lock()
	490	+	defer s.mu.Unlock()
	491	+	if fl.waiters == 0 && !fl.finished && fl.gen == gen {
	492	+	s.abandonLocked(fl)
	493	+	}
	494	+	})
	495	+	}
	496	+
	497	+	// abandonLocked cancels a flight nobody waits for. A later request for the
	498	+	// digest starts a new one.
	499	+	func (s store) abandonLocked(fl flight) {
	500	+	fl.cancel()
	501	+	if s.flights[fl.key] == fl {
	502	+	delete(s.flights, fl.key)
	503	+	}
	504	+	}
	505	+
	506	+	// takeSlotLocked takes a global download slot and one of quota (nil: none),
	507	+	// both or neither.
	508	+	func (s store) takeSlotLocked(quota Quota) bool {
	509	+	if s.downloads >= s.maxDownloads {
	510	+	return false
	511	+	}
	512	+	if quota != nil && !quota.tryAcquire() {
	513	+	return false
	514	+	}
	515	+	s.downloads++
	516	+	return true
	517	+	}
	518	+
	519	+	// waitSlot waits until a slot may have freed (freed is closed), keeping the
	520	+	// client alive meanwhile. It fails with errBusy at the deadline.
	521	+	func waitSlot(ctx context.Context, freed <-chan struct{}, deadline <-chan time.Time, keep keepalive) error {
	522	+	var tick <-chan time.Time
	523	+	if keep.every > 0 && keep.fn != nil {
	524	+	t := time.NewTicker(keep.every)
	525	+	defer t.Stop()
	526	+	tick = t.C
	527	+	}
	528	+	for {
	529	+	select {
	530	+	case <-freed:
	531	+	return nil
	532	+	case <-ctx.Done():
	533	+	return ctx.Err()
	534	+	case <-deadline:
	535	+	return errBusy
	536	+	case <-tick:
	537	+	keep.fn() // bounded by the slot wait
	538	+	}
	539	+	}
	540	+	}
	541	+
	542	+	// finishLocked ends a flight and releases its slots. A committed entry is
	543	+	// pinned on behalf of the waiters, so that no eviction removes it before they
	544	+	// open it.
	545	+	func (s store) finishLocked(fl flight, err error, committed *entry) {
	546	+	fl.err = err
	547	+	fl.finished = true
	548	+	if err == nil && committed != nil && fl.waiters > 0 {
	549	+	committed.pins++
	550	+	fl.pinned = true
	551	+	}
	552	+	if s.flights[fl.key] == fl {
	553	+	delete(s.flights, fl.key)
	554	+	}
	555	+	if fl.kind == kindBlob {
	556	+	s.downloads--
	557	+	if fl.quota != nil {
	558	+	fl.quota.release()
	559	+	}
	560	+	close(s.slotFreed)
	561	+	s.slotFreed = make(chan struct{})
	562	+	}
	563	+	}
	564	+
	565	+	// run downloads and finishes the flight. A panic in fetch fails the flight
	566	+	// (and frees its slots) rather than leave its waiters hanging.
	567	+	func (s store) run(ctx context.Context, fl flight, digest string, fetch fetch) {
	568	+	var err error
	569	+	defer func() {
	570	+	if v := recover(); v != nil {
	571	+	err = fmt.Errorf("registry download panicked: %v", v)
	572	+	s.log.Error().Str("key", fl.key).Err(err).Msg("registry download")
	573	+	}
	574	+	fl.cancel()
	575	+	s.mu.Lock()
	576	+	if !fl.finished {
	577	+	if err == nil {
	578	+	err = errors.New("registry download ended without a commit")
	579	+	}
	580	+	s.finishLocked(fl, err, nil)
	581	+	}
	582	+	s.mu.Unlock()
	583	+	if fl.err == nil && s.hookCommitted != nil {
	584	+	s.hookCommitted(fl.key)
	585	+	}
	586	+	close(fl.done)
	587	+	}()
	588	+	err = s.fill(ctx, fl, digest, fetch)
	589	+	}
	590	+
	591	+	func waitFlight(ctx context.Context, fl *flight, keep keepalive) error {
	592	+	var tick <-chan time.Time
	593	+	if keep.every > 0 && keep.fn != nil {
	594	+	t := time.NewTicker(keep.every)
	595	+	defer t.Stop()
	596	+	tick = t.C
	597	+	}
	598	+	last := fl.written.Load()
	599	+	for {
	600	+	select {
	601	+	case <-ctx.Done():
	602	+	return ctx.Err()
	603	+	case <-fl.done:
	604	+	return fl.err
	605	+	case <-tick:
	606	+	if n := fl.written.Load(); n != last {
	607	+	last = n
	608	+	keep.fn()
	609	+	}
	610	+	}
	611	+	}
	612	+	}
	613	+
	614	+	type chargedWriter struct {
	615	+	s *store
	616	+	w io.Writer
	617	+	n int64
	618	+	written *atomic.Int64
	619	+	}
	620	+
	621	+	func (w *chargedWriter) Write(b []byte) (int, error) {
	622	+	s := w.s
	623	+	s.mu.Lock()
	624	+	need := int64(len(b))
	625	+	s.evictLocked(need)
	626	+	if need > s.max-s.total-s.pending {
	627	+	s.mu.Unlock()
	628	+	return 0, errTooLarge
	629	+	}
	630	+	s.pending += need
	631	+	w.n += need
	632	+	s.mu.Unlock()
	633	+	n, err := w.w.Write(b)
	634	+	if n < len(b) {
	635	+	s.mu.Lock()
	636	+	s.pending -= int64(len(b) - n)
	637	+	w.n -= int64(len(b) - n)
	638	+	s.mu.Unlock()
	639	+	}
	640	+	w.written.Add(int64(n))
	641	+	return n, err
	642	+	}
	643	+
	644	+	// fill downloads into tmp/, verifies the digest and commits. On success it has
	645	+	// finished the flight (finishLocked) under the same lock as the commit.
	646	+	func (s store) fill(ctx context.Context, fl flight, digest string, fetch fetch) error {
	647	+	key := fl.key
	648	+	f, err := os.CreateTemp(filepath.Join(s.dir, "tmp"), "download-")
	649	+	if err != nil {
	650	+	return err
	651	+	}
	652	+	defer func() { _ = f.Close(); _ = os.Remove(f.Name()) }()
	653	+	h := sha256.New()
	654	+	cw := &chargedWriter{s: s, w: io.MultiWriter(f, h), written: &fl.written}
	655	+	defer func() { s.mu.Lock(); s.pending -= cw.n; s.mu.Unlock() }()
	656	+	media, err := fetch(ctx, cw)
	657	+	if err != nil {
	658	+	return err
	659	+	}
	660	+	if "sha256:"+hex.EncodeToString(h.Sum(nil)) != digest {
	661	+	return errDigest
	662	+	}
	663	+	if err = f.Close(); err != nil {
	664	+	return err
	665	+	}
	666	+	s.mu.Lock()
	667	+	defer s.mu.Unlock()
	668	+	if e, ok := s.entries[key]; ok {
	669	+	// Same digest, same bytes: keep the stored file and its pins rather than
	670	+	// renaming over a file that may be open (its bytes would leave the
	671	+	// accounting while still allocated).
	672	+	s.finishLocked(fl, nil, e)
	673	+	return nil
	674	+	}
	675	+	path := filepath.Join(s.dir, key)
	676	+	metadata := int64(0)
	677	+	if fl.kind == kindManifest {
	678	+	if len(media) > 1024 {
	679	+	return errors.New("manifest media type too large")
	680	+	}
	681	+	metadata = int64(len(media))
	682	+	}
	683	+	// The download is charged its bytes in pending; the entry is charged at
	684	+	// least minCharge, and its media type.
	685	+	size := charge(cw.n + metadata)
	686	+	if extra := size - cw.n; extra > 0 {
	687	+	s.evictLocked(extra)
	688	+	if extra > s.max-s.total-s.pending {
	689	+	return errTooLarge
	690	+	}
	691	+	}
	692	+	if fl.kind == kindManifest {
	693	+	if err := os.WriteFile(path+".type", []byte(media), 0600); err != nil {
	694	+	return err
	695	+	}
	696	+	}
	697	+	if err := os.Rename(f.Name(), path); err != nil {
	698	+	if fl.kind == kindManifest {
	699	+	_ = os.Remove(path + ".type")
	700	+	}
	701	+	return err
	702	+	}
	703	+	e := &entry{key: key, kind: fl.kind, size: size, used: s.now()}
	704	+	s.addLocked(e)
	705	+	s.pending -= cw.n
	706	+	cw.n = 0
	707	+	s.finishLocked(fl, nil, e)
	708	+	return nil
	709	+	}
	710	+
	711	+	// tagKey is the key of a tag for a normalized Accept (normalizeAccept).
	712	+	func tagKey(name, tag, accept string) string {
	713	+	return kindTag.key(fmt.Sprintf("%x", sha256.Sum256([]byte(name+"\x00"+tag+"\x00"+accept))))
	714	+	}
	715	+	func (s *store) readTagFile(key string) string {
	716	+	f, err := os.Open(filepath.Join(s.dir, key))
	717	+	if err != nil {
	718	+	return ""
	719	+	}
	720	+	defer func() { _ = f.Close() }()
	721	+	b, err := io.ReadAll(io.LimitReader(f, 72))
	722	+	if err != nil \|\| !validDigest(string(b)) {
	723	+	return ""
	724	+	}
	725	+	return string(b)
	726	+	}
	727	+	func (s *store) tag(name, tag, accept string) string {
	728	+	s.mu.Lock()
	729	+	defer s.mu.Unlock()
	730	+	e, ok := s.entries[tagKey(name, tag, accept)]
	731	+	if !ok {
	732	+	return ""
	733	+	}
	734	+	s.touchLocked(e)
	735	+	return e.digest
	736	+	}
	737	+	func (s *store) setTag(name, tag, accept, digest string) error {
	738	+	if !validDigest(digest) {
	739	+	return errDigest
	740	+	}
	741	+	s.mu.Lock()
	742	+	defer s.mu.Unlock()
	743	+	manifest, ok := s.entries[kindManifest.key(digest[7:])]
	744	+	if !ok {
	745	+	return os.ErrNotExist
	746	+	}
	747	+	// Protect the target while making room for its metadata.
	748	+	manifest.pins++
	749	+	defer func() { manifest.pins-- }()
	750	+	key := tagKey(name, tag, accept)
	751	+	old, exists := s.entries[key]
	752	+	if exists {
	753	+	// Already charged: rewriting it needs no room.
	754	+	s.touchLocked(old)
	755	+	} else {
	756	+	s.evictLocked(charge(0))
	757	+	if charge(0) > s.max-s.total-s.pending {
	758	+	return errTooLarge
	759	+	}
	760	+	}
	761	+	f, err := os.CreateTemp(filepath.Join(s.dir, "tmp"), "tag-")
	762	+	if err != nil {
	763	+	return err
	764	+	}
	765	+	defer func() { _ = f.Close(); _ = os.Remove(f.Name()) }()
	766	+	if _, err = f.WriteString(digest); err != nil {
	767	+	return err
	768	+	}
	769	+	if err = f.Close(); err != nil {
	770	+	return err
	771	+	}
	772	+	if err = os.Rename(f.Name(), filepath.Join(s.dir, key)); err != nil {
	773	+	return err
	774	+	}
	775	+	if old, ok := s.entries[key]; ok {
	776	+	s.unindexTagLocked(key, old.digest)
	777	+	old.digest = digest
	778	+	old.used = s.now()
	779	+	s.indexTagLocked(key, digest)
	780	+	return nil
	781	+	}
	782	+	s.addLocked(&entry{key: key, kind: kindTag, size: charge(0), used: s.now(), digest: digest})
	783	+	return nil
	784	+	}

A internal/registryproxy/store_test.go +327 -0

@@ -0,0 +1,327 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"context"
	7	+	"fmt"
	8	+	"io"
	9	+	"net/http"
	10	+	"net/http/httptest"
	11	+	"os"
	12	+	"path/filepath"
	13	+	"strings"
	14	+	"testing"
	15	+	"time"
	16	+	)
	17	+
	18	+	// Reopening a store keeps its content, charges it again and clears the
	19	+	// incomplete downloads in tmp/.
	20	+	func TestStoreReopen(t *testing.T) {
	21	+	dir := t.TempDir()
	22	+	s := mustOpen(t, storeCfg(dir, 8*minCharge))
	23	+	put(t, s, "aaaa")
	24	+	putManifest(t, s, manifestBody, "application/vnd.oci.image.index.v1+json")
	25	+	if err := s.setTag("library/alpine", "3", normalizeAccept(""), sum(manifestBody)); err != nil {
	26	+	t.Fatal(err)
	27	+	}
	28	+	if err := os.WriteFile(filepath.Join(dir, "tmp", "leftover"), []byte("partial"), 0600); err != nil {
	29	+	t.Fatal(err)
	30	+	}
	31	+	total := s.total
	32	+	s = mustOpen(t, storeCfg(dir, 8*minCharge))
	33	+	f, _, err := s.open(kindBlob, sum("aaaa"))
	34	+	if err != nil {
	35	+	t.Fatal(err)
	36	+	}
	37	+	_ = f.Close()
	38	+	if got := s.tag("library/alpine", "3", normalizeAccept("")); got != sum(manifestBody) {
	39	+	t.Fatalf("tag after reopen: %q", got)
	40	+	}
	41	+	if ds, _ := os.ReadDir(filepath.Join(dir, "tmp")); len(ds) != 0 {
	42	+	t.Fatal("tmp not cleared")
	43	+	}
	44	+	if accounted(t, s); s.total != total {
	45	+	t.Fatalf("reopened total %d, was %d", s.total, total)
	46	+	}
	47	+	}
	48	+
	49	+	// Every entry is charged at least minCharge, on commit and on reopen, so tiny
	50	+	// blobs cannot make more than Max/minCharge files.
	51	+	func TestEntriesChargedAtLeastMinCharge(t *testing.T) {
	52	+	dir := t.TempDir()
	53	+	s := mustOpen(t, storeCfg(dir, 3*minCharge))
	54	+	for i := range 10 {
	55	+	put(t, s, fmt.Sprint("tiny-", i))
	56	+	}
	57	+	accounted(t, s)
	58	+	if n := len(s.entries); n > 3 {
	59	+	t.Fatalf("%d entries under a cap of 3 charges", n)
	60	+	}
	61	+	s = mustOpen(t, storeCfg(dir, 3*minCharge))
	62	+	accounted(t, s)
	63	+	if s.total != int64(len(s.entries))*minCharge {
	64	+	t.Fatalf("reopened total %d for %d entries", s.total, len(s.entries))
	65	+	}
	66	+	}
	67	+
	68	+	// A cap below one entry's minimum charge is refused; a blob larger than Max is
	69	+	// refused and leaves nothing charged.
	70	+	func TestStoreOversize(t *testing.T) {
	71	+	if _, err := openStore(storeCfg(t.TempDir(), minCharge-1)); err == nil {
	72	+	t.Fatal("cap below minCharge accepted")
	73	+	}
	74	+	s := mustOpen(t, storeCfg(t.TempDir(), minCharge))
	75	+	large := strings.Repeat("x", int(minCharge)+1)
	76	+	_, _, _, err := s.ensure(context.Background(), kindBlob, sum(large), func(_ context.Context, w io.Writer) (string, error) {
	77	+	_, err := io.WriteString(w, large)
	78	+	return "", err
	79	+	}, keepalive{})
	80	+	if err != errTooLarge {
	81	+	t.Fatal(err)
	82	+	}
	83	+	if s.pending != 0 \|\| s.total != 0 {
	84	+	t.Fatalf("accounting: %d %d", s.pending, s.total)
	85	+	}
	86	+	}
	87	+
	88	+	// Eviction walks the LRU, evicts least recently used first, frees down to the
	89	+	// low-water mark rather than the bare need, and skips pinned entries.
	90	+	func TestEvictionLRUAndLowWater(t *testing.T) {
	91	+	now := time.Unix(1_700_000_000, 0)
	92	+	const n = 40
	93	+	c := storeCfg(t.TempDir(), n*minCharge) // low water: 5%, two entries
	94	+	c.now = func() time.Time { return now }
	95	+	s := mustOpen(t, c)
	96	+	// 40 blobs fill the store. Freeing only the need would evict one blob; the
	97	+	// low-water mark evicts two.
	98	+	blob := func(i int) string { return fmt.Sprintf("%03d", i) + strings.Repeat("x", 47) }
	99	+	for i := range n {
	100	+	now = now.Add(time.Second)
	101	+	put(t, s, blob(i))
	102	+	}
	103	+	// Touch 0 and 1, and keep 2 open: the least recently used are then 3, 4...
	104	+	for _, i := range []int{0, 1} {
	105	+	now = now.Add(time.Second)
	106	+	f, _, err := s.open(kindBlob, sum(blob(i)))
	107	+	if err != nil {
	108	+	t.Fatal(err)
	109	+	}
	110	+	_ = f.Close()
	111	+	}
	112	+	pinned, _, err := s.open(kindBlob, sum(blob(2)))
	113	+	if err != nil {
	114	+	t.Fatal(err)
	115	+	}
	116	+	defer func() { _ = pinned.Close() }()
	117	+	s.mu.Lock()
	118	+	s.lru.MoveToFront(s.entries[kindBlob.key(sum(blob(2))[7:])].elem) // oldest of all, but open
	119	+	s.mu.Unlock()
	120	+	now = now.Add(time.Second)
	121	+	put(t, s, "a") // over the cap: frees the low-water mark
	122	+	present := func(i int) bool {
	123	+	_, err := os.Stat(filepath.Join(s.dir, kindBlob.key(sum(blob(i))[7:])))
	124	+	return err == nil
	125	+	}
	126	+	for i := range n {
	127	+	want := i != 3 && i != 4 // 3 and 4 are the least recently used unpinned
	128	+	if present(i) != want {
	129	+	t.Errorf("blob %d present=%v", i, present(i))
	130	+	}
	131	+	}
	132	+	accounted(t, s)
	133	+	s.mu.Lock()
	134	+	free := s.max - s.total
	135	+	s.mu.Unlock()
	136	+	if free < min(lowWater, s.max/20)-minCharge {
	137	+	t.Fatalf("freed only to %d", free)
	138	+	}
	139	+	}
	140	+
	141	+	// Eviction restarts from the front after a manifest removal that fails, and
	142	+	// does not loop on it.
	143	+	func TestEvictionAfterFailedManifestRemoval(t *testing.T) {
	144	+	now := time.Unix(1_700_000_000, 0)
	145	+	c := storeCfg(t.TempDir(), 1<<20)
	146	+	c.now = func() time.Time { return now }
	147	+	s := mustOpen(t, c)
	148	+	m := `{"schemaVersion":2}`
	149	+	putManifest(t, s, m, "application/vnd.oci.image.index.v1+json")
	150	+	now = now.Add(time.Second)
	151	+	if err := s.setTag("library/alpine", "3", "", sum(m)); err != nil {
	152	+	t.Fatal(err)
	153	+	}
	154	+	now = now.Add(time.Second)
	155	+	put(t, s, "blob")
	156	+	// The manifest's .type cannot be removed: replace it with a non-empty
	157	+	// directory. Its tag goes first all the same.
	158	+	typ := filepath.Join(s.dir, kindManifest.key(sum(m)[7:])+".type")
	159	+	if err := os.Remove(typ); err != nil {
	160	+	t.Fatal(err)
	161	+	}
	162	+	if err := os.MkdirAll(filepath.Join(typ, "x"), 0700); err != nil {
	163	+	t.Fatal(err)
	164	+	}
	165	+	s.mu.Lock()
	166	+	s.evictLocked(s.max) // ask for everything
	167	+	_, manifestKept := s.entries[kindManifest.key(sum(m)[7:])]
	168	+	_, blobKept := s.entries[kindBlob.key(sum("blob")[7:])]
	169	+	tags := len(s.tagsOf)
	170	+	s.mu.Unlock()
	171	+	if !manifestKept \|\| blobKept \|\| tags != 0 {
	172	+	t.Fatalf("manifest kept=%v blob kept=%v tags=%d", manifestKept, blobKept, tags)
	173	+	}
	174	+	accounted(t, s)
	175	+	}
	176	+
	177	+	// The committed entry is pinned for its waiters, so an eviction between the
	178	+	// commit and their open cannot remove it.
	179	+	func TestCommittedEntryPinnedForWaiters(t *testing.T) {
	180	+	s := mustOpen(t, storeCfg(t.TempDir(), minCharge))
	181	+	key := kindBlob.key(sum("aaaa")[7:])
	182	+	s.hookCommitted = func(string) {
	183	+	// Ask for the whole store before the waiters are woken.
	184	+	s.mu.Lock()
	185	+	s.evictLocked(s.max)
	186	+	s.mu.Unlock()
	187	+	}
	188	+	f, _, _, err := s.ensure(context.Background(), kindBlob, sum("aaaa"), func(_ context.Context, w io.Writer) (string, error) {
	189	+	_, err := io.WriteString(w, "aaaa")
	190	+	return "", err
	191	+	}, keepalive{})
	192	+	if err != nil {
	193	+	t.Fatalf("waiter lost its entry: %v", err)
	194	+	}
	195	+	s.mu.Lock()
	196	+	pins := s.entries[key].pins
	197	+	s.mu.Unlock()
	198	+	if pins != 1 {
	199	+	t.Fatalf("pins %d: the commit pin was not released to the reader's", pins)
	200	+	}
	201	+	_ = f.Close()
	202	+	s.hookCommitted = nil
	203	+	s.mu.Lock()
	204	+	s.evictLocked(s.max)
	205	+	_, kept := s.entries[key]
	206	+	s.mu.Unlock()
	207	+	if kept {
	208	+	t.Fatal("unpinned entry not evictable")
	209	+	}
	210	+	}
	211	+
	212	+	// A blob that a response is still sending is pinned: a fill that needs its
	213	+	// room fails, and succeeds once the response has closed the file.
	214	+	func TestEvictionWhileServing(t *testing.T) {
	215	+	a, b := strings.Repeat("a", int(minCharge)), strings.Repeat("b", int(minCharge))
	216	+	srv := upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	217	+	switch {
	218	+	case strings.HasSuffix(r.URL.Path, sum(a)):
	219	+	_, _ = io.WriteString(w, a)
	220	+	case strings.HasSuffix(r.URL.Path, sum(b)):
	221	+	_, _ = io.WriteString(w, b)
	222	+	default:
	223	+	http.NotFound(w, r)
	224	+	}
	225	+	})
	226	+	p := proxyWith(t, srv, Config{Max: minCharge * 3 / 2})
	227	+	if w := request(t, p, http.MethodGet, "/v2/library/alpine/blobs/"+sum(a)); w.Code != http.StatusOK {
	228	+	t.Fatal(w.Code)
	229	+	}
	230	+	bw := &blockingWriter{ResponseRecorder: httptest.NewRecorder(), started: make(chan struct{}), release: make(chan struct{})}
	231	+	done := make(chan struct{})
	232	+	go func() {
	233	+	defer close(done)
	234	+	p.ServeHTTP(bw, httptest.NewRequest(http.MethodGet, "/v2/library/alpine/blobs/"+sum(a), nil))
	235	+	}()
	236	+	<-bw.started
	237	+	if w := request(t, p, http.MethodGet, "/v2/library/alpine/blobs/"+sum(b)); w.Code != http.StatusBadGateway {
	238	+	t.Fatalf("fill evicted a blob being served: %d", w.Code)
	239	+	}
	240	+	if _, err := os.Stat(filepath.Join(p.s.dir, kindBlob.key(sum(a)[7:]))); err != nil {
	241	+	t.Fatalf("served blob removed: %v", err)
	242	+	}
	243	+	accounted(t, p.s)
	244	+	close(bw.release)
	245	+	<-done
	246	+	if bw.Code != http.StatusOK \|\| bw.Body.String() != a {
	247	+	t.Fatalf("served: %d", bw.Code)
	248	+	}
	249	+	if w := request(t, p, http.MethodGet, "/v2/library/alpine/blobs/"+sum(b)); w.Code != http.StatusOK \|\| w.Body.String() != b {
	250	+	t.Fatalf("after release: %d", w.Code)
	251	+	}
	252	+	if _, err := os.Stat(filepath.Join(p.s.dir, kindBlob.key(sum(a)[7:]))); !os.IsNotExist(err) {
	253	+	t.Fatal("released blob not evicted")
	254	+	}
	255	+	accounted(t, p.s)
	256	+	}
	257	+
	258	+	// Tag files share the LRU of the store, so they cannot grow the store past
	259	+	// Max; reopening charges them again.
	260	+	func TestTagsChargedAndEvicted(t *testing.T) {
	261	+	now := time.Unix(1_700_000_000, 0)
	262	+	dir := t.TempDir()
	263	+	c := storeCfg(dir, 4*minCharge) // the manifest and 3 tags
	264	+	c.now = func() time.Time { return now }
	265	+	s := mustOpen(t, c)
	266	+	putManifest(t, s, manifestBody, "application/vnd.oci.image.index.v1+json")
	267	+	for i := range 20 {
	268	+	now = now.Add(time.Second)
	269	+	if err := s.setTag("library/alpine", fmt.Sprint("t", i), "", sum(manifestBody)); err != nil {
	270	+	t.Fatalf("tag %d: %v", i, err)
	271	+	}
	272	+	if n := accounted(t, s); n > 3 {
	273	+	t.Fatalf("%d tags over a cap of 3", n)
	274	+	}
	275	+	}
	276	+	if s.tag("library/alpine", "t19", "") != sum(manifestBody) \|\| s.tag("library/alpine", "t0", "") != "" {
	277	+	t.Fatal("tags not evicted least recently used first")
	278	+	}
	279	+	s = mustOpen(t, storeCfg(dir, 4*minCharge))
	280	+	if n := accounted(t, s); n != 3 {
	281	+	t.Fatalf("reopened with %d tags", n)
	282	+	}
	283	+	}
	284	+
	285	+	// The tag index follows rewrites, and removing a manifest takes exactly its
	286	+	// own tags along.
	287	+	func TestTagIndex(t *testing.T) {
	288	+	s := mustOpen(t, storeCfg(t.TempDir(), 1<<20))
	289	+	manifests := []string{`{"schemaVersion":2,"a":1}`, `{"schemaVersion":2,"b":1}`}
	290	+	for _, m := range manifests {
	291	+	putManifest(t, s, m, "application/vnd.oci.image.index.v1+json")
	292	+	}
	293	+	for _, tag := range []string{"x", "y"} {
	294	+	if err := s.setTag("library/alpine", tag, "", sum(manifests[0])); err != nil {
	295	+	t.Fatal(err)
	296	+	}
	297	+	}
	298	+	// y moves to the second manifest.
	299	+	if err := s.setTag("library/alpine", "y", "", sum(manifests[1])); err != nil {
	300	+	t.Fatal(err)
	301	+	}
	302	+	s.mu.Lock()
	303	+	if !s.removeLocked(kindManifest.key(sum(manifests[0])[7:])) {
	304	+	t.Fatal("remove failed")
	305	+	}
	306	+	n0, n1 := len(s.tagsOf[sum(manifests[0])]), len(s.tagsOf[sum(manifests[1])])
	307	+	s.mu.Unlock()
	308	+	if s.tag("library/alpine", "x", "") != "" \|\| s.tag("library/alpine", "y", "") != sum(manifests[1]) \|\| n0 != 0 \|\| n1 != 1 {
	309	+	t.Fatalf("index: %d %d", n0, n1)
	310	+	}
	311	+	accounted(t, s)
	312	+	}
	313	+
	314	+	// A .type file without its manifest is removed at startup.
	315	+	func TestOrphanTypeRemoved(t *testing.T) {
	316	+	dir := t.TempDir()
	317	+	mustOpen(t, storeCfg(dir, 1<<20))
	318	+	orphan := filepath.Join(dir, kindManifest.key(sum("gone")[7:])+".type")
	319	+	if err := os.WriteFile(orphan, []byte("application/json"), 0600); err != nil {
	320	+	t.Fatal(err)
	321	+	}
	322	+	s := mustOpen(t, storeCfg(dir, 1<<20))
	323	+	if _, err := os.Stat(orphan); !os.IsNotExist(err) {
	324	+	t.Fatal("orphan .type kept")
	325	+	}
	326	+	accounted(t, s)
	327	+	}

A internal/registryproxy/upstream.go +169 -0

@@ -0,0 +1,169 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"context"
	7	+	"encoding/json"
	8	+	"errors"
	9	+	"fmt"
	10	+	"io"
	11	+	"net"
	12	+	"net/http"
	13	+	"net/url"
	14	+	"sync"
	15	+	"time"
	16	+	)
	17	+
	18	+	type upstreamError struct{ status int }
	19	+
	20	+	func (e upstreamError) Error() string { return fmt.Sprintf("registry upstream status %d", e.status) }
	21	+
	22	+	// unavailable reports an upstream that cannot answer now (down, timing out,
	23	+	// failing or rate limiting): a known tag may then be served stale.
	24	+	func unavailable(err error) bool {
	25	+	var e upstreamError
	26	+	if errors.As(err, &e) {
	27	+	return e.status >= http.StatusInternalServerError \|\| e.status == http.StatusTooManyRequests
	28	+	}
	29	+	var network net.Error
	30	+	return errors.As(err, &network) \|\| errors.Is(err, context.DeadlineExceeded)
	31	+	}
	32	+
	33	+	func proxyStatus(err error) int {
	34	+	var e upstreamError
	35	+	if errors.As(err, &e) && (e.status == http.StatusUnauthorized \|\| e.status == http.StatusForbidden \|\| e.status == http.StatusNotFound) {
	36	+	return http.StatusNotFound
	37	+	}
	38	+	return http.StatusBadGateway
	39	+	}
	40	+
	41	+	type bearer struct {
	42	+	value string
	43	+	until time.Time
	44	+	}
	45	+
	46	+	type upstream struct {
	47	+	base, auth string
	48	+	client *http.Client
	49	+	blobClient *http.Client
	50	+	requestTimeout, blobIdle time.Duration
	51	+	mu sync.Mutex
	52	+	tokens map[string]bearer
	53	+	}
	54	+
	55	+	func (u *upstream) token(ctx context.Context, name string, refresh bool) (string, error) {
	56	+	// Do not hold the token map lock over network I/O: an unavailable auth
	57	+	// endpoint must not queue unrelated repositories behind its timeout.
	58	+	// No guest credentials or challenge-controlled URLs are accepted.
	59	+	u.mu.Lock()
	60	+	t, ok := u.tokens[name]
	61	+	u.mu.Unlock()
	62	+	if ok && !refresh && time.Now().Before(t.until) {
	63	+	return t.value, nil
	64	+	}
	65	+	a, err := url.Parse(u.auth)
	66	+	if err != nil {
	67	+	return "", err
	68	+	}
	69	+	q := a.Query()
	70	+	q.Set("service", "registry.docker.io")
	71	+	q.Set("scope", "repository:"+name+":pull")
	72	+	a.RawQuery = q.Encode()
	73	+	req, err := http.NewRequestWithContext(ctx, http.MethodGet, a.String(), nil)
	74	+	if err != nil {
	75	+	return "", err
	76	+	}
	77	+	resp, err := u.client.Do(req)
	78	+	if err != nil {
	79	+	return "", err
	80	+	}
	81	+	defer func() { _ = resp.Body.Close() }()
	82	+	if resp.StatusCode != http.StatusOK {
	83	+	return "", upstreamError{resp.StatusCode}
	84	+	}
	85	+	var data struct {
	86	+	Token string `json:"token"`
	87	+	AccessToken string `json:"access_token"`
	88	+	Expires int64 `json:"expires_in"`
	89	+	}
	90	+	b, err := io.ReadAll(io.LimitReader(resp.Body, 1<<20+1))
	91	+	if err != nil {
	92	+	return "", err
	93	+	}
	94	+	if len(b) > 1<<20 {
	95	+	return "", errors.New("registry token response too large")
	96	+	}
	97	+	if err = json.Unmarshal(b, &data); err != nil {
	98	+	return "", err
	99	+	}
	100	+	if data.Token == "" {
	101	+	data.Token = data.AccessToken
	102	+	}
	103	+	if data.Token == "" {
	104	+	return "", errors.New("empty registry token")
	105	+	}
	106	+	if data.Expires <= 0 {
	107	+	data.Expires = 60
	108	+	}
	109	+	if data.Expires > 86400 {
	110	+	data.Expires = 86400
	111	+	}
	112	+	u.mu.Lock()
	113	+	defer u.mu.Unlock()
	114	+	if len(u.tokens) >= 1024 {
	115	+	clear(u.tokens)
	116	+	}
	117	+	u.tokens[name] = bearer{data.Token, time.Now().Add(time.Duration(data.Expires) * time.Second)}
	118	+	return data.Token, nil
	119	+	}
	120	+
	121	+	// authorized calls send with a bearer token for name, and once more with a
	122	+	// fresh token after a 401 or 403. Each token request is bounded by
	123	+	// RequestTimeout (and ctx). It returns a 200 response; any other closes the
	124	+	// body and is an upstreamError.
	125	+	func (u upstream) authorized(ctx context.Context, name string, send func(tok string) (http.Response, error)) (*http.Response, error) {
	126	+	for attempt := 0; attempt < 2; attempt++ {
	127	+	authCtx, cancel := context.WithTimeout(ctx, u.requestTimeout)
	128	+	tok, err := u.token(authCtx, name, attempt > 0)
	129	+	cancel()
	130	+	if err != nil {
	131	+	return nil, err
	132	+	}
	133	+	resp, err := send(tok)
	134	+	if err != nil {
	135	+	return nil, err
	136	+	}
	137	+	if resp.StatusCode == http.StatusOK {
	138	+	return resp, nil
	139	+	}
	140	+	_ = resp.Body.Close()
	141	+	if (resp.StatusCode == http.StatusUnauthorized \|\| resp.StatusCode == http.StatusForbidden) && attempt == 0 {
	142	+	continue
	143	+	}
	144	+	return nil, upstreamError{resp.StatusCode}
	145	+	}
	146	+	return nil, upstreamError{http.StatusUnauthorized}
	147	+	}
	148	+
	149	+	// request is a metadata request (manifests, blob HEAD) bounded by ctx. Manifests
	150	+	// use the client that never follows redirects; a blob HEAD uses the blob client,
	151	+	// because Docker Hub answers it with a redirect to its CDN.
	152	+	func (u upstream) request(ctx context.Context, method, name string, k kind, ref, accept string) (http.Response, error) {
	153	+	client := u.client
	154	+	if k == kindBlob {
	155	+	client = u.blobClient
	156	+	}
	157	+	return u.authorized(ctx, name, func(tok string) (*http.Response, error) {
	158	+	req, err := http.NewRequestWithContext(ctx, method, u.base+"/v2/"+name+"/"+k.dir()+"/"+ref, nil)
	159	+	if err != nil {
	160	+	return nil, err
	161	+	}
	162	+	req.Header.Set("Authorization", "Bearer "+tok)
	163	+	if accept != "" {
	164	+	req.Header.Set("Accept", accept)
	165	+	}
	166	+	// Do not forward guest Authorization, cookies, query parameters or Range.
	167	+	return client.Do(req)
	168	+	})
	169	+	}

A internal/registryproxy/upstream_test.go +172 -0

@@ -0,0 +1,172 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package registryproxy
	4	+
	5	+	import (
	6	+	"fmt"
	7	+	"io"
	8	+	"net/http"
	9	+	"net/http/httptest"
	10	+	"os"
	11	+	"path/filepath"
	12	+	"strings"
	13	+	"sync/atomic"
	14	+	"testing"
	15	+	"time"
	16	+	)
	17	+
	18	+	// A blob body has no total deadline: a transfer that keeps moving may last
	19	+	// far longer than RequestTimeout and BlobIdleTimeout.
	20	+	func TestBlobTransferOutlivesRequestTimeout(t *testing.T) {
	21	+	body := strings.Repeat("layer", 4000)
	22	+	srv := upstreamWith(t, slowBlob(body, 20, 25*time.Millisecond))
	23	+	p := proxyWith(t, srv, Config{RequestTimeout: 100 * time.Millisecond, BlobIdleTimeout: 150 * time.Millisecond})
	24	+	start := time.Now()
	25	+	w := request(t, p, http.MethodGet, "/v2/library/alpine/blobs/"+sum(body))
	26	+	if w.Code != http.StatusOK \|\| w.Body.String() != body {
	27	+	t.Fatalf("blob: %d", w.Code)
	28	+	}
	29	+	if d := time.Since(start); d < 300*time.Millisecond {
	30	+	t.Fatalf("transfer took %v, not longer than the timeouts", d)
	31	+	}
	32	+	}
	33	+
	34	+	// A blob body that stops moving is cut after BlobIdleTimeout, and auth,
	35	+	// manifests and HEAD keep their total RequestTimeout.
	36	+	func TestStalledUpstreamTimesOut(t *testing.T) {
	37	+	body := strings.Repeat("layer", 4000)
	38	+	srv := upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	39	+	if strings.Contains(r.URL.Path, "/blobs/") && r.Method == http.MethodGet {
	40	+	w.Header().Set("Content-Length", fmt.Sprint(len(body)))
	41	+	_, _ = io.WriteString(w, body[:100])
	42	+	w.(http.Flusher).Flush()
	43	+	}
	44	+	select { // a stalled body, or headers that never come
	45	+	case <-r.Context().Done():
	46	+	case <-time.After(5 * time.Second):
	47	+	}
	48	+	})
	49	+	p := proxyWith(t, srv, Config{RequestTimeout: 100 * time.Millisecond, BlobIdleTimeout: 150 * time.Millisecond})
	50	+	for _, tc := range []struct{ method, path string }{
	51	+	{http.MethodGet, "/v2/library/alpine/blobs/" + sum(body)},
	52	+	{http.MethodHead, "/v2/library/alpine/blobs/" + sum(body)},
	53	+	{http.MethodGet, "/v2/library/alpine/manifests/3"},
	54	+	} {
	55	+	start := time.Now()
	56	+	if w := request(t, p, tc.method, tc.path); w.Code != http.StatusBadGateway {
	57	+	t.Errorf("%s %s: %d", tc.method, tc.path, w.Code)
	58	+	}
	59	+	if d := time.Since(start); d > 2*time.Second {
	60	+	t.Errorf("%s %s: cut after %v", tc.method, tc.path, d)
	61	+	}
	62	+	}
	63	+	if _, err := os.Stat(filepath.Join(p.s.dir, kindBlob.key(sum(body)[7:]))); !os.IsNotExist(err) {
	64	+	t.Fatal("partial blob stored")
	65	+	}
	66	+	}
	67	+
	68	+	// Auth and manifest requests never follow a redirect.
	69	+	func TestMetadataRedirectsNotFollowed(t *testing.T) {
	70	+	var elsewhere atomic.Int32
	71	+	other := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	72	+	elsewhere.Add(1)
	73	+	_, _ = io.WriteString(w, `{"token":"public"}`)
	74	+	}))
	75	+	t.Cleanup(other.Close)
	76	+	for _, redirectAuth := range []bool{true, false} {
	77	+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	78	+	if r.URL.Path == "/token" && !redirectAuth {
	79	+	_, _ = io.WriteString(w, `{"token":"public"}`)
	80	+	return
	81	+	}
	82	+	http.Redirect(w, r, other.URL+r.URL.Path, http.StatusTemporaryRedirect)
	83	+	}))
	84	+	p := proxyWith(t, srv, Config{})
	85	+	for _, ref := range []string{"3", sum(manifestBody)} {
	86	+	if w := request(t, p, http.MethodGet, "/v2/library/alpine/manifests/"+ref); w.Code != http.StatusBadGateway {
	87	+	t.Errorf("auth redirect %v, ref %s: %d", redirectAuth, ref, w.Code)
	88	+	}
	89	+	}
	90	+	srv.Close()
	91	+	}
	92	+	if elsewhere.Load() != 0 {
	93	+	t.Fatalf("%d redirects followed", elsewhere.Load())
	94	+	}
	95	+	}
	96	+
	97	+	// Blob requests, HEAD included, follow the CDN redirect without the bearer
	98	+	// token.
	99	+	func TestBlobRedirectStripsBearer(t *testing.T) {
	100	+	var cdnHits atomic.Int32
	101	+	cdn := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
	102	+	cdnHits.Add(1)
	103	+	if r.Header.Get("Authorization") != "" {
	104	+	t.Error("bearer sent to the CDN")
	105	+	}
	106	+	w.Header().Set("Content-Length", fmt.Sprint(len(blobBody)))
	107	+	if r.Method == http.MethodGet {
	108	+	_, _ = io.WriteString(w, blobBody)
	109	+	}
	110	+	}))
	111	+	t.Cleanup(cdn.Close)
	112	+	srv := upstreamWith(t, func(w http.ResponseWriter, r *http.Request) {
	113	+	if r.Header.Get("Authorization") != "Bearer public" {
	114	+	t.Error("no bearer on the registry")
	115	+	}
	116	+	http.Redirect(w, r, cdn.URL+"/layer", http.StatusTemporaryRedirect)
	117	+	})
	118	+	p := proxyWith(t, srv, Config{})
	119	+	path := "/v2/library/alpine/blobs/" + sum(blobBody)
	120	+	if w := request(t, p, http.MethodHead, path); w.Code != http.StatusOK \|\| w.Header().Get("Content-Length") != fmt.Sprint(len(blobBody)) {
	121	+	t.Fatalf("HEAD: %d %v", w.Code, w.Header())
	122	+	}
	123	+	if w := request(t, p, http.MethodGet, path); w.Code != http.StatusOK \|\| w.Body.String() != blobBody {
	124	+	t.Fatalf("blob: %d", w.Code)
	125	+	}
	126	+	if cdnHits.Load() != 2 {
	127	+	t.Fatalf("CDN hits %d", cdnHits.Load())
	128	+	}
	129	+	}
	130	+
	131	+	// A 401 or 403 is retried once with a fresh token; a second one is a 404, so
	132	+	// that dockerd falls back to Docker Hub with the job's credentials.
	133	+	func TestUnauthorizedRetriedOnce(t *testing.T) {
	134	+	for _, path := range []string{"/v2/library/alpine/manifests/3", "/v2/library/alpine/blobs/" + sum(blobBody)} {
	135	+	f := fake(t)
	136	+	p := proxyFor(t, f)
	137	+	f.status.Store(http.StatusUnauthorized)
	138	+	if w := request(t, p, http.MethodGet, path); w.Code != http.StatusNotFound {
	139	+	t.Fatalf("%s: %d", path, w.Code)
	140	+	}
	141	+	if f.tokens.Load() != 2 {
	142	+	t.Fatalf("%s: %d token requests, want a fresh one", path, f.tokens.Load())
	143	+	}
	144	+	}
	145	+	}
	146	+
	147	+	// When upstream is down, fails or rate-limits (429), a known tag is served
	148	+	// stale; an unknown one is an error.
	149	+	func TestStaleTagWhenUpstreamUnavailable(t *testing.T) {
	150	+	for _, tc := range []struct {
	151	+	name string
	152	+	status int32 // 0: the server is closed
	153	+	}{{"rate limited", http.StatusTooManyRequests}, {"failing", http.StatusServiceUnavailable}, {"down", 0}} {
	154	+	t.Run(tc.name, func(t *testing.T) {
	155	+	f := fake(t)
	156	+	p := proxyFor(t, f)
	157	+	if w := request(t, p, http.MethodGet, "/v2/library/alpine/manifests/3"); w.Code != http.StatusOK {
	158	+	t.Fatal(w.Code)
	159	+	}
	160	+	if tc.status == 0 {
	161	+	f.server.Close()
	162	+	}
	163	+	f.status.Store(tc.status)
	164	+	if w := request(t, p, http.MethodGet, "/v2/library/alpine/manifests/3"); w.Code != http.StatusOK \|\| w.Body.String() != manifestBody {
	165	+	t.Fatalf("stale: %d %s", w.Code, w.Body)
	166	+	}
	167	+	if w := request(t, p, http.MethodGet, "/v2/library/alpine/manifests/unknown"); w.Code != http.StatusBadGateway {
	168	+	t.Fatalf("unknown: %d", w.Code)
	169	+	}
	170	+	})
	171	+	}
	172	+	}

M internal/sandbox/container/container_test.go +11 -0


@@ -349,6 +349,17 @@ func TestStartRunStop(t *testing.T) {
349	if err != nil {	349		if err != nil {
350	t.Fatal(err)	350		t.Fatal(err)
351	}	351		}
		352	+	timed := sb.(sandbox.Timed)
		353	+	timings := timed.StartTimings()
		354	+	for _, key := range []string{"socket_ms", "cache_ms", "scratch_ms", "net_ms", "container_ms", "connect_ms"} {
		355	+	if value, ok := timings[key]; !ok \|\| value < 0 {
		356	+	t.Errorf("StartTimings[%q] = %d, present=%v", key, value, ok)
		357	+	}
		358	+	}
		359	+	timings["socket_ms"] = -1
		360	+	if timed.StartTimings()["socket_ms"] < 0 {
		361	+	t.Error("StartTimings returned shared storage")
		362	+	}
352	out, code := stub(t, conn)	363		out, code := stub(t, conn)
353	if out != "hello from fake container\n" \|\| code != 7 {	364		if out != "hello from fake container\n" \|\| code != 7 {
354	t.Fatalf("out=%q code=%d", out, code)	365		t.Fatalf("out=%q code=%d", out, code)

M internal/sandbox/container/driver.go +34 -6

 	"context"
 	"errors"
 	"fmt"
+	"maps"
 	"net"
 	"net/netip"
 	"os"
 )
 type containerSandbox struct {
-	d    *Driver
+	d       *Driver
-	slot int
+	slot    int
-	id   string
+	id      string
-	gate sandbox.BootGate
+	gate    sandbox.BootGate
+	timings map[string]int64
 	mu        sync.Mutex
 	started   bool
 	attached  bool
 }
+// StartTimings returns a copy of the phase durations of a successful Start.
+// It is valid once Start has returned, which writes them.
+func (s *containerSandbox) StartTimings() map[string]int64 { return maps.Clone(s.timings) }
 // ID implements sandbox.Sandbox.
 func (s *containerSandbox) ID() string { return s.id }
 	if d.cfg.GuestForge != nil {
 		log.Warn().Str("job", spec.JobID).Str("container", s.id).Msg(d.cfg.GuestForge.Warning())
 	}
+	start := time.Now()
+	s.timings = make(map[string]int64)
 	conn, err := s.run(bootCtx, spec)
 	if err != nil {
+		s.timings = nil
 		var tail string
 		if s.container != "" {
 			tail, _ = d.eng.LogsTail(context.WithoutCancel(ctx), s.container, 40)
 		}
 		return nil, errors.Join(err, cerr)
 	}
-	log.Info().Str("container", s.container).Int("slot", s.slot).Str("job", spec.JobID).Bool("privileged", d.privileged).Msg("container running")
+	fields := map[string]any{"total_ms": time.Since(start).Milliseconds()}
+	for k, v := range s.timings {
+		fields[k] = v
+	}
+	log.Info().Str("container", s.container).Int("slot", s.slot).Str("job", spec.JobID).Bool("privileged", d.privileged).Fields(fields).Msg("container running")
 	return conn, nil
 }
 	if err != nil {
 		return nil, err
 	}
+	start := time.Now()
 	accepted, err := s.runSocket()
 	if err != nil {
 		return nil, err
 	}
+	s.timings["socket_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	if err := s.runCache(spec); err != nil {
 		return nil, err
 	}
+	s.timings["cache_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	if err := s.runScratch(ctx, spec); err != nil {
 		return nil, err
 	}
 	labels := map[string]string{sandbox.LabelJob: spec.JobID}
+	s.timings["scratch_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	if err := s.runNetwork(ctx, netw, labels); err != nil {
 		return nil, err
 	}
+	s.timings["net_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	exited, err := s.runContainer(ctx, spec, netw, labels)
 	if err != nil {
 		return nil, err
 	}
-	return s.waitExecutor(ctx, accepted, exited)
+	s.timings["container_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
+	conn, err := s.waitExecutor(ctx, accepted, exited)
+	if err == nil {
+		s.timings["connect_ms"] = time.Since(start).Milliseconds()
+	}
+	return conn, err
 }
 type acceptResult struct {

M internal/sandbox/sandbox.go +7 -0


@@ -89,6 +89,13 @@ type Sandbox interface {
89	Stop(ctx context.Context) error	89		Stop(ctx context.Context) error
90	}	90		}
91		91
		92	+	// Timed is implemented by sandboxes that measure their start phases.
		93	+	type Timed interface {
		94	+	// StartTimings returns a copy of the phase durations (ms) of a successful
		95	+	// Start, nil after a failed one. Call it only once Start has returned.
		96	+	StartTimings() map[string]int64
		97	+	}
		98	+
92	// Driver creates sandboxes of one mode and reaps what a previous run left.	99		// Driver creates sandboxes of one mode and reaps what a previous run left.
93	type Driver interface {	100		type Driver interface {
94	// Mode is VM or Container.	101		// Mode is VM or Container.

M internal/sandbox/vm/driver.go +42 -7

 	"errors"
 	"fmt"
 	"io/fs"
+	"maps"
 	"net"
 	"net/netip"
 	"os"
 // vmSandbox is one VM, single use.
 type vmSandbox struct {
-	d    *Driver
+	d       *Driver
-	slot int
+	slot    int
-	id   string
+	id      string
-	gate sandbox.BootGate
+	gate    sandbox.BootGate
+	timings map[string]int64
 	mu      sync.Mutex
 	started bool
 	attached bool
 }
+// StartTimings returns a copy of the phase durations of a successful Start.
+// It is valid once Start has returned, which writes them.
+func (s *vmSandbox) StartTimings() map[string]int64 { return maps.Clone(s.timings) }
 // ID implements sandbox.Sandbox.
 func (s *vmSandbox) ID() string { return s.id }
 		return nil, fmt.Errorf("write state record: %w", err)
 	}
+	start := time.Now()
+	s.timings = make(map[string]int64)
 	conn, err := s.boot(bootCtx, spec)
 	if err != nil {
+		s.timings = nil
 		console := ""
 		if s.console != nil {
 			console = s.console.String()
 		}
 		return nil, errors.Join(err, cerr)
 	}
-	log.Info().Str("vm", s.id).Int("slot", s.slot).Str("job", spec.JobID).Msg("micro-VM running")
+	fields := map[string]any{"total_ms": time.Since(start).Milliseconds()}
+	for k, v := range s.timings {
+		fields[k] = v
+	}
+	log.Info().Str("vm", s.id).Int("slot", s.slot).Str("job", spec.JobID).Fields(fields).Msg("micro-VM running")
 	return conn, nil
 }
 	if err != nil {
 		return nil, err
 	}
+	start := time.Now()
 	if err := s.bootNetwork(ctx, netw); err != nil {
 		return nil, err
 	}
+	s.timings["net_ms"] = time.Since(start).Milliseconds() - s.timings["tap_ms"]
+	start = time.Now()
 	api, err := s.bootVMM(ctx, spec)
 	if err != nil {
 		return nil, err
 	}
+	s.timings["vmm_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	files, err := s.bootFiles(ctx, spec)
 	if err != nil {
 		return nil, err
 	}
+	s.timings["files_ms"] = time.Since(start).Milliseconds() - s.timings["scratch_ms"]
+	start = time.Now()
 	accepted, err := s.bootVsock()
 	if err != nil {
 		return nil, err
 	if err := s.bootCache(spec); err != nil {
 		return nil, err
 	}
+	s.timings["vsock_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	if err := api.configure(ctx, s.vmConfig(spec, netw, files)); err != nil {
 		return nil, err
 	}
-	return s.waitExecutor(ctx, accepted)
+	s.timings["configure_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
+	conn, err := s.waitExecutor(ctx, accepted)
+	if err == nil {
+		s.timings["connect_ms"] = time.Since(start).Milliseconds()
+	}
+	return conn, err
 }
 // bootNetwork creates the TAP (it must exist when Firecracker opens it) and
 	if err := d.store.save(s.rec); err != nil {
 		return err
 	}
+	start := time.Now()
 	if err := createTap(ctx, d.opt.Run, s.tap, s.lay.uid, s.gateway); err != nil {
 		return err
 	}
+	s.timings["tap_ms"] = time.Since(start).Milliseconds()
 	s.attached = true // from here Detach is idempotent and always safe
 	return d.net.Attach(ctx, netpolicy.Guest{Iface: s.tap, Gateway: netw.Gateway, Addr: netw.Guest, ForgePort: d.cfg.GuestForge.TCPPort()})
 }
 	if s.lay.jailed {
 		owner = s.lay.uid
 	}
-	return f, disk.CreateScratch(ctx, d.opt.Run, s.lay.host("scratch.ext4"), spec.DiskMiB, owner)
+	start := time.Now()
+	err = disk.CreateScratch(ctx, d.opt.Run, s.lay.host("scratch.ext4"), spec.DiskMiB, owner)
+	if err == nil {
+		s.timings["scratch_ms"] = time.Since(start).Milliseconds()
+	}
+	return f, err
 }
 // shareExternals makes the read-only disk of the host's external tools available

M internal/sandbox/vm/vm_test.go +10 -0


@@ -228,6 +228,16 @@ func TestStartRunStop(t *testing.T) {
228	if err != nil {	228		if err != nil {
229	t.Fatal(err)	229		t.Fatal(err)
230	}	230		}
		231	+	timings := sb.(sandbox.Timed).StartTimings()
		232	+	for _, key := range []string{"tap_ms", "net_ms", "vmm_ms", "files_ms", "scratch_ms", "vsock_ms", "configure_ms", "connect_ms"} {
		233	+	if value, ok := timings[key]; !ok \|\| value < 0 {
		234	+	t.Errorf("%s = %d, present=%v", key, value, ok)
		235	+	}
		236	+	}
		237	+	timings["tap_ms"] = -1
		238	+	if sb.(sandbox.Timed).StartTimings()["tap_ms"] < 0 {
		239	+	t.Error("shared timing map")
		240	+	}
231	out, code := runStub(t, conn)	241		out, code := runStub(t, conn)
232	if out != "hello from fake guest\n" \|\| code != 0 {	242		if out != "hello from fake guest\n" \|\| code != 0 {
233	t.Fatalf("out=%q code=%d", out, code)	243		t.Fatalf("out=%q code=%d", out, code)

M main.go +1 -0


@@ -79,6 +79,7 @@ func execCmd(ctx context.Context) int {
79	}	79		}
80	code, err := guest.Exec(ctx, guest.ExecConfig{	80		code, err := guest.Exec(ctx, guest.ExecConfig{
81	Target: target,	81		Target: target,
		82	+	BootMs: guest.ParseBootMs(os.Getenv("ERMITE_BOOT_MS")),
82	Sandbox: envOr("ERMITE_SANDBOX", "container"),	83		Sandbox: envOr("ERMITE_SANDBOX", "container"),
83	Version: envOr("ERMITE_VERSION", version),	84		Version: envOr("ERMITE_VERSION", version),
84	// A test image without the user "runner" (ERMITE_RUNNER_ALLOW_ROOT_STEPS=1);	85		// A test image without the user "runner" (ERMITE_RUNNER_ALLOW_ROOT_STEPS=1);

A registry_setup_test.go +75 -0

@@ -0,0 +1,75 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package main
	4	+
	5	+	import (
	6	+	"context"
	7	+	"strings"
	8	+	"testing"
	9	+
	10	+	"bnema.dev/ermite-runner/internal/actionscache"
	11	+	"bnema.dev/ermite-runner/internal/cachesvc"
	12	+	"bnema.dev/ermite-runner/internal/sandbox"
	13	+	)
	14	+
	15	+	// The three size caps share one parser: a zero size in any unit turns the
	16	+	// registry proxy and the action archive cache off, and is refused for the
	17	+	// cache API, which ERMITE_RUNNER_CACHE=0 turns off. Each error names its
	18	+	// variable.
	19	+	func TestCacheSizeConfiguration(t *testing.T) {
	20	+	t.Setenv(envCache, "1")
	21	+	for _, tc := range []struct {
	22	+	registry, actions, cache string
	23	+	registryOn, archivesOn bool
	24	+	}{
	25	+	{"", "", "1M", true, true},
	26	+	{"1M", "0", "2M", true, false},
	27	+	{"0", "1M", "1M", false, true},
	28	+	{"0G", "0GiB", "1M", false, false},
	29	+	{" 0M ", "", "1M", false, true},
	30	+	{"00", "", "1M", false, true},
	31	+	{"0GiB", "", "1M", false, true},
	32	+	{"10M", "", "1M", true, true},
	33	+	} {
	34	+	t.Setenv(envRegistryMax, tc.registry)
	35	+	t.Setenv(actionscache.EnvMax, tc.actions)
	36	+	t.Setenv(cachesvc.EnvMax, tc.cache)
	37	+	cfg := sandbox.Config{StateDir: t.TempDir()}
	38	+	svc, archives, err := setupCache(context.Background(), &cfg)
	39	+	if err != nil {
	40	+	t.Fatalf("%+v: %v", tc, err)
	41	+	}
	42	+	if svc.RegistryEnabled() != tc.registryOn \|\| (archives != nil) != tc.archivesOn {
	43	+	t.Fatalf("%+v: registry=%v archives=%v", tc, svc.RegistryEnabled(), archives != nil)
	44	+	}
	45	+	_ = svc.CloseAll()
	46	+	}
	47	+	t.Setenv(envRegistryMax, "")
	48	+	t.Setenv(actionscache.EnvMax, "")
	49	+	t.Setenv(cachesvc.EnvMax, "")
	50	+	for _, tc := range []struct{ env, value string }{
	51	+	{envRegistryMax, "invalid"}, {envRegistryMax, "G"}, {envRegistryMax, "-1G"},
	52	+	{actionscache.EnvMax, "x"},
	53	+	{cachesvc.EnvMax, "0"}, {cachesvc.EnvMax, "0G"}, {cachesvc.EnvMax, "-1"},
	54	+	} {
	55	+	t.Run(tc.env+"="+tc.value, func(t *testing.T) {
	56	+	t.Setenv(tc.env, tc.value)
	57	+	cfg := sandbox.Config{StateDir: t.TempDir()}
	58	+	svc, _, err := setupCache(context.Background(), &cfg)
	59	+	if err == nil {
	60	+	_ = svc.CloseAll()
	61	+	t.Fatal("accepted")
	62	+	}
	63	+	if !strings.HasPrefix(err.Error(), tc.env+": ") {
	64	+	t.Fatalf("error does not name %s: %v", tc.env, err)
	65	+	}
	66	+	})
	67	+	}
	68	+	t.Setenv(envCache, "0")
	69	+	t.Setenv(envRegistryMax, "invalid")
	70	+	cfg := sandbox.Config{StateDir: t.TempDir()}
	71	+	svc, _, err := setupCache(context.Background(), &cfg)
	72	+	if err != nil \|\| svc != nil {
	73	+	t.Fatalf("cache off: %v %v", svc, err)
	74	+	}
	75	+	}