jschoubben
36d9b38a0d
The playbook, the README and the status skill knew five statuses; the cycle check knew a sixth, 'fixed', and not 'wontfix'. Eleven issues sat in the sixth for weeks with their fixes shipped, one step short of closed. They are resolved; the check refuses the word from now on and accepts the one the playbook allows.
107 lines
5.1 KiB
Markdown
107 lines
5.1 KiB
Markdown
---
|
|
status: resolved
|
|
opened: 2026-09-01
|
|
located-in: [mesh-lab]
|
|
fixed-by: mesh-lab 3503ad9
|
|
amended-design:
|
|
---
|
|
|
|
# 024 — A run stalls before the host is placed, and says nothing while it does
|
|
|
|
## Symptom
|
|
|
|
The first scenario of the end-to-end suite raises its machines and then stops. Observed twice on
|
|
2026-09-01, both times after the rebuild step grew:
|
|
|
|
- **Once mid-run**, during the rotation test: the suite had reported thirteen passes, then the
|
|
process ended with no summary, no failure and no receipt.
|
|
- **Once from the start**: `a bare machine becomes a mesh` ran for **35 minutes** against a
|
|
measured 4.5, produced no output at all, and was still running when it was stopped by hand.
|
|
|
|
Both machines were `RUNNING` throughout. The second one was interrogated directly: the anchor VM
|
|
answered, and had **no `mesh-host` log and no containers** — so the run had not reached placing
|
|
the host. It was stuck earlier, in stocking the scenario's registry.
|
|
|
|
## What is not the cause
|
|
|
|
- **Not memory.** 84 GiB available, no OOM in the kernel log.
|
|
- **Not the daemon.** `incus exec` into the stalled machine answered immediately.
|
|
- **Not the changes under test.** The credential work is applied after the host is placed, and the
|
|
host was never placed.
|
|
|
|
## What changed just before — *and it was not the cause*
|
|
|
|
The rebuild step had gone from two artifacts to six, and every image is pushed into the scenario's
|
|
registry, which looked like where the stall sat. That was written down as a coincidence rather
|
|
than a diagnosis, and it is as well: **stocking takes 34 seconds and always did.** Timed directly,
|
|
eight images, before anything was changed.
|
|
|
|
The suspicion was the ordinary kind — the thing that changed most recently looks guilty — and the
|
|
thing that changed had nothing to do with it.
|
|
|
|
## Why it matters more than a slow test
|
|
|
|
**A stall is indistinguishable from work.** The suite prints nothing between starting a scenario
|
|
and finishing its first test, so four and a half minutes and thirty-five look identical from the
|
|
outside — and the operator's only recourse is to guess, which is precisely how a workstation was
|
|
left unbootable in August by killing a package manager that was working.
|
|
|
|
The first stall is worse: the process ended *silently* after thirteen passes. No summary, no
|
|
receipt, nothing that says the run was cut short. A run that stops without saying so is a run
|
|
somebody may believe.
|
|
|
|
## What a fix has to give
|
|
|
|
- **Progress while stocking**, so a long step is visibly a long step. Bytes moved, images pushed,
|
|
anything that changes.
|
|
- **A receipt when a run is cut short**, saying how far it got. `lastrun` already refuses to guess;
|
|
what is missing is it being written at all when the process dies mid-run.
|
|
- **A stated timeout on stocking**, so a stall ends as a failure with a reason rather than as a
|
|
process somebody eventually kills.
|
|
|
|
## The cause
|
|
|
|
**The registry machine was addressed by hand and every other machine was not.**
|
|
|
|
Machines get a systemd-networkd unit with a static `Address=`, so networkd finishes configuring
|
|
the link and reports it `configured`. The registry instead ran `ip addr add` inline. An address
|
|
put on a link that way leaves networkd still waiting to configure something it was never told
|
|
about, so the link sits at `configuring` — and `systemd-networkd-wait-online` has
|
|
`TimeoutStartUSec=infinity`.
|
|
|
|
So `network-online.target` is never reached, and **everything ordered after it never starts.** On
|
|
these machines that is Docker. `docker load` then blocks on a socket whose daemon is queued behind
|
|
a target that will never come, and the three bounded timeouts around it — save, push, load — stack
|
|
to thirty-five minutes.
|
|
|
|
Measured on one scenario, before and after:
|
|
|
|
| | before | after |
|
|
|---|---|---|
|
|
| the registry's link | `configuring` | `configured` |
|
|
| `docker.service` | inactive, 5 jobs pending | active, no jobs |
|
|
| the raise | never finished | **87.5 s** |
|
|
|
|
These machines have **no DHCP by design** — a scenario is a closed address space and the
|
|
declaration owns the addresses — so nothing was ever going to complete that wait.
|
|
|
|
## Fixed
|
|
|
|
- **The registry is addressed the way every other machine is**, through the same helper.
|
|
- **Placing an image waits for the container runtime** and refuses after 120s, naming what systemd
|
|
is still waiting on. A stall becomes a failure that says why.
|
|
- **The end-to-end test passes `onProgress`.** The raise reported every step and the test threw it
|
|
away, which is why thirty-five minutes of silence and four minutes of silence looked the same.
|
|
|
|
The suite then ran to completion: **23 of 24**, the one failure a check of its own that flagged
|
|
`/var/lib/mesh/builder/broker` as a credential because `/` is in the base64 alphabet. Fixed with
|
|
it.
|
|
|
|
## Also learned, at some cost
|
|
|
|
**A redirected log lags.** Node block-buffers stdout when it is a file, so `> run.log` sits
|
|
unchanged for minutes while the run is fine. That was read as a stall twice — the second time
|
|
immediately after the real fix, where a buffering artifact argues the fix did not work. The
|
|
machines answer instantly and are the source of truth. *"I cannot see progress" is not evidence of
|
|
no progress.*
|