Skip to content

Commit a5e3383

Browse files
BotCoder254BotCoder254
authored
Merge pull request #30 from BotCoder254/feat/log-chunk-sections
docs: runbook for the empty-/workspace stale-runner-image failure
2 parents 2c41218 + fa87406 commit a5e3383

2 files changed

Lines changed: 321 additions & 0 deletions

File tree

‎docs/README.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ Docker runner).
1313
| [deploy-frontend-netlify.md](./deploy-frontend-netlify.md) | Deploying the **React frontend** to Netlify: proxy rewrites that keep the session cookie first-party (`netlify.toml`), CLI setup and deploys, backend + GitHub URL changes for the Netlify origin, the WebSocket/polling limitation, and troubleshooting. |
1414
| [fix-hosted-runner-docker-socket.md](./fix-hosted-runner-docker-socket.md) | **Runbook** for the `hosted-runner provisioner: docker unreachable` warning on a Dokploy-deployed backend: reading the `attempts=` line to identify the stage, the socket bind mount, the host ACL for uid 10001 (`setfacl` + systemd persistence), the follow-up `error from registry: denied` pre-pull fix, and end-to-end verification. |
1515
| [publish-runner-image.md](./publish-runner-image.md) | Building and publishing the **runner Docker image** (`runner/Dockerfile`) that `RUNNER_IMAGE` points at: repo-root build context rule, building from WSL, GHCR PAT + push + the required public-visibility flip, anonymous-pull verification, updating the image, the build-on-VPS no-registry alternative, and troubleshooting. |
16+
| [fix-empty-workspace-stale-runner.md](./fix-empty-workspace-stale-runner.md) | **Runbook** for jobs failing with an empty `/workspace` (`ENOENT package.json`) because the deployed runner image is older than the repo: the log-order fingerprint that identifies the stale binary, rebuild-from-the-right-source + in-image `grep` verification, registry-side layer forensics without Docker, the revoke-and-recreate rollout, plus the two look-alike failures — containerd `Lchown` layer-extraction errors (host healing) and `cargo: not found` (per-toolchain job images via `container:`). |
1617

1718
## Planned documents
1819

‎docs/fix-empty-workspace-stale-runner.md‎

