diff --git a/cmd/mesh-control/main.go b/cmd/mesh-control/main.go index 9aa4ccd..1417763 100644 --- a/cmd/mesh-control/main.go +++ b/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 { - fmt.Println("every module with a source is built from what that source has") - return nil + if len(behind) > 0 { + var names []string + 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 - 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(" %-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", "") - } + if len(wrong) == 0 && len(quiet) == 0 && len(behind) == 0 { + // Said plainly. "Nothing to report" and "nothing was checked" must never look the same, + // 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, "+ + "and every module current with its source\n", len(nodes)) } return nil } diff --git a/internal/inventory/doing_test.go b/internal/inventory/doing_test.go new file mode 100644 index 0000000..44a9760 --- /dev/null +++ b/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) + } +} diff --git a/internal/inventory/migrations/0011-what-a-node-did.sql b/internal/inventory/migrations/0011-what-a-node-did.sql new file mode 100644 index 0000000..87d4485 --- /dev/null +++ b/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() +); diff --git a/internal/inventory/nodes.go b/internal/inventory/nodes.go index de9a19b..d0811b1 100644 --- a/internal/inventory/nodes.go +++ b/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 +} diff --git a/internal/link/enrolment.go b/internal/link/enrolment.go index 3b0c23f..53fb405 100644 --- a/internal/link/enrolment.go +++ b/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. diff --git a/internal/link/heard_test.go b/internal/link/heard_test.go new file mode 100644 index 0000000..d339054 --- /dev/null +++ b/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) + } +}