From 8bd0ca0bdcf7b4779d96201610d020f7cef55b3e Mon Sep 17 00:00:00 2001 From: jochen Date: Wed, 30 Sep 2026 21:38:45 +0200 Subject: [PATCH] Issue 175: an announcement queued behind a long build came back, and the build ran again --- .../00-report.md | 62 +++++++++++++++++++ 1 file changed, 62 insertions(+) create mode 100644 04-ISSUES/175-an-announcement-behind-a-long-build-comes-back/00-report.md diff --git a/04-ISSUES/175-an-announcement-behind-a-long-build-comes-back/00-report.md b/04-ISSUES/175-an-announcement-behind-a-long-build-comes-back/00-report.md new file mode 100644 index 0000000..6b8220b --- /dev/null +++ b/04-ISSUES/175-an-announcement-behind-a-long-build-comes-back/00-report.md @@ -0,0 +1,62 @@ +--- +status: resolved +opened: 2026-09-30 +located-in: [mesh-controller internal/broker/streams.go (the controller's EVENTS consumer), mesh-controller internal/link/receive_nats.go] +fixed-by: mesh-controller PR 173 (MaxAckPending 1 on the controller's events consumer); the packaging module's rebuild record and the status count remain open in the text below +amended-design: +--- + +# 175 — An announcement queued behind a long build comes back, and the build runs again + +## What was observed + +On the evening of 2026-09-30 five merges landed within minutes. The controller's log then showed the +same four announcements — two into this repository, one into the catalogue, one into the controller's +own — arriving again every couple of minutes, and each arrival of the controller's rebuilt the two +modules that package its source. The builder built `builder` and `route-proxy` five times over for one +merge, the control node was pushed after each, and every other message the controller handles waited +behind the builds. It looked like a slow mesh; it was a loop. + +Earlier the same evening, at a lower rate, the log already carried duplicated lines — a merge seen +twice, a module "moved" twice — that nobody read as a symptom. + +## Why + +The controller acts on what it consumes in **one loop, one message at a time**, and a merge's handler +builds every module the merge changed before it returns — minutes of work. The bus's acknowledgement +window is thirty seconds. That contradiction was met once already: the message being worked on is kept +alive by a heartbeat while its handler runs +([issue 127](../127-a-shared-delivery-subject-is-not-a-per-consumer-queue/00-report.md)'s stretch, +controller PR 122). **The heartbeat covers one message.** The consumer is a push consumer with no +bound on what it may have outstanding, so the client is handed everything that is waiting at once; the +messages queued behind the one being built time out unacknowledged, come back after thirty seconds, +and are handled again when the loop gets to them — including the merge whose builds are already done, +which builds them again. A module that only *packages* another repository's source has no record of +which commit it was last rebuilt for, so nothing says "already done". + +## Why it matters beyond this instance + +The design permits work to be done twice, silently, and the doubling scales with how busy the mesh +is: the busier the builder, the longer the queue, the more that comes back. A push to a machine is +idempotent and a rebuild produces the same digest, so nothing broke — but every merge cost several +builds, the control node was pushed after each, and a person watching saw a mesh that would not +settle. It was the redelivery storm of 2026-09-28 in a narrower form, one layer out. + +## What would have prevented it + +- **A consumer that is handled one at a time is delivered one at a time.** `MaxAckPending: 1` on the + controller's events consumer: the server holds the rest, nothing times out behind a build, and the + heartbeat that keeps one message alive is then keeping *the* message alive. +- **A packaging module records the commit it was last rebuilt for**, so a replayed announcement is + "already built from it", the answer the source-built modules already give. +- **A log line that appears twice with the same commit is a symptom**, and the check is cheap: the + same announcement acted on twice within its window is a count worth exposing in `status`. + +## Resolved on the first remedy, 2026-09-30 + +`MaxAckPending: 1` on the controller's events consumer (mesh-controller PR 173): the server hands the +controller one announcement at a time and holds the rest, so nothing times out behind a build. The +existing consumer is brought to that configuration by the assertion the controller makes at start. +The second and third remedies — a packaging module recording the commit it was last rebuilt for, and +a doubled announcement counted in `status` — are not built; they would make the same fault visible +and cheaper should the first ever be undone, and they are left here as what to reach for then.