Lines changed: 320 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,320 @@
1+
# Fix: jobs fail with an empty `/workspace` — the stale-runner-image runbook
2+
3+
This is the verified runbook for a family of job failures that all trace back to one
4+
root cause: **the runner binary executing your jobs is older than the code in the
5+
repository.** It also covers the two look-alike failures that were diagnosed alongside
6+
it (a containerd image-pull error and a missing-toolchain error), because they show up
7+
in the same job logs and are easy to blame on the wrong component.
8+
9+
The failures this runbook resolves, as they appear in a pipeline's job log:
10+
11+
```
12+
▶ step 1/4: Install dependencies
13+
npm error code ENOENT
14+
npm error path /workspace/package.json
15+
npm error enoent Could not read package.json: Error: ENOENT: no such file or directory
16+
step failed (exit code 254)
17+
```
18+
19+
```
20+
image pull failed: Docker stream error: failed to extract layer (…) to overlayfs …
21+
failed to Lchown "…/libdjvulibre.a" for UID 0, GID 0: … no such file or directory
22+
```
23+
24+
```
25+
▶ step 1/2: Build
26+
sh: 1: cargo: not found
27+
step failed (exit code 127)
28+
```
29+
30+
They look related — same pipeline, same image, back-to-back runs — but they are three
31+
independent problems with three independent fixes:
32+
33+
| Symptom | Actual cause | Section |
34+
| --- | --- | --- |
35+
| `ENOENT /workspace/package.json` (workspace empty at step time) | The deployed runner image contains the **old, pre-archive-API binary** | §1–§5 |
36+
| `failed to extract layer … failed to Lchown … no such file or directory` | **Docker-host** containerd snapshotter state (disk pressure / partial-pull leftovers), not Overup | §6 |
37+
| `cargo: not found` (or any missing toolchain) | The **job image** doesn't ship that toolchain — `catthehacker/ubuntu:act-latest` has no Rust | §7 |
38+
39+
## 0. The 10-second diagnostic: read the log ORDER, not the log text
40+
41+
The old and new runner binaries produce almost identical log lines — but in a
42+
**different order**. This ordering is the single reliable fingerprint for which binary
43+
actually ran your job, and it cannot lie:
44+
45+
| Binary | Log order |
46+
| --- | --- |
47+
| **OLD (broken)** | `downloading repository archive` → **`checkout complete`** → `pulling image …` → `container started (…)` |
48+
| **NEW (fixed)** | `downloading repository archive` → `pulling image …` → `container started (…)` → **`checkout complete (N files)`** |
49+
50+
Two tells, either is conclusive:
51+
52+
1. **Position** — the old binary "checks out" to a runner-local temp dir *before* the
53+
container exists (it then bind-mounts that path, which resolves against the wrong
54+
filesystem when the runner itself runs in a container — hence the empty
55+
`/workspace`). The new binary streams the source *into the running container* over
56+
the Docker archive API, so its checkout necessarily happens after
57+
`container started`.
58+
2. **The file count** — the new binary always prints `checkout complete (N files)`.
59+
A bare `checkout complete` with no count is the old binary, full stop.
60+
61+
If a job shows the OLD ordering, do not debug the workflow, the YAML, npm, or the job
62+
image — nothing you change there can work. The runner is stale; continue below.
63+
64+
## 1. Why this happens: the publish gap
65+
66+
The fix for the empty-workspace bug (streaming source over the Docker archive API
67+
instead of bind-mounting) lives in `runner/src/executor.rs` — **in the repository**.
68+
But hosted runners execute whatever is inside the image named by `RUNNER_IMAGE`
69+
(default `ghcr.io/botcoder254/overup-runner:latest`), and historically **nothing
70+
published that image automatically**. Merging a runner fix changed zero bytes of the
71+
image the provisioner runs. Three distinct gaps kept the old binary alive; every one
72+
of them must be closed:
73+
74+
1. **The fix wasn't on the deployed branch.** Runner commits merged to `main` only
75+
help if the image is built from an up-to-date `main` checkout.
76+
2. **The image was never rebuilt/republished** — or worse, was rebuilt from a stale
77+
clone that didn't contain the fix (a `git clone` from weeks ago, never pulled).
78+
The image then has a *fresh timestamp* and an *old binary* — the most deceptive
79+
failure mode in this whole runbook, because everything "looks updated".
80+
3. **Existing runner containers keep their image.** `docker restart` (and the
81+
janitor's auto-restart of stopped runners) reuses the image the container was
82+
*created* from. Pulling a new `:latest` changes nothing for a running runner —
83+
only **revoking and re-creating** the hosted runner produces a container on the
84+
new image.
85+
86+
A CI job now exists (`.github/workflows/ci.yml`, job `runner-image`) that builds
87+
`runner/Dockerfile` and pushes `:latest` + `:{sha}` to GHCR on every push to `main` —
88+
that is the durable fix for gap 2. Note it only helps when GitHub Actions actually
89+
runs: on a **private** repository, an exhausted spending limit or a failed payment
90+
makes every workflow die instantly as `startup_failure` (even Dependabot's), and the
91+
publish silently never happens. Check github.com → Settings → Billing if runs show
92+
`startup_failure` at 0s. Until Actions is healthy, publish manually (§2–§3).
93+
94+
## 2. Rebuild from the RIGHT source
95+
96+
On whatever machine builds the image (the VPS is fine — see
97+
[publish-runner-image.md](./publish-runner-image.md) for the full build/publish
98+
reference):
99+
100+
```bash
101+
cd <repo-root>
102+
git checkout main
103+
git fetch origin
104+
git pull --ff-only origin main
105+
106+
# CRITICAL — prove the fix commits are in the tree you are about to build:
107+
git log --oneline -5
108+
# must include the runner-fix commits (e.g. "fix(runner): verify checkout delivers
109+
# files, tolerate transient pull failures, publish image from CI"). If the log shows
110+
# only old commits, STOP — you are about to rebuild the broken image with a fresh
111+
# timestamp.
112+
113+
# Build context MUST be the repo root (runner/ needs the sibling protocol/ crate):
114+
docker build -f runner/Dockerfile -t ghcr.io/<your-gh-username>/overup-runner:latest .
115+
```
116+
117+
## 3. Verify the binary INSIDE the image before shipping it
118+
119+
Never trust the tag or the build timestamp — verify the artifact. The fixed binary
120+
contains log strings the old one does not, so one `grep` inside the image is a
121+
conclusive test:
122+
123+
```bash
124+
docker run --rm --entrypoint sh ghcr.io/<your-gh-username>/overup-runner:latest \
125+
-c 'grep -c "checkout complete (" /app/runner'
126+
```
127+
128+
- **Prints `1` (or more)** → the image contains the fixed binary. Ship it.
129+
- **Prints `0`** → the source tree was stale (§2). Do **not** push; fix the checkout
130+
and rebuild.
131+
132+
Other new-binary marker strings, if you want a stronger check:
133+
`" files)"`, `"using locally cached image"`, `"contained no usable files"`.
134+
135+
Then push (PAT with `write:packages`; package must be **public** — see
136+
[publish-runner-image.md](./publish-runner-image.md) §3):
137+
138+
```bash
139+
docker login ghcr.io -u <your-gh-username> # paste the PAT
140+
docker push ghcr.io/<your-gh-username>/overup-runner:latest
141+
```
142+
143+
### Verifying what a REGISTRY holds, without Docker
144+
145+
You can prove what is actually published on GHCR from any machine with `curl` — this
146+
is how the stale image was caught in the wild (it had a post-merge timestamp and a
147+
pre-merge binary):
148+
149+
```bash
150+
# 1. Anonymous pull token (works because the package is public)
151+
TOKEN=$(curl -s "https://ghcr.io/token?service=ghcr.io&scope=repository:<user>/overup-runner:pull" \
152+
| sed -n 's/.*"token":"\([^"]*\)".*/\1/p')
153+
154+
# 2. Resolve :latest → per-arch manifest → list layers (the last one is the binary COPY layer)
155+
curl -s -H "Authorization: Bearer $TOKEN" \
156+
-H "Accept: application/vnd.oci.image.index.v1+json" \
157+
https://ghcr.io/v2/<user>/overup-runner/manifests/latest
158+
159+
# 3. Download the last layer blob, gunzip it, and grep the tar for the marker string
160+
curl -s -L -H "Authorization: Bearer $TOKEN" \
161+
https://ghcr.io/v2/<user>/overup-runner/blobs/<last-layer-digest> | gunzip -c \
162+
| grep -c "checkout complete (" # 1+ = fixed binary is published
163+
```
164+
165+
## 4. Roll it out — a restart is NOT enough
166+
167+
On the VPS (skip the pull if you built directly on the server's daemon):
168+
169+
```bash
170+
docker pull ghcr.io/<your-gh-username>/overup-runner:latest
171+
```
172+
173+
Then, in the Overup UI: **Runners page → revoke each hosted runner → create new
174+
ones** (same labels, e.g. the defaults `self-hosted,linux,x64,ubuntu-latest`). The
175+
provisioner pulls the registry before every provision (falling back to the local
176+
image only if the pull is denied), so newly created runners get the new image.
177+
178+
Why revoke + recreate: a Docker container is bound to the image ID it was created
179+
from. `docker restart`, a backend redeploy, and the janitor's stopped-container
180+
restarts all keep the **old** image. Only container re-creation rebinds `:latest`.
181+
182+
Sanity check on the VPS that the running runner really moved:
183+
184+
```bash
185+
docker images --format '{{.ID}}' ghcr.io/<your-gh-username>/overup-runner:latest
186+
docker ps --format '{{.Names}}\t{{.Image}}' # find the overup-runner-… container
187+
docker inspect <runner-container> --format '{{.Image}}' # must match the image ID above
188+
```
189+
190+
## 5. Verify end to end
191+
192+
Dispatch any pipeline and read the job log. Success looks exactly like this, in this
193+
order:
194+
195+
```
196+
downloading repository archive
197+
pulling image catthehacker/ubuntu:act-latest
198+
container started (ab12cd34ef56)
199+
checkout complete (137 files)
200+
▶ step 1/4: Install dependencies
201+
```
202+
203+
…and the step finds its files (`/workspace/package.json` exists). If the log still
204+
shows `checkout complete` (no count) before `pulling image`, one of §2–§4 was skipped
205+
or done against the wrong machine/daemon — walk them again in order.
206+
207+
The hardened runner also closes the *silent* variant of this failure permanently:
208+
209+
- The repackaged source tar is **counted** — a tarball that filters down to zero
210+
files fails the job (`checkout_failed`, log: `repository archive contained no
211+
usable files`) instead of uploading an empty archive and logging success.
212+
- Tarballs whose entries carry a leading `./` are handled (the wrapper directory is
213+
stripped, not the no-op dot), so files can't land at `/workspace/<repo-sha>/…`.
214+
- `checkout complete (N files)` makes delivery observable in every job log.
215+
216+
## 6. The containerd `Lchown … no such file or directory` pull error
217+
218+
```
219+
image pull failed: Docker stream error: failed to extract layer
220+
(application/vnd.docker.image.rootfs.diff.tar.gzip sha256:…) to overlayfs as "extract-…":
221+
failed to Lchown "/var/lib/containerd/io.containerd.snapshotter.v1.overlayfs/…"
222+
for UID 0, GID 0: … no such file or directory
223+
```
224+
225+
This is the **Docker host** failing to unpack an image layer under the containerd
226+
snapshotter — not an Overup bug, and typically transient (the same pull often
227+
succeeds on retry). Known causes, in likelihood order for a VPS:
228+
229+
1. **Disk pressure** — `catthehacker/ubuntu:act-latest` needs several GB to extract;
230+
an ENOSPC mid-extraction surfaces as bizarre `Lchown`/`no such file` errors, not
231+
always as "no space left on device".
232+
2. **Leftover partial-pull state** — a cancelled/failed pull leaves snapshotter and
233+
content-store data that `docker system prune` cannot always clear
234+
(containerd/containerd#10548).
235+
3. **Nested/loopback filesystems** — running the daemon on overlay-on-overlay
236+
(LXC/rootless setups) breaks layer extraction (containerd/containerd#2402,
237+
moby/moby#43576). `/var/lib/containerd` needs a real ext4, or xfs with `ftype=1`.
238+
239+
Host healing sequence:
240+
241+
```bash
242+
df -h /var/lib/docker /var/lib/containerd # several GB free?
243+
docker system df
244+
docker system prune -af # then clear partial-extract state:
245+
sudo systemctl restart docker
246+
docker pull catthehacker/ubuntu:act-latest # must extract cleanly now
247+
```
248+
249+
> **Careful:** on a Dokploy-style host the daemon restart re-creates
250+
> `/var/run/docker.sock` and drops the uid-10001 ACL unless the systemd drop-in from
251+
> [fix-hosted-runner-docker-socket.md](./fix-hosted-runner-docker-socket.md) §2 is in
252+
> place — that is the `connected but ping failed` regression. Verify
253+
> `getfacl /var/run/docker.sock` still lists `user:10001:rw-` after the restart.
254+
255+
Two platform mitigations make this class of failure non-fatal going forward:
256+
257+
- **Pre-pull warm-up** — `RUNNER_PREPULL_IMAGES` (default: the default job image)
258+
pulls job images into the daemon on every provisioner (re)connect, so the common
259+
`pulling_image` stage is a cache hit instead of a multi-GB network+extract.
260+
- **Local-image fallback in the runner** — when a job's image pull errors but the
261+
daemon already holds the image, the job logs
262+
`image pull failed (…); using locally cached image` and proceeds. Only a pull
263+
failure with **no** local copy fails the job (`image_pull_failed`).
264+
265+
## 7. `cargo: not found` — pick the right JOB image per toolchain
266+
267+
`catthehacker/ubuntu:act-latest` (the default job image, and what `runs-on:
268+
ubuntu-latest` maps to) is deliberately a **medium** image: Node.js, Python, git,
269+
build-essential — enough for most actions at a fraction of GitHub's runner size. It
270+
does **not** include Rust, Go, Java, or .NET. The
271+
[catthehacker/docker_images](https://github.com/catthehacker/docker_images) catalog
272+
publishes per-toolchain variants: `rust-latest` (rustfmt, clippy, cbindgen),
273+
`js-latest`, `go-latest`, `java-tools-latest`, `pwsh-latest`, and `full-latest`
274+
(GitHub's full hosted-runner toolcache — ~60 GB extracted; not practical on a VPS).
275+
276+
How Overup chooses a job's image (`backend/src/services/pipeline_plan.rs`), highest
277+
precedence first:
278+
279+
1. the job's **`container:`** key (string or `{image: …}` map), when it is a valid
280+
image reference;
281+
2. the **`runs-on` label map** (`ubuntu-latest`/`ubuntu-24.04`/… →
282+
`catthehacker/ubuntu:act-*`);
283+
3. the **`DEFAULT_JOB_IMAGE`** env (itself defaulting to
284+
`catthehacker/ubuntu:act-latest`).
285+
286+
So a Rust job needs exactly one line in its workflow YAML:
287+
288+
```yaml
289+
jobs:
290+
build:
291+
runs-on: ubuntu-latest
292+
container: ghcr.io/catthehacker/ubuntu:rust-latest # or rust:1-bookworm (official, smaller)
293+
steps:
294+
- run: cargo build --release
295+
```
296+
297+
The only no-YAML alternative is installing the toolchain as the job's first step —
298+
correct but slow, since it re-downloads every run:
299+
300+
```bash
301+
curl --proto '=https' --tlsv1.2 -sSf https://sh.rustup.rs | sh -s -- -y
302+
. "$HOME/.cargo/env"
303+
```
304+
305+
Whatever image a job pins, add it to `RUNNER_PREPULL_IMAGES` (comma-separated) so it
306+
is warmed into the daemon instead of pulled mid-pipeline.
307+
308+
## 8. Troubleshooting quick reference
309+
310+
| Symptom | Diagnosis | Fix |
311+
| --- | --- | --- |
312+
| `checkout complete` (no file count) **before** `pulling image` | Old runner binary is executing | §2–§4, in order |
313+
| Rebuilt + pushed, jobs still old | Image built from a stale clone (fresh timestamp, old binary) | §2 `git log` check, §3 grep check |
314+
| Pulled new image on VPS, jobs still old | Runner containers were restarted, not re-created | §4 revoke + re-create |
315+
| `checkout failed: repository archive contained no usable files` | New binary working as designed: the tarball filtered to zero files (unexpected layout) | Inspect the repo/tarball; this replaces the old silent-empty behavior |
316+
| `image pull failed (…); using locally cached image` (job continues) | New binary tolerating a transient pull failure | Nothing — informational; heal the host per §6 when frequent |
317+
| `failed to extract layer … Lchown … no such file or directory` | Docker-host snapshotter state | §6 |
318+
| `sh: 1: <tool>: not found` in a step | Job image lacks the toolchain | §7 |
319+
| GitHub Actions runs all end `startup_failure` at 0s (even Dependabot) | Private-repo Actions billing block | github.com → Settings → Billing: valid payment method + non-zero Actions spending limit |
320+
| `connected but ping failed` provisioner warn after `systemctl restart docker` | Socket ACL dropped by the daemon restart | [fix-hosted-runner-docker-socket.md](./fix-hosted-runner-docker-socket.md) §2 |

0 commit comments

Comments
 (0)