From f6b1834ea9b1d58b69d56690989dd3a3b663bee7 Mon Sep 17 00:00:00 2001 From: jochen Date: Tue, 1 Sep 2026 09:53:08 +0200 Subject: [PATCH] =?UTF-8?q?024=20fixed=20=E2=80=94=20the=20registry=20was?= =?UTF-8?q?=20addressed=20by=20hand=20and=20nothing=20else=20was?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The cause was one line. Machines get a systemd-networkd unit with a static address, so networkd finishes and reports the link configured. The registry ran `ip addr add` inline, which leaves networkd waiting to configure something it was never told about — and systemd-networkd-wait-online has an infinite timeout. So network-online.target was never reached and everything ordered after it never started. On these machines that is Docker, so `docker load` blocked on a socket whose daemon was queued behind a target that would never come, and three bounded timeouts stacked to thirty-five minutes. These machines have no DHCP by design, so that wait was never going to end. The hypothesis in this record was wrong and the record now says so. Stocking had just been changed, so stocking looked guilty; stocking takes 34 seconds and always did, timed directly before changing anything. Fixed with two things that made it cost hours instead of minutes: an image placement now waits for the runtime and refuses after 120s naming what systemd is waiting on, and the end-to-end test passes onProgress — the raise reported every step and the test discarded it, which is why thirty-five minutes 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 flagging a path as a credential because `/` is in the base64 alphabet. Also recorded: a redirected log lags, because Node block-buffers stdout to a file. Read as a stall twice, the second time right after the real fix — where a buffering artifact argues the fix did not work. --- .../00-report.md | 68 +++++++++++++++---- 1 file changed, 53 insertions(+), 15 deletions(-) diff --git a/04-ISSUES/024-a-lab-run-stalls-before-the-host-is-placed/00-report.md b/04-ISSUES/024-a-lab-run-stalls-before-the-host-is-placed/00-report.md index 037910b..8601342 100644 --- a/04-ISSUES/024-a-lab-run-stalls-before-the-host-is-placed/00-report.md +++ b/04-ISSUES/024-a-lab-run-stalls-before-the-host-is-placed/00-report.md @@ -1,8 +1,8 @@ --- -status: open +status: fixed opened: 2026-09-01 located-in: [mesh-lab] -fixed-by: +fixed-by: mesh-lab 3503ad9 amended-design: --- @@ -29,16 +29,15 @@ the host. It was stuck earlier, in stocking the scenario's registry. - **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 +## What changed just before — *and it was not the cause* -The rebuild step went from two artifacts to six — the suite now builds every image the run uses, -rather than the control plane's alone -([`005`](../005-pipeline-test-harness-unbuildable/00-report.md)'s family, fixed the same day). More -images are built, and every one of them is then pushed into the scenario's own registry, which is -the step the second stall was sitting in. +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. -That is a strong coincidence and not yet a diagnosis. It is written down as what changed, not as -the answer. +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 @@ -60,9 +59,48 @@ somebody may believe. - **A stated timeout on stocking**, so a stall ends as a failure with a reason rather than as a process somebody eventually kills. -## What was done instead, for now +## The cause -The run was stopped by hand and the instances removed. The gate that does not need a hypervisor — -`make check` in `mesh-control`, against a real PostgreSQL — is green, and the last complete run of -this suite was 21 of 24 with every failure diagnosed. **Neither of those covers what this suite -covers**, which is the point of the suite. +**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.*