Merge pull request 'Issue 266: a merge on the bus was never handed to the controller' (#123) from issues/266-a-merge-the-bus-never-handed-the-controller into main

2026-10-05 23:33:19 +00:00
parent 64c2d3a0a1 14dabf60ee
commit 3ba75a312b
1 changed files with 104 additions and 0 deletions
@@ -0,0 +1,104 @@
+---
+status: located
+opened: 2026-10-06
+located-in: [mesh-catalog, mesh-controller]
+fixed-by:
+amended-design:
+---
+
+# 266. A merge on the bus was never handed to the controller
+
+## Symptom
+
+A pull request was merged into the tools repository, which the runtime and the console are built
+from. Nothing was built. The runtime was then built by hand.
+
+The forge's poll said in its journal that it announced the merge, 19 seconds after it was made. The
+controller's journal has no line for it: no plan, and no "nothing the mesh holds reads it". The
+controller did log the merges just before and just after it, to other repositories, as it always
+does. It had restarted three minutes earlier, when a new controller was rolled out.
+
+## Evidence
+
+- **The announcement is on the bus.** The events stream holds it, on the merge subject, with the
+  merge commit and the files it changed.
+- **The controller's consumer is past it and holds nothing.** The controller's durable consumer on
+  the events stream has nothing pending and nothing unacknowledged. Its delivered and acknowledged
+  positions are past the announcement.
+- **It was never handed over.** Since the controller connected, the stream took 25 messages on the
+  consumer's subjects. The server's own count for the controller's subscription is 24 deliveries.
+  The consumer hands over one message at a time, and the next message, a build outcome, was handed
+  over and acted on 20 seconds after the merge. So the merge was not handed over and then lost by
+  the controller. No other subscriber to the consumer's delivery subject existed, then or since.
+- **Every way the controller could take it logs.** Acting on a merge, or refusing one, writes a line
+  in every case. An announcement the controller could not read, or one it did not recognise, would
+  be taken without a line, but this one has the subject and the body the controller expects. A
+  merge announced into another repository 8 minutes later was acted on and logged.
+- **It is not the first.** Across three days, 23 merges the poll announced have no matching line in
+  the controller's journal. Most of them fall in windows when the bus or the controller was being
+  replaced. This one does not.
+
+## Cause
+
+The bus server ran **nats 2.10.29**. On that release, a JetStream consumer with **more than one
+filter subject** sometimes moves its position past a matching message without delivering it. It
+does not count the message as pending, and it does not redeliver it. The controller's consumer has
+seven filters: merges, build outcomes, catalogue upgrades, a catalogue's catch-up, and the two
+provider standings. The controller acts only on what that consumer hands it. Nothing compares what
+was announced with what was acted on, so a skipped merge is silent.
+
+Reproduced outside the mesh with the server library. A stream shaped like the events stream, with
+a consumer configured exactly like the controller's, receives traffic like the mesh's: mostly build
+logs on new subjects, with the followed events among them.
+
+- On 2.10.29, a few percent of the followed events are never delivered, and the consumer has
+  nothing pending.
+- On the same release, a consumer with a single filter received every message.
+- On 2.11.17, 2.12.15 and 2.14.5, every message was delivered.
+
+Every module consumer with more than one filter on that bus is exposed in the same way. That
+includes the catalogue's consumer of build outcomes and every provider's consumer of provisioned and
+deprovisioned events.
+
+## Fix
+
+1. **mesh-catalog: the bus server runs 2.11.17.** The nats module's image is pinned by its
+   multi-architecture index digest. The Dockerfile now also states the release that digest is,
+   because a digest does not state it. 2.11.17 is the smallest step that delivers every message in
+   the reproduction. Moving to 2.11 is a one-way upgrade of the stream store, so plan it for when the
+   bus can be restarted.
+2. **mesh-controller: missed merges are caught up.** Every five minutes the controller reads the
+   last day of merge announcements back from the events stream. It reads them on an ordered consumer
+   of its own, filtered on the merge subject alone, which acknowledges nothing. For each announcement
+   older than ten minutes, it judges the merge the way acting on it would. A merge that was already
+   acted on reads as history, because acting marks every module the merge moved as looked at since.
+   A merge that would still move a module was never acted on. The controller says so, naming the
+   repository, the commit, how late it is and which modules are behind, and then acts on it. So no
+   record of which merges were handled is needed.
+
+   It only considers modules built from the merged repository. Modules that only package source
+   from that repository have no record that acting touched them, so they would always read as never
+   acted on. A merge that moves both kinds is caught through the first kind, and acting on it also
+   rebuilds the second. A merge older than a day is left to a person, because rebuilding it days
+   later would be a surprise.
+
+## How it is checked
+
+- mesh-catalog, `modules/nats/cmd/nats-tools`.
+  `TestAConsumerWithSeveralFiltersIsHandedEveryMessage` runs the reproduction above against the
+  server release the module's tests pin. It fails on 2.10.29 and passes on 2.11.17.
+  `TestTheImageIsTheServerTestedHere` fails if the release named in the Dockerfile differs from the
+  tested server's version. The first test is therefore a statement about the server the mesh runs.
+- mesh-controller, `cmd/mesh-controller`.
+  `TestAMergeTheBusNeverHandedOverIsActedOnLate` replays this incident: an announcement the
+  controller never acted on, among others that were acted on or that nothing reads. It is left to
+  the controller's own consumer for ten minutes. Then it is said and acted on once, and never
+  again. `TestAMissedMergeThatCouldNotBeActedOnIsTriedAgain` and
+  `TestAMergeOlderThanTheLookBackIsLeftAlone` check the edges. Reading the stream back was also
+  checked against an embedded 2.10.29 server holding exactly the controller's bus permissions.
+
+## Not covered
+
+If the forge's poll never announces a merge at all, the catch-up has nothing to read. The poll keeps
+its own record of what it announced, so a restart of the poll does not lose merges. A poll that is
+down for longer than a day would still lose them.