Keep what each machine did, so status can say what is wrong

A node reports back after applying a declaration: it worked, some of it
failed, or the whole thing was refused. A refusal or a failure moved
last_seen and the reason went to a log line — so "which machine is not
doing what it was told" had no answer the next morning, which is the
question a mesh exists to answer.

Refused and failed are kept as different things, because they are
different situations with different remedies: refused means the machine
is exactly as it was and what is wrong is in what was sent; failed means
it is in a state nobody declared and what is wrong is on the machine. One
word for both would make the record say less than the node did.

One row per node, replaced. The question is the machine's current state —
"this failed an hour ago and then succeeded" is not a machine anybody
needs to look at, and a table of every report would bury the ones that
matter under the ones that do not.

`status` now answers three questions in the order somebody asks them: is
anything broken, is anything not answering, is anything out of date. The
first has consequences now, the third is a plan for later, and a status
leading with the third would bury the first. A machine that has never
spoken is reported as quiet rather than as broken — new, switched off and
unreachable are not the same as tried and could not.

The mapping from a report to an outcome had no test at all, which the
injection caught: it is the code deciding which of those situations a
machine is in. It has four now, including that a partial report never
becomes the account of what the machine holds — the fault that destroyed
a substrate once.

cmd/mesh-control/main.go

@@ -1500,35 +1500,81 @@ func statusCommand(ctx context.Context) error {
 	}
 	defer inv.Close()
 
+	// Three questions, in the order somebody asks them: is anything broken, is anything not
+	// answering, is anything out of date. The first has consequences now, the second may, and
+	// the third is a plan for later — and a status that led with the third would bury the first.
+	wrong, err := inv.NotDoingWhatTheyWereTold(ctx)
+	if err != nil {
+		return err
+	}
+	if len(wrong) > 0 {
+		fmt.Printf("%d machine(s) are not doing what they were told:\n\n", len(wrong))
+		for _, d := range wrong {
+			fmt.Printf("  %-18s %-9s %s\n", d.Node, d.Outcome, d.At.Local().Format("2006-01-02 15:04"))
+			if d.Refused != "" {
+				// The host's own words. It says exactly what it could not accept, and nothing
+				// written here would say it better.
+				fmt.Printf("  %-18s %s\n", "", firstLine(d.Refused))
+			}
+			for _, f := range d.Failed {
+				fmt.Printf("  %-18s %s: %s\n", "", f.ID, firstLine(f.Error))
+			}
+		}
+		fmt.Println()
+	}
+
+	nodes, err := inv.Nodes(ctx)
+	if err != nil {
+		return err
+	}
+	var quiet []string
+	for _, n := range nodes {
+		// Never heard from, or not lately. Different from failing: a machine that says nothing
+		// may be new, switched off, or unreachable, and none of those is a machine that tried
+		// and could not.
+		if n.LastSeen.IsZero() || time.Since(n.LastSeen) > time.Hour {
+			quiet = append(quiet, n.Name+" ("+heardFrom(n)+")")
+		}
+	}
+	if len(quiet) > 0 {
+		fmt.Printf("%d machine(s) not heard from lately:\n  %s\n\n",
+			len(quiet), strings.Join(quiet, "\n  "))
+	}
+
 	behind, err := inv.Behind(ctx)
 	if err != nil {
 		return err
 	}
-	if len(behind) == 0 {
+	if len(behind) > 0 {
-		fmt.Println("every module with a source is built from what that source has")
+		var names []string
-		return nil
+		for m := range behind {
+			names = append(names, m)
+		}
+		sort.Strings(names)
+
+		fmt.Printf("%d module(s) behind their source:\n\n", len(behind))
+		for _, m := range names {
+			from, err := inv.SourceOf(ctx, m)
+			if err != nil {
+				return err
+			}
+			fmt.Printf("  %-18s holds %s, source has %s\n", m, short(from.BuiltFrom), short(from.Head))
+			if on := behind[m]; len(on) > 0 {
+				// The part somebody actually wants. A module being out of date is a fact about
+				// the catalogue; machines running the old one is the thing with consequences.
+				fmt.Printf("  %-18s running on %s\n", "", strings.Join(on, ", "))
+			} else {
+				fmt.Printf("  %-18s assigned to nothing\n", "")
+			}
+		}
+		fmt.Println()
 	}
 
-	var names []string
+	if len(wrong) == 0 && len(quiet) == 0 && len(behind) == 0 {
-	for m := range behind {
+		// Said plainly. "Nothing to report" and "nothing was checked" must never look the same,
-		names = append(names, m)
+		// and getting here means all three questions were asked and answered.
-	}
+		fmt.Printf("%d machine(s), all doing what they were told, all heard from, "+
-	sort.Strings(names)
+			"and every module current with its source\n", len(nodes))
-
-	fmt.Printf("%d module(s) behind their source:\n\n", len(behind))
-	for _, m := range names {
-		from, err := inv.SourceOf(ctx, m)
-		if err != nil {
-			return err
-		}
-		fmt.Printf("  %-20s holds %s, source has %s\n", m, short(from.BuiltFrom), short(from.Head))
-		if nodes := behind[m]; len(nodes) > 0 {
-			// The part somebody actually wants. A module being out of date is a fact about the
-			// catalogue; machines running the old one is the thing with consequences.
-			fmt.Printf("  %-20s running on %s\n", "", strings.Join(nodes, ", "))
-		} else {
-			fmt.Printf("  %-20s assigned to nothing\n", "")
-		}
 	}
 	return nil
 }

internal/inventory/doing_test.go

@@ -0,0 +1,157 @@
+package inventory
+
+import (
+	"context"
+	"strings"
+	"testing"
+)
+
+// What each machine did with what it was last sent.
+//
+// Until this, a refusal or a failure moved last_seen and the reason went to a log line — so
+// "which machine is not doing what it was told" had no answer the next morning, which is the
+// question a mesh exists to answer.
+
+func nodeNamed(t *testing.T, inv *Inventory, name string) string {
+	t.Helper()
+	n, err := inv.AddNode(context.Background(), name)
+	if err != nil {
+		t.Fatal(err)
+	}
+	return n.ID
+}
+
+func TestRefusedAndFailedAreDifferentSituations(t *testing.T) {
+	// Refused means the machine is exactly as it was, and what is wrong is in what was sent.
+	// Failed means it is in a state nobody declared, and what is wrong is on the machine. One
+	// word for both would make the report say less than the node did.
+	inv := fresh(t)
+	ctx := context.Background()
+	refuser := nodeNamed(t, inv, "refuser")
+	failer := nodeNamed(t, inv, "failer")
+
+	if err := inv.RecordDoing(ctx, refuser, Doing{
+		Outcome: OutcomeRefused, Refused: "resource \"x\": a file needs a path",
+	}); err != nil {
+		t.Fatal(err)
+	}
+	if err := inv.RecordDoing(ctx, failer, Doing{
+		Outcome: OutcomeFailed,
+		Failed:  []FailedResource{{ID: "svc", Error: "unit not found"}},
+		Applied: 4,
+	}); err != nil {
+		t.Fatal(err)
+	}
+
+	wrong, err := inv.NotDoingWhatTheyWereTold(ctx)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(wrong) != 2 {
+		t.Fatalf("got %d", len(wrong))
+	}
+	by := map[string]Doing{}
+	for _, d := range wrong {
+		by[d.Node] = d
+	}
+	if by["refuser"].Outcome != OutcomeRefused || !strings.Contains(by["refuser"].Refused, "needs a path") {
+		t.Fatalf("got %+v", by["refuser"])
+	}
+	if by["failer"].Outcome != OutcomeFailed || len(by["failer"].Failed) != 1 {
+		t.Fatalf("got %+v", by["failer"])
+	}
+	// And how much DID work, because "four of five" and "none of five" are different machines.
+	if by["failer"].Applied != 4 {
+		t.Fatalf("what did apply was not kept: %+v", by["failer"])
+	}
+}
+
+func TestAMachineDoingWhatItWasToldIsNotOnTheList(t *testing.T) {
+	inv := fresh(t)
+	ctx := context.Background()
+	id := nodeNamed(t, inv, "fine")
+	if err := inv.RecordDoing(ctx, id, Doing{Outcome: OutcomeApplied, Applied: 6}); err != nil {
+		t.Fatal(err)
+	}
+	wrong, err := inv.NotDoingWhatTheyWereTold(ctx)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(wrong) != 0 {
+		t.Fatalf("a machine that did as it was told is listed as wrong: %+v", wrong)
+	}
+	// It is still answerable about, which is a different question.
+	d, said, err := inv.DoingOf(ctx, "fine")
+	if err != nil || !said {
+		t.Fatalf("said=%v err=%v", said, err)
+	}
+	if d.Wrong() || d.Applied != 6 {
+		t.Fatalf("got %+v", d)
+	}
+}
+
+func TestTheLastReportReplacesTheOneBefore(t *testing.T) {
+	// The question is the machine's CURRENT state. "This failed an hour ago and then succeeded"
+	// is not a machine anybody needs to look at, and a table of every report would bury the ones
+	// that matter under the ones that do not.
+	inv := fresh(t)
+	ctx := context.Background()
+	id := nodeNamed(t, inv, "recovered")
+	if err := inv.RecordDoing(ctx, id, Doing{
+		Outcome: OutcomeFailed, Failed: []FailedResource{{ID: "a", Error: "no"}},
+	}); err != nil {
+		t.Fatal(err)
+	}
+	if err := inv.RecordDoing(ctx, id, Doing{Outcome: OutcomeApplied, Applied: 3}); err != nil {
+		t.Fatal(err)
+	}
+	wrong, err := inv.NotDoingWhatTheyWereTold(ctx)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(wrong) != 0 {
+		t.Fatalf("a machine that recovered is still listed as wrong: %+v", wrong)
+	}
+	d, _, _ := inv.DoingOf(ctx, "recovered")
+	if len(d.Failed) != 0 {
+		t.Fatalf("the old failure survived: %+v", d)
+	}
+}
+
+func TestAMachineThatHasSaidNothingIsNotWrong(t *testing.T) {
+	// It may be new, switched off, or unreachable. None of those is a machine that tried and
+	// could not, and treating silence as failure would have somebody debug a machine that has
+	// simply never been sent anything.
+	inv := fresh(t)
+	ctx := context.Background()
+	nodeNamed(t, inv, "silent")
+	wrong, err := inv.NotDoingWhatTheyWereTold(ctx)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(wrong) != 0 {
+		t.Fatalf("silence was read as failure: %+v", wrong)
+	}
+	if _, said, err := inv.DoingOf(ctx, "silent"); err != nil || said {
+		t.Fatalf("a machine that never reported was reported about: said=%v err=%v", said, err)
+	}
+}
+
+func TestWhatANodeSaidGoesWhenTheNodeDoes(t *testing.T) {
+	inv := fresh(t)
+	ctx := context.Background()
+	id := nodeNamed(t, inv, "leaving")
+	if err := inv.RecordDoing(ctx, id, Doing{Outcome: OutcomeFailed}); err != nil {
+		t.Fatal(err)
+	}
+	if _, err := inv.store.Pool().Exec(ctx, `delete from node where name = 'leaving'`); err != nil {
+		t.Fatal(err)
+	}
+	var left int
+	if err := inv.store.Pool().QueryRow(ctx, `select count(*) from node_report`).Scan(&left); err != nil {
+		t.Fatal(err)
+	}
+	if left != 0 {
+		t.Fatalf("%d report(s) outlived the machine", left)
+	}
+}

internal/inventory/migrations/0011-what-a-node-did.sql

@@ -0,0 +1,33 @@
+-- What each machine did with what it was last sent.
+--
+-- A node reports back after applying a declaration: everything worked, some of it failed, or the
+-- whole thing was refused. Until this, a refusal or a failure moved `last_seen` and the reason
+-- went to a log line -- so **which machine is not doing what it was told** had no answer the next
+-- morning, and that is the question a mesh exists to answer.
+--
+-- One row per node, replaced. The question is about the machine's CURRENT state, not its history:
+-- "this failed an hour ago and then succeeded" is not a machine anybody needs to look at, and a
+-- table of every report would bury the ones that matter under the ones that do not.
+
+create table node_report (
+    node     uuid        primary key references node(id) on delete cascade,
+
+    -- applied · failed · refused. Named rather than a boolean, because "some of it failed" and
+    -- "none of it was applied" are different situations with different remedies, and collapsing
+    -- them would make the report say less than the node did.
+    outcome  text        not null,
+
+    -- Why, when the whole declaration was refused. The node's own words: the host says exactly
+    -- what it could not accept, and anything this end wrote instead would be a second, worse
+    -- explanation of the same thing.
+    refused  text        not null default '',
+
+    -- Which resources failed, when some did, as [{id, error}].
+    failed   jsonb       not null default '[]',
+
+    -- How many were applied, for the ordinary case where nothing is wrong and the only useful
+    -- fact is that the machine did what it was asked.
+    applied  int         not null default 0,
+
+    at       timestamptz not null default now()
+);

internal/inventory/nodes.go

@@ -408,3 +408,108 @@ func (i *Inventory) SetPlace(ctx context.Context, name, endpoint, site string, h
 		   where id = $1`, node.ID, endpoint, site, hub, addr)
 	return err
 }
+
+// Outcomes a node's last report can have.
+const (
+	// OutcomeApplied is everything the declaration asked for.
+	OutcomeApplied = "applied"
+	// OutcomeFailed is some of it. The machine is in a state nobody declared.
+	OutcomeFailed = "failed"
+	// OutcomeRefused is none of it: the host would not accept the declaration at all, so the
+	// machine is exactly as it was. A different situation from failing, with a different remedy —
+	// one is fixed on the machine and the other in what was sent.
+	OutcomeRefused = "refused"
+)
+
+// Doing is what one machine did with what it was last sent.
+type Doing struct {
+	Node    string
+	Outcome string
+	Refused string
+	Failed  []FailedResource
+	Applied int
+	At      time.Time
+}
+
+// FailedResource is one thing a node could not do.
+type FailedResource struct {
+	ID    string `json:"id"`
+	Error string `json:"error"`
+}
+
+// Wrong reports whether this machine needs somebody to look at it.
+func (d Doing) Wrong() bool { return d.Outcome != OutcomeApplied }
+
+// RecordDoing keeps what a node said it did.
+//
+// One row per node, replaced. The question is the machine's current state — "this failed an hour
+// ago and then succeeded" is not something anybody needs to look at, and a table of every report
+// would bury the ones that matter.
+func (i *Inventory) RecordDoing(ctx context.Context, node string, d Doing) error {
+	failed, err := json.Marshal(d.Failed)
+	if err != nil {
+		return err
+	}
+	_, err = i.store.Pool().Exec(ctx,
+		`insert into node_report (node, outcome, refused, failed, applied, at)
+		 values ($1, $2, $3, $4, $5, now())
+		 on conflict (node) do update set outcome = excluded.outcome, refused = excluded.refused,
+		   failed = excluded.failed, applied = excluded.applied, at = excluded.at`,
+		node, d.Outcome, d.Refused, failed, d.Applied)
+	return err
+}
+
+// NotDoingWhatTheyWereTold is every machine whose last report was not a clean apply.
+//
+// The list somebody wants when they ask what is wrong. A machine that has never reported is
+// absent rather than listed: it may be new, or switched off, and "never said anything" is a
+// different situation from "said it could not" — which is what `node list` reports as last heard
+// from.
+func (i *Inventory) NotDoingWhatTheyWereTold(ctx context.Context) ([]Doing, error) {
+	rows, err := i.store.Pool().Query(ctx,
+		`select n.name, r.outcome, r.refused, r.failed, r.applied, r.at
+		 from node_report r join node n on n.id = r.node
+		 where r.outcome <> $1 order by r.at desc`, OutcomeApplied)
+	if err != nil {
+		return nil, err
+	}
+	defer rows.Close()
+
+	var out []Doing
+	for rows.Next() {
+		var d Doing
+		var failed []byte
+		if err := rows.Scan(&d.Node, &d.Outcome, &d.Refused, &failed, &d.Applied, &d.At); err != nil {
+			return nil, err
+		}
+		if err := json.Unmarshal(failed, &d.Failed); err != nil {
+			return nil, err
+		}
+		out = append(out, d)
+	}
+	return out, rows.Err()
+}
+
+// DoingOf is what one machine last did, and whether it has said anything at all.
+func (i *Inventory) DoingOf(ctx context.Context, name string) (Doing, bool, error) {
+	node, err := i.NodeByName(ctx, name)
+	if err != nil {
+		return Doing{}, false, err
+	}
+	var d Doing
+	var failed []byte
+	err = i.store.Pool().QueryRow(ctx,
+		`select outcome, refused, failed, applied, at from node_report where node = $1`, node.ID).
+		Scan(&d.Outcome, &d.Refused, &failed, &d.Applied, &d.At)
+	if errors.Is(err, pgx.ErrNoRows) {
+		return Doing{}, false, nil
+	}
+	if err != nil {
+		return Doing{}, false, err
+	}
+	d.Node = name
+	if err := json.Unmarshal(failed, &d.Failed); err != nil {
+		return Doing{}, false, err
+	}
+	return d, true, nil
+}

internal/link/enrolment.go

@@ -7,6 +7,7 @@ import (
 	"encoding/base64"
 	"errors"
 	"fmt"
+	"sort"
 
 	"github.com/novox/mesh-control/internal/broker"
 	"github.com/novox/mesh-control/internal/identity"
@@ -141,6 +142,29 @@ func (e Enrolment) Heard(ctx context.Context, report Report) error {
 	if err != nil {
 		return err
 	}
+	// What it did is kept whichever way it went. Until this, a refusal or a failure moved
+	// last_seen and the reason went to a log line, so "which machine is not doing what it was
+	// told" had no answer the next morning — which is the question a mesh exists to answer.
+	doing := inventory.Doing{
+		Outcome: inventory.OutcomeApplied,
+		Refused: report.Refused,
+		Applied: len(report.Applied),
+	}
+	switch {
+	case report.Refused != "":
+		doing.Outcome = inventory.OutcomeRefused
+	case len(report.Failed) > 0:
+		doing.Outcome = inventory.OutcomeFailed
+	}
+	for id, why := range report.Failed {
+		doing.Failed = append(doing.Failed, inventory.FailedResource{ID: id, Error: why})
+	}
+	// Ordered, so two readings of one failure are the same reading.
+	sort.Slice(doing.Failed, func(i, j int) bool { return doing.Failed[i].ID < doing.Failed[j].ID })
+	if err := e.Inventory.RecordDoing(ctx, node.ID, doing); err != nil {
+		return err
+	}
+
 	// A refusal, a failure, or a bare word that the node is there — none of them is an account of
 	// what the machine holds, so each moves last_seen and nothing else. Recording a partial list
 	// as though it were the whole would tell a rebuilding node to remove what it still has.

internal/link/heard_test.go

@@ -0,0 +1,114 @@
+package link_test
+
+import (
+	"context"
+	"strings"
+	"testing"
+
+	"github.com/novox/mesh-control/internal/inventory"
+	"github.com/novox/mesh-control/internal/link"
+)
+
+// Turning what a node said into what the mesh keeps.
+//
+// This is where "refused" and "failed" become different things. They are different situations
+// with different remedies — one is fixed in what was sent and the other on the machine — and the
+// mapping deciding which is which had no test at all.
+
+func heardFrom(t *testing.T, report link.Report) (*inventory.Inventory, inventory.Doing, bool) {
+	t.Helper()
+	inv := inventory.ForTest(t)
+	ctx := context.Background()
+	if _, err := inv.AddNode(ctx, report.Node); err != nil {
+		t.Fatal(err)
+	}
+	if err := (link.Enrolment{Inventory: inv}).Heard(ctx, report); err != nil {
+		t.Fatal(err)
+	}
+	doing, said, err := inv.DoingOf(ctx, report.Node)
+	if err != nil {
+		t.Fatal(err)
+	}
+	return inv, doing, said
+}
+
+func TestARefusalIsKeptAsARefusalWithTheNodesOwnWords(t *testing.T) {
+	_, doing, said := heardFrom(t, link.Report{
+		Node: "workstation", Refused: `resource "conf": a file needs a path`,
+	})
+	if !said {
+		t.Fatal("a refusal was not recorded")
+	}
+	if doing.Outcome != inventory.OutcomeRefused {
+		t.Fatalf("a refusal was recorded as %q", doing.Outcome)
+	}
+	if !strings.Contains(doing.Refused, "needs a path") {
+		// The host says exactly what it could not accept. Anything this end wrote instead would
+		// be a second, worse explanation of the same thing.
+		t.Fatalf("the node's own words were not kept: %q", doing.Refused)
+	}
+}
+
+func TestSomeOfItFailingIsNotARefusal(t *testing.T) {
+	// Refused means the machine is exactly as it was. Failed means it is in a state nobody
+	// declared. Reporting one as the other sends somebody to the wrong place.
+	_, doing, _ := heardFrom(t, link.Report{
+		Node:    "workstation",
+		Applied: []string{"a", "b", "c"},
+		Failed:  map[string]string{"svc": "unit not found", "pkg": "no such package"},
+	})
+	if doing.Outcome != inventory.OutcomeFailed {
+		t.Fatalf("a partial failure was recorded as %q", doing.Outcome)
+	}
+	if doing.Applied != 3 {
+		t.Fatalf("what did apply was not kept: %d", doing.Applied)
+	}
+	if len(doing.Failed) != 2 {
+		t.Fatalf("got %+v", doing.Failed)
+	}
+	// Ordered, so two readings of one failure are the same reading.
+	if doing.Failed[0].ID != "pkg" || doing.Failed[1].ID != "svc" {
+		t.Fatalf("failures came back unordered: %+v", doing.Failed)
+	}
+}
+
+func TestACleanApplyIsRecordedAsOne(t *testing.T) {
+	inv, doing, _ := heardFrom(t, link.Report{Node: "workstation", Applied: []string{"a", "b"}})
+	if doing.Outcome != inventory.OutcomeApplied || doing.Applied != 2 {
+		t.Fatalf("got %+v", doing)
+	}
+	wrong, err := inv.NotDoingWhatTheyWereTold(context.Background())
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(wrong) != 0 {
+		t.Fatalf("a clean apply is listed as wrong: %+v", wrong)
+	}
+}
+
+func TestAFailureDoesNotBecomeTheAccountOfWhatTheMachineHolds(t *testing.T) {
+	// A partial list is not an account of what the machine holds. Recording one as though it
+	// were would tell a rebuilding node to remove what it still has — which is the fault that
+	// destroyed a substrate once (novox/hq 04-ISSUES/010).
+	inv := inventory.ForTest(t)
+	ctx := context.Background()
+	node, err := inv.AddNode(ctx, "workstation")
+	if err != nil {
+		t.Fatal(err)
+	}
+	if err := inv.RecordOwned(ctx, node.ID, []string{"one", "two", "three"}); err != nil {
+		t.Fatal(err)
+	}
+	if err := (link.Enrolment{Inventory: inv}).Heard(ctx, link.Report{
+		Node: "workstation", Applied: []string{"one"}, Failed: map[string]string{"two": "no"},
+	}); err != nil {
+		t.Fatal(err)
+	}
+	owned, _, err := inv.Owned(ctx, node.ID)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(owned) != 3 {
+		t.Fatalf("a partial report replaced the account of what the machine holds: %v", owned)
+	}
+}