Merge pull request 'Never say a reconcile's report after a newer apply's (hq issue 267)' (#30) from fix/stale-report-overwrites into main

internal/link/overtaken_test.go

@@ -0,0 +1,94 @@
+package link
+
+import (
+	"context"
+	"testing"
+	"time"
+)
+
+// A reconcile's report about the declaration kept before a delivery is never said after that
+// delivery's report (novox/hq issue 267).
+
+// Measured on the home server: the reconcile timer fired three seconds before a declaration
+// arrived. The reconcile held the machine to the declaration kept then; the delivery's apply waited
+// for it, applied the new one and was reported — and then the reconcile's report, queued meanwhile,
+// went out and was stored as the machine's latest account, naming the older declaration. The
+// release plan waited on a report it had already been given.
+func TestAReconcileReportOlderThanTheApplyIsNotSaidAfterIt(t *testing.T) {
+	m, key := aMember(t)
+	l := newQuietLink(&said{body: signedBy(t, key, []byte(`{"declaration":2}`))})
+	outbox := make(chan Unasked, 1)
+
+	ctx, stop := context.WithCancel(context.Background())
+	defer stop()
+	settled := make(chan bool, 1)
+	apply := func(context.Context, []byte, []byte) Report {
+		// The reconcile ran first, on what was kept then, and queued its report while this waited.
+		outbox <- Unasked{Report: Report{Declared: "d1", Applied: []string{"a"}, Outward: []string{"eth0"}},
+			Done: func(published bool) { settled <- published; stop() }}
+		return Report{Declared: "d2", Applied: []string{"a", "b"}, Outward: []string{"eth0"}}
+	}
+
+	done := make(chan error, 1)
+	go func() { done <- serve(ctx, l, m, apply, nil, time.Second, outbox, &keptInMemory{}) }()
+	select {
+	case published := <-settled:
+		if published {
+			t.Fatal("the reconcile's report was counted as said")
+		}
+	case <-time.After(5 * time.Second):
+		t.Fatal("the reconcile's report was never settled")
+	}
+	if err := <-done; err != nil {
+		t.Fatal(err)
+	}
+	reports := l.said()
+	if len(reports) != 1 || reports[0].Declared != "d2" {
+		t.Fatalf("the mesh heard %+v; it should have heard only the apply of d2", reports)
+	}
+}
+
+// A reconcile's report about the declaration this link applied is news, and is said.
+func TestAReconcileReportAboutTheAppliedDeclarationIsSaid(t *testing.T) {
+	m, key := aMember(t)
+	l := newQuietLink(&said{body: signedBy(t, key, []byte(`{"declaration":2}`))})
+	outbox := make(chan Unasked, 1)
+
+	ctx, stop := context.WithCancel(context.Background())
+	defer stop()
+	settled := make(chan bool, 1)
+	apply := func(context.Context, []byte, []byte) Report {
+		outbox <- Unasked{Report: Report{Declared: "d2", Applied: []string{"a", "b"}, Firewall: "nftables"},
+			Done: func(published bool) { settled <- published; stop() }}
+		return Report{Declared: "d2", Applied: []string{"a", "b"}}
+	}
+
+	go func() { _ = serve(ctx, l, m, apply, nil, time.Second, outbox, nil) }()
+	select {
+	case published := <-settled:
+		if !published {
+			t.Fatal("a reconcile's report about the applied declaration was not said")
+		}
+	case <-time.After(5 * time.Second):
+		t.Fatal("the reconcile's report was never settled")
+	}
+	if reports := l.said(); len(reports) != 2 || reports[1].Declared != "d2" {
+		t.Fatalf("the mesh heard %+v", reports)
+	}
+}
+
+func TestOvertaken(t *testing.T) {
+	for _, c := range []struct {
+		declared, applied string
+		want              bool
+	}{
+		{"d1", "d2", true},
+		{"d2", "d2", false},
+		{"", "d2", false}, // names no declaration
+		{"d1", "", false}, // this link has applied nothing yet
+	} {
+		if got := overtaken(Report{Declared: c.declared}, c.applied); got != c.want {
+			t.Errorf("overtaken(%q, %q) = %v, want %v", c.declared, c.applied, got, c.want)
+		}
+	}
+}

internal/link/run.go

@@ -243,6 +243,10 @@ func serve(ctx context.Context, link Link, m Membership, apply Applier, say Anno
 	defer beat.Stop()
 	publishAlive(ctx, link, m, say, timeout)
 
+	// **The declaration this link last applied**, so a report made about an older one is not said
+	// after it (novox/hq issue 267). Empty until something is applied or said again here.
+	var applied string
+
 	// **What the last apply did, if the mesh never heard it** — said before anything newly
 	// delivered is applied, so it can never land after, and read as newer than, a later report.
 	if unsaid != nil {
@@ -251,6 +255,7 @@ func serve(ctx context.Context, link Link, m Membership, apply Applier, say Anno
 			say("cannot read the report this node kept unsaid: " + err.Error())
 		case ok:
 			say("saying again what the last apply did: its report never reached the mesh")
+			applied = kept.Declared
 			if publishReport(reporting, link, m, kept, say, timeout) {
 				if err := unsaid.Said(kept.Declared); err != nil {
 					say("said the kept report, and cannot forget it: " + err.Error())
@@ -275,6 +280,23 @@ func serve(ctx context.Context, link Link, m Membership, apply Applier, say Anno
 		case unasked := <-outbox:
 			// Said without having been asked: a reconcile found what an adopted node holds, or
 			// its firewall, changed since it last said.
+			//
+			// **Unless a newer declaration was applied while it waited** (novox/hq issue 267). A
+			// reconcile that held the machine a moment before a delivery arrived made its report
+			// about the declaration kept then; the delivery's apply waited for it, was reported, and
+			// only then did this loop get round to the reconcile's — which reached the mesh last,
+			// named the older declaration, and was stored as the machine's latest account. The plan
+			// waiting on the machine then waited on a report it had already been given. What the
+			// reconcile saw, the newer apply has said since, and fresher; the next reconcile says
+			// anything that is still news.
+			if overtaken(unasked.Report, applied) {
+				say(fmt.Sprintf("set aside a reconcile's report of declaration %s: %s was applied and "+
+					"reported since", short(unasked.Report.Declared), short(applied)))
+				if unasked.Done != nil {
+					unasked.Done(false)
+				}
+				continue
+			}
 			published := publishReport(ctx, link, m, unasked.Report, say, timeout)
 			if unasked.Done != nil {
 				unasked.Done(published)
@@ -302,6 +324,9 @@ func serve(ctx context.Context, link Link, m Membership, apply Applier, say Anno
 				_ = old.Handled()
 			}
 			report := handleBody(ctx, m, declaration.Body(), apply)
+			if report.Declared != "" {
+				applied = report.Declared
+			}
 			if unsaid != nil {
 				if err := unsaid.Keep(report); err != nil {
 					say("cannot keep this apply's report until it is said: " + err.Error())
@@ -331,6 +356,21 @@ func serve(ctx context.Context, link Link, m Membership, apply Applier, say Anno
 	}
 }
 
+// overtaken says whether a report made unasked is about a declaration other than the one this link
+// has applied since. Unanswerable is not overtaken: a report that names no declaration, or a link
+// that has applied nothing yet, has nothing to be older than.
+func overtaken(r Report, applied string) bool {
+	return r.Declared != "" && applied != "" && r.Declared != applied
+}
+
+// short is a declaration's digest as a person reads it in a log line.
+func short(digest string) string {
+	if len(digest) > 12 {
+		return digest[:12]
+	}
+	return digest
+}
+
 // drainDepth is how many declarations the host will hold unacknowledged while it looks for a newer
 // one; drainWindow is how long it waits for another to follow the one it has. Both small: a push is
 // rare and a backlog is the exception this exists for, not the shape of ordinary traffic.