Merge pull request 'An apply says what it held, not only what it applied' (#52) from fix/125-a-hold-is-a-line-in-the-report into main

novox/hq 04-ISSUES/125. An adopted node keeps what it found until its
module is taken, which is correct and was recorded only in the node's own
state file. On the edge cut-over the mesh sent 346 resources, the journal
said it applied 330, and nothing anywhere said which sixteen or why —
reading it meant opening state.json by hand, and not reading it took every
public name on the machine down.

The line that reports the apply now carries it, grouped by module and
ordered by name, because the sentence an operator needs is "route-proxy is
assigned and not taken" and the module is the thing `take` acts on. An
apply that held nothing says nothing extra: a line that reports "0 held"
on every converged apply is a line that stops being read.

cmd/mesh-host/main.go

@@ -706,15 +706,18 @@ func enrol(ctx context.Context, opts options) error {
 	fmt.Printf("  signing key         %s\n",
 		base64.StdEncoding.EncodeToString(token.Signer)[:16]+"...")
 
-	// The check that has to happen before this machine says anything.
+	// **The pin is checked by the connection that presents this token, not by a dial of our own**
-	conn, err := link.Dial(token.Broker, token.Fingerprint, opts.timeout)
+	// (novox/hq 04-ISSUES/146). This opened a raw TLS connection to the bus first, which worked
-	if err != nil {
+	// against the broker the mesh used to run and cannot work against the one it runs now: NATS
-		return err
+	// speaks its own protocol before it upgrades to TLS, so an immediate handshake is answered
-	}
+	// with a plaintext line and the enrolment failed with "first record does not look like a TLS
-	defer conn.Close()
+	// handshake" — on every node that has tried to join since the bus changed, which is why this
-	fmt.Println("\nthe broker presented the certificate this token pins")
+	// went unnoticed: none had.
-
+	//
-	conn.Close()
+	// What ADR 0004 requires still holds, and holds better: the client that presents the token
+	// carries the same pinned configuration, reads the server's greeting, upgrades, and the
+	// verification runs inside that handshake — so the one-time secret is sent only after the
+	// certificate has been checked, and nothing of this node's reaches an impostor.
 
 	mine, err := identity.Generate(*name)
 	if err != nil {
@@ -788,10 +791,16 @@ func enrol(ctx context.Context, opts options) error {
 	proof := mine.Sign(link.EnrolProof(token.Secret, mine.Public, mine.Overlay.Public,
 		sealing.Public, serving.Public))
 	// The token says where to go and which certificate that address must present. It says nothing
-	// about which bus is there, and does not need to: every token names the one the mesh runs on
+	// about which bus is there, and does not need to: there is one, and this host knows which
-	// today until the rollout (novox/hq ADR 0116 step 5), and that is what an empty Transport is.
+	// (novox/hq ADR 0131 — the mesh speaks to one seat and the old transport is gone).
+	//
+	// **It used to leave this empty** and mean "whatever the mesh runs today", which was true
+	// while two buses existed and became a refusal the moment one did: an empty transport is not
+	// the bus's name, so every enrolment ended at "this token is for the \"\" bus"
+	// (novox/hq 04-ISSUES/146). Nothing caught it because nothing had enrolled since the bus
+	// changed.
 	reply, err := link.Enrol(ctx,
-		link.Approach{Address: token.Broker, Fingerprint: token.Fingerprint},
+		link.Approach{Address: token.Broker, Fingerprint: token.Fingerprint, Transport: link.OnNATS},
 		*name, token.Secret,
 		mine.Public, mine.Overlay.Public, sealing.Public, serving.Public, reported, proof, found,
 		opts.timeout)
@@ -1246,6 +1255,21 @@ func applyDeclared(ctx context.Context, opts options, raw []byte, sched *apply.S
 	return applyAndKeep(ctx, opts, raw, nil, sched, say)
 }
 
+// announceOr is what the apply writes its detail with, given what the caller has to say things with.
+//
+// **Never nil.** This argument was nil on the serving path, and nil is silence: everything the apply
+// says — a file held, a container replaced, the found firewall retired — was visible when a person ran
+// the one-shot command and discarded in the way the host actually runs (novox/hq 04-ISSUES/143).
+//
+// Named rather than written inline at the call site so both paths reach the apply the same way, and so
+// a reader asking "where does the apply's output go" finds one answer.
+func announceOr(say link.Announce) func(string) {
+	if say == nil {
+		return func(string) {}
+	}
+	return say
+}
+
 // applying serialises applies within this process.
 //
 // **Two things apply here: the link and the reconcile loop**, and each reads the node's state,
@@ -1308,8 +1332,18 @@ func applyAndKeep(ctx context.Context, opts options, raw []byte, signed *store.D
 
 	// Declared, not carried. A declaration from the mesh removes only what the mesh previously
 	// declared — never what this machine raised for itself from its bundle (04-ISSUES/010).
+	// **What the apply says goes to the console, which is the journal when this runs as a service.**
+	//
+	// It was nil, and nil is silence. The one-shot path has always passed a real one, so every detail
+	// the apply produces — a file held, a container replaced, the found firewall retired — was visible
+	// when a person ran it by hand and discarded in the way the host actually runs. Measured: after a
+	// machine was converged and its found firewall was not retired, what the host decided was
+	// unrecoverable, because it had said it to nobody (novox/hq 04-ISSUES/143).
+	//
+	// `say` already reaches stdout, and the launcher's unit sends that to the journal, so this needs
+	// no new mechanism — only for the argument to be passed.
 	outcome, updated, applyErr := apply.ApplyKeeping(ctx, built, declared, known, store.OriginDeclared,
-		apply.ExecRunner, nil, sealOpener(opts.state), apply.KeepIn(filepath.Dir(opts.state)))
+		apply.ExecRunner, announceOr(say), sealOpener(opts.state), apply.KeepIn(filepath.Dir(opts.state)))
 
 	// The mode the mesh said, recorded whichever way the apply went: the declaration is kept
 	// either way, and the node is held to it from the next reconcile (novox/hq ADR 0100).

cmd/mesh-host/main_test.go

@@ -568,3 +568,28 @@ func TestAConvergedMachineSaysItsOutwardLinksUnasked(t *testing.T) {
 		t.Fatal("a refused report is offered as news about the machine")
 	}
 }
+
+// **A host running as a service says what its apply did.**
+//
+// The serving path passed nil where the apply writes its detail, and nil is silence. The one-shot path
+// has always passed a real function, so everything the apply says was visible when a person ran it by
+// hand and discarded in the way the host actually runs. Measured before this was written: a machine was
+// converged, its found firewall was not retired, and what the host decided was unrecoverable because it
+// had been said to nobody (novox/hq 04-ISSUES/143).
+//
+// This asserts only that the apply's log is never nil and that a line reaches what the caller gave.
+// **It cannot catch the fault it was written for** — a call site passing nil directly — because that is
+// wiring, and wiring is only proved by running the thing. That proof is a deployed host whose journal
+// carries the apply's detail, which is how this fix was verified.
+func TestTheApplysLogIsNeverNil(t *testing.T) {
+	if announceOr(nil) == nil {
+		t.Fatal("a host with nowhere to say things got a nil log, which the apply will call")
+	}
+	announceOr(nil)("this goes nowhere and must not panic")
+
+	var said []string
+	announceOr(func(line string) { said = append(said, line) })("  disabled ufw")
+	if len(said) != 1 || !strings.Contains(said[0], "disabled ufw") {
+		t.Fatalf("the apply's detail did not reach the caller's announce: %v", said)
+	}
+}

examples/foundation-first-node-nats.lock

@@ -127,12 +127,21 @@
     {
       "id": "bus-certificate",
       "type": "action",
-      "command": ["docker", "run", "--rm", "--entrypoint", "sh", "-v", "mesh-broker-tls:/tls",
+      // **The mesh makes its own** (novox/hq 04-ISSUES/146). This ran `openssl` inside the
-                  "192.0.2.250:5000/nats@sha256:b83efabe3e7def1e0a4a31ec6e078999bb17c80363f881df35edc70fcb6bb927",
+      // broker's image while the broker was one that carried it; the bus that replaced it has a
-                  "-c", "test -f /tls/tls.crt || (openssl req -x509 -newkey rsa:2048 -nodes -keyout /tls/tls.key -out /tls/tls.crt -days 3650 -subj '/CN=mesh-broker' -addext 'subjectAltName=DNS:mesh-broker,IP:127.0.0.1' >/dev/null 2>&1 && chmod 644 /tls/tls.crt && chmod 600 /tls/tls.key)"],
+      // shell and no openssl, and no other image the bundle names has one either. So the program
-      "verify": ["docker", "run", "--rm", "--entrypoint", "sh", "-v", "mesh-broker-tls:/tls",
+      // that needs the certificate writes it — already on this machine, since the schema step ran
-                 "192.0.2.250:5000/nats@sha256:b83efabe3e7def1e0a4a31ec6e078999bb17c80363f881df35edc70fcb6bb927",
+      // it, and asking nothing of the image it writes into. Self-signed on purpose: a host pins
-                 "-c", "test -s /tls/tls.crt && openssl x509 -in /tls/tls.crt -noout"]
+      // this server's exact certificate (novox/hq ADR 0004), and at this moment there is no mesh
+      // to ask an authority of.
+      // `--user 0:0` because the volume is root's and this image runs as nobody, which is right
+      // for the long-running control plane and wrong for a one-shot writing into a fresh volume.
+      "command": ["docker", "run", "--rm", "--user", "0:0", "-v", "mesh-broker-tls:/tls",
+                  "192.0.2.250:5000/mesh-controller@sha256:c67db38439ff0aee242b467486765467bb95801f52175fc5727cc4e437338ace",
+                  "broker", "certificate", "--into", "/tls"],
+      "verify": ["docker", "run", "--rm", "--user", "0:0", "-v", "mesh-broker-tls:/tls",
+                 "192.0.2.250:5000/mesh-controller@sha256:c67db38439ff0aee242b467486765467bb95801f52175fc5727cc4e437338ace",
+                 "broker", "certificate", "--check", "--into", "/tls"]
     },
     {
       "id": "bus-conf-dir",

internal/link/held_note_test.go

@@ -0,0 +1,46 @@
+package link
+
+import (
+	"strings"
+	"testing"
+)
+
+// The count that did not add up was the only symptom sixteen held resources had, and reading it meant
+// opening the node's state file by hand (novox/hq 04-ISSUES/125). The line that says what an apply did
+// says what it did not, too.
+
+func TestTheApplyLineSaysWhatItHeldAndForWhichModule(t *testing.T) {
+	got := heldNote([]Held{
+		{ID: "ca", Module: "route-proxy", Kind: "directory"},
+		{ID: "certs", Module: "route-proxy", Kind: "directory"},
+		{ID: "server", Module: "route-proxy", Kind: "container"},
+		{ID: "mail", Module: "mailu", Kind: "container"},
+	})
+	if !strings.Contains(got, "4 held") {
+		t.Fatalf("the count of what was held is not in the line: %q", got)
+	}
+	// The module is the thing an operator can act on: `take` takes a module.
+	if !strings.Contains(got, "route-proxy: 3") || !strings.Contains(got, "mailu: 1") {
+		t.Fatalf("the line does not break the holds down by module: %q", got)
+	}
+	// Ordered, so two machines holding the same things read the same and a diff of two reports is
+	// about what changed.
+	if strings.Index(got, "mailu") > strings.Index(got, "route-proxy") {
+		t.Fatalf("modules are not in a stated order: %q", got)
+	}
+	// It says why, because "held" alone reads as a failure and this is correct behaviour.
+	if !strings.Contains(got, "taken") {
+		t.Fatalf("the line does not say a hold ends when the module is taken: %q", got)
+	}
+}
+
+func TestAnApplyThatHeldNothingSaysNothingExtra(t *testing.T) {
+	// A converged machine holds nothing, which is most applies. Reporting "0 held" on every one of
+	// them is how a line stops being read.
+	if got := heldNote(nil); got != "" {
+		t.Fatalf("an apply with no holds added %q to its line", got)
+	}
+	if got := heldNote([]Held{}); got != "" {
+		t.Fatalf("an apply with no holds added %q to its line", got)
+	}
+}

internal/link/pinned.go

@@ -73,8 +73,19 @@ func PinnedConfig(pin string) (*tls.Config, error) {
 	}, nil
 }
 
-// Dial opens a TLS connection to the broker, refusing anything but the pinned certificate.
+// dialPinned completes a TLS handshake against an address, refusing anything but the pinned
-func Dial(address, pin string, timeout time.Duration) (*tls.Conn, error) {
+// certificate.
+//
+// **Not how the bus is reached, and it used to be** (novox/hq 04-ISSUES/146). Enrolment opened one
+// of these before it said anything, which was right while the broker answered TLS immediately and
+// wrong the moment the mesh moved to a bus that speaks its own protocol first. The pin itself was
+// never the problem — PinnedConfig is what the NATS client is given, and the verification runs
+// inside the handshake that client performs.
+//
+// It stays here because this is where the pin is proven: the tests beside it run a real TLS server
+// and assert that a wrong certificate is refused before a byte of application data is sent. What it
+// must not become again is something a caller uses to reach the bus.
+func dialPinned(address, pin string, timeout time.Duration) (*tls.Conn, error) {
 	config, err := PinnedConfig(pin)
 	if err != nil {
 		return nil, err
@@ -86,7 +97,7 @@ func Dial(address, pin string, timeout time.Duration) (*tls.Conn, error) {
 		if errors.Is(err, ErrWrongCertificate) {
 			return nil, err
 		}
-		return nil, fmt.Errorf("cannot reach the broker at %s: %w", address, err)
+		return nil, fmt.Errorf("cannot reach %s: %w", address, err)
 	}
 	return conn, nil
 }

internal/link/pinned_test.go

@@ -63,7 +63,7 @@ func server(t *testing.T) (address string, fingerprint string) {
 
 func TestTheRightBrokerIsAccepted(t *testing.T) {
 	address, pin := server(t)
-	conn, err := Dial(address, pin, 5*time.Second)
+	conn, err := dialPinned(address, pin, 5*time.Second)
 	if err != nil {
 		t.Fatalf("the broker its token describes was refused: %v", err)
 	}
@@ -76,7 +76,7 @@ func TestADifferentBrokerIsRefused(t *testing.T) {
 	address, _ := server(t)
 	_, other := server(t)
 
-	_, err := Dial(address, other, 5*time.Second)
+	_, err := dialPinned(address, other, 5*time.Second)
 	if err == nil {
 		t.Fatal("a broker presenting a different certificate was accepted")
 	}
@@ -130,7 +130,7 @@ func TestNothingIsSentToTheWrongBroker(t *testing.T) {
 
 	// A pin for a certificate this server does not have.
 	_, elsewhere := server(t)
-	if _, err := Dial(listener.Addr().String(), elsewhere, 5*time.Second); err == nil {
+	if _, err := dialPinned(listener.Addr().String(), elsewhere, 5*time.Second); err == nil {
 		t.Fatal("the impostor was accepted")
 	}
 	if n := <-received; n > 0 {
@@ -160,7 +160,7 @@ func TestAnUnreachableBrokerIsAnOrdinaryFailure(t *testing.T) {
 	address := listener.Addr().String()
 	listener.Close()
 
-	_, err = Dial(address, pin, 2*time.Second)
+	_, err = dialPinned(address, pin, 2*time.Second)
 	if err == nil {
 		t.Fatal("dialling a closed port succeeded")
 	}

internal/link/run.go

@@ -6,6 +6,8 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"sort"
+	"strings"
 	"time"
 )
 
@@ -250,9 +252,11 @@ func Run(ctx context.Context, m Membership, apply Applier, say Announce, timeout
 			case report.Refused != "":
 				say("refused a declaration: " + report.Refused)
 			case len(report.Failed) > 0:
-				say(fmt.Sprintf("applied %d and failed: %v", len(report.Applied), report.Failed))
+				say(fmt.Sprintf("applied %d and failed: %v%s",
+					len(report.Applied), report.Failed, heldNote(report.Held)))
 			default:
-				say(fmt.Sprintf("applied %d resource(s)", len(report.Applied)))
+				say(fmt.Sprintf("applied %d resource(s)%s",
+					len(report.Applied), heldNote(report.Held)))
 			}
 			publishReport(ctx, link, m, report, say, timeout)
 			// Settled after the report is published. A node that dies between applying and
@@ -392,3 +396,36 @@ func publishAlive(ctx context.Context, bus Bus, m Membership, say Announce,
 		say("could not tell the mesh this node is here: " + err.Error())
 	}
 }
+
+// heldNote is what this apply did NOT do, for the line that says what it did.
+//
+// **A count that does not add up is the only symptom a held resource had** (novox/hq 04-ISSUES/125).
+// An adopted node keeps what it found until its module is taken (ADR 0100), and that is correct — but
+// it was recorded only in the node's own state file. On the edge cut-over the mesh sent 346 resources,
+// the journal said it applied 330, and nothing anywhere said which sixteen or why. Reading it took
+// opening state.json by hand; not reading it took every public name on the machine down, because the
+// operator had four green surfaces and a discrepancy nobody could interpret.
+//
+// So the line that reports the apply carries it. Grouped by module and ordered by name, because the
+// sentence an operator needs is "route-proxy is assigned and not taken", and the module is the thing
+// they can act on — `take` is the verb, and it takes a module.
+func heldNote(held []Held) string {
+	if len(held) == 0 {
+		return ""
+	}
+	byModule := map[string]int{}
+	for _, h := range held {
+		byModule[h.Module]++
+	}
+	names := make([]string, 0, len(byModule))
+	for name := range byModule {
+		names = append(names, name)
+	}
+	sort.Strings(names)
+	parts := make([]string, 0, len(names))
+	for _, name := range names {
+		parts = append(parts, fmt.Sprintf("%s: %d", name, byModule[name]))
+	}
+	return fmt.Sprintf(", %d held until their module is taken (%s)",
+		len(held), strings.Join(parts, ", "))
+}