amadan

carlos / platform Public

host: an unwired move pager is loud, once per rule per move

moves-phase1-6 Tasks 4+5 fix round 1, ruling 2. With no Page wired a
paging rule logs one WARNING in the agent's log per rule per move (the
journal's unwired:<rule> step remembers it across a restart) and
refuses nothing. pageOnce now returns what became of the page;
pageStartRefused returns it and the refused start check's log line
says it, so the result is never dropped.

No censused unit changes.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
claude e8827f7381dbdd691539388c8c186212676a76a4 parent e20b03c
3 files changed, +132 −26
  • internal/host/movespaging.go +74 −22
  • internal/host/movespaging_test.go +55 −2
  • internal/host/movesprobeowners.go +3 −2
diff --git a/internal/host/movespaging.go b/internal/host/movespaging.go
index e47b0919c..c196c7ed7 100644
--- a/internal/host/movespaging.go
+++ b/internal/host/movespaging.go
@@ -44,15 +44,46 @@ import (
// two, or a send that fails (logged), pages nothing more, as the console's
// move_pages records an attempt whether or not delivery worked (pages are
// best effort). A journal that cannot be read or written sends nothing, so a
-// rule that fires every pass can never flood. Unwired (nil Page), nothing
-// pages and nothing is marked.
+// rule that fires every pass can never flood.
+//
+// Unwired (nil Page, as production is until Plan 5 Task 9b wires it), a rule
+// is never silent: the agent's log says so loudly, once per rule per move
+// (the journal's unwired:<rule> step remembers it across a restart), and
+// nothing is refused (fix round 1, ruling 2).
// pagingLogf is the agent's log for the paging code (a variable so tests
// can read it).
var pagingLogf = log.Printf
-// pagedStep is the journal step that records a rule's page.
-const pagedStep = "paged:"
+// pagedStep is the journal step that records a rule's page; unwiredStep
+// records that its warning about an unwired pager was logged.
+const (
+ pagedStep = "paged:"
+ unwiredStep = "unwired:"
+)
+
+// pageOutcome is what became of one rule's page.
+type pageOutcome int
+
+const (
+ pageSent pageOutcome = iota // handed to the pager without error
+ pagePagedBefore // the journal says it was sent before
+ pageUnwired // no pager is wired (logged loudly once)
+ pageUndelivered // the journal or the pager failed (logged)
+)
+
+// String is the outcome as the agent's log says it.
+func (o pageOutcome) String() string {
+ switch o {
+ case pageSent:
+ return "paged"
+ case pagePagedBefore:
+ return "paged before"
+ case pageUnwired:
+ return "not paged: no pager is wired"
+ }
+ return "not paged: the page was not delivered"
+}
// The rules' names in the journal.
const (
@@ -67,34 +98,54 @@ func pageRuleStuck(m *provision.MoveState) string {
}
// pageOnce sends one page for rule unless the journal of (host, op) under
-// dataDir says it was sent: it marks the journal, then pages. sent is true
-// only when the page was handed to page without error.
-func pageOnce(ctx context.Context, page func(ctx context.Context, level, subject, body string) error, dataDir, host, op, rule string, now time.Time, level, subject, body string) (sent bool) {
+// dataDir says it was sent: it marks the journal, then pages. Unwired, it
+// warns instead (unwiredOnce).
+func pageOnce(ctx context.Context, page func(ctx context.Context, level, subject, body string) error, dataDir, host, op, rule string, now time.Time, level, subject, body string) pageOutcome {
if page == nil {
- return false
+ unwiredOnce(dataDir, host, op, rule, now)
+ return pageUnwired
}
j, err := moves.ReadJournal(dataDir, host, op)
if err != nil {
- log.Printf("moves: %s: the %s page of %s is not sent: its journal: %v", host, rule, op, err)
- return false
+ pagingLogf("moves: %s: the %s page of %s is not sent: its journal: %v", host, rule, op, err)
+ return pageUndelivered
}
if j.Done(pagedStep + rule) {
- return false
+ return pagePagedBefore
}
j.Mark(pagedStep+rule, now.UTC().Format(time.RFC3339))
if err := j.Write(dataDir); err != nil {
- log.Printf("moves: %s: the %s page of %s is not sent: its journal: %v", host, rule, op, err)
- return false
+ pagingLogf("moves: %s: the %s page of %s is not sent: its journal: %v", host, rule, op, err)
+ return pageUndelivered
}
if err := page(ctx, level, subject, body); err != nil {
- log.Printf("moves: %s: the %s page of %s: %v", host, rule, op, err)
- return false
+ pagingLogf("moves: %s: the %s page of %s: %v", host, rule, op, err)
+ return pageUndelivered
+ }
+ return pageSent
+}
+
+// unwiredOnce logs, loudly, that rule's page for op is not sent because no
+// pager is wired: once per rule per move, which the journal's unwired:<rule>
+// step remembers. A journal that cannot be read or written does not quiet
+// it: the warning is logged again the next time.
+func unwiredOnce(dataDir, host, op, rule string, now time.Time) {
+ j, err := moves.ReadJournal(dataDir, host, op)
+ if err == nil && j.Done(unwiredStep+rule) {
+ return
+ }
+ pagingLogf("moves: %s: WARNING: no operator pager is wired on this box, so the %s page of move %s is not sent; the move goes on (Plan 5 Task 9b wires the pager)", host, rule, op)
+ if err != nil {
+ return
+ }
+ j.Mark(unwiredStep+rule, now.UTC().Format(time.RFC3339))
+ if err := j.Write(dataDir); err != nil {
+ pagingLogf("moves: %s: the warning about the unwired %s page of %s is not recorded, so it is logged again: %v", host, rule, op, err)
}
- return true
}
// pageOnce is the worker's pageOnce: its pager, journals and clock.
-func (w *movesWorker) pageOnce(ctx context.Context, host, op, rule, level, subject, body string) bool {
+func (w *movesWorker) pageOnce(ctx context.Context, host, op, rule, level, subject, body string) pageOutcome {
return pageOnce(ctx, w.cfg.Page, w.cfg.DataDir, host, op, rule, w.now(), level, subject, body)
}
@@ -145,16 +196,17 @@ func (w *movesWorker) pageStray(ctx context.Context, rec provision.Record) {
return
}
subject, body := strayPage(rec.Host, w.cfg.Box)
- if !w.pageOnce(ctx, rec.Host, rec.Move.ID, pageRuleStray, alerting.LevelIncident, subject, body) {
+ if w.pageOnce(ctx, rec.Host, rec.Move.ID, pageRuleStray, alerting.LevelIncident, subject, body) != pageSent {
return
}
pagingLogf("moves: %s: move %s: %s", rec.Host, rec.Move.ID, strayLine(w.cfg.Box, rec.Host))
}
// pageStartRefused pages an incident once per op for a refused §5.1 start
-// check on this box (§13). The probe owners' lock is held across the
-// journal's read and write, as their other journal writes hold it.
-func (m *movesProbeOwners) pageStartRefused(ctx context.Context, host, op string) {
+// check on this box (§13), and returns what became of the page. The probe
+// owners' lock is held across the journal's read and write, as their other
+// journal writes hold it.
+func (m *movesProbeOwners) pageStartRefused(ctx context.Context, host, op string) pageOutcome {
now := time.Now()
if m.Now != nil {
now = m.Now()
@@ -162,7 +214,7 @@ func (m *movesProbeOwners) pageStartRefused(ctx context.Context, host, op string
subject, body := startRefusedPage(host, op, m.Box)
m.mu.Lock()
defer m.mu.Unlock()
- pageOnce(ctx, m.Page, m.DataDir, host, op, pageRuleStartCheck, now, alerting.LevelIncident, subject, body)
+ return pageOnce(ctx, m.Page, m.DataDir, host, op, pageRuleStartCheck, now, alerting.LevelIncident, subject, body)
}
// rolledBackPage is the rolled_back page: the subject (MV-N385) and the
diff --git a/internal/host/movespaging_test.go b/internal/host/movespaging_test.go
index 9730c53f0..eeed1db75 100644
--- a/internal/host/movespaging_test.go
+++ b/internal/host/movespaging_test.go
@@ -220,12 +220,65 @@ func TestPagingIsRateLimited(t *testing.T) {
}
})
+ // Fix round 1, ruling 2: production stays unwired until Plan 5 9b, and
+ // an unwired pager is never silent. Each rule says so in the agent's
+ // log, loudly, once per move (its journal remembers, across a restart);
+ // nothing is refused. The probe owners' refused start check says what
+ // became of its page, so the result is never dropped.
+ t.Run("an unwired pager is loud, once per rule per move", func(t *testing.T) {
+ logged := capturePagingLog(t)
+ dd := t.TempDir()
+ worker := func() *movesWorker { return &movesWorker{cfg: moveCfg{DataDir: dd, Box: "uk-box"}} }
+ rec := provision.Record{Host: p1Host, Move: &provision.MoveState{ID: p1ID, State: provision.MoveStuck}}
+ loud := func() int { return strings.Count(strings.Join(*logged, "\n"), "WARNING: no operator pager is wired") }
+ w := worker()
+ w.pageStuck(ctx, rec, "target", provision.StuckReturnTargetDatabase)
+ w.pageStuck(ctx, rec, "target", provision.StuckReturnTargetDatabase)
+ worker().pageStuck(ctx, rec, "target", provision.StuckReturnTargetDatabase) // a restarted agent
+ if loud() != 1 {
+ t.Fatalf("the unwired stuck page warned %d times, want once: %q", loud(), *logged)
+ }
+ w.pageRolledBack(ctx, rec, p1ID)
+ w.pageRolledBack(ctx, rec, p1ID)
+ if loud() != 2 {
+ t.Fatalf("a second rule warned %d times in all, want 2: %q", loud(), *logged)
+ }
+ for _, l := range *logged {
+ if strings.Contains(l, "WARNING") && (!strings.Contains(l, p1Host) || !strings.Contains(l, p1ID)) {
+ t.Fatalf("the warning does not name the host and the move: %q", l)
+ }
+ }
+
+ // The probe owners: the start check is refused as before, the
+ // warning comes once, and every refusal's line says it was not paged.
+ *logged = nil
+ f := newPOFixture(t)
+ o := f.read()
+ in, err := f.owners.Select(ctx, f.route, o, poProbe)
+ if err != nil {
+ t.Fatal(err)
+ }
+ admitted := f.admit(o, in)
+ f.writeLocal("mv_other", poOp, f.inc)
+ for i := 0; i < 2; i++ {
+ if err := f.owners.Materialize(ctx, admitted, in, poWork{action: "spawn", f: f}); !errors.Is(err, moves.ErrStartFiles) {
+ t.Fatalf("files of another op: %v", err)
+ }
+ }
+ if loud() != 1 {
+ t.Fatalf("the unwired start check page warned %d times, want once: %q", loud(), *logged)
+ }
+ if n := strings.Count(strings.Join(*logged, "\n"), "refused to start "+poHost+" for "+poOp+" (not paged: no pager is wired)"); n != 2 {
+ t.Fatalf("the refusals' lines %d, want 2 saying the page was not sent: %q", n, *logged)
+ }
+ })
+
t.Run("a journal that cannot be written sends nothing", func(t *testing.T) {
var pages pagesSeen
- if pageOnce(ctx, pages.hook(), t.TempDir(), "bad/host", p1ID, pageRuleStray, time.Now(), "incident", "s", "b") || len(pages) != 0 {
+ if pageOnce(ctx, pages.hook(), t.TempDir(), "bad/host", p1ID, pageRuleStray, time.Now(), "incident", "s", "b") == pageSent || len(pages) != 0 {
t.Fatalf("paged without a journal: %+v", pages)
}
- if pageOnce(ctx, nil, t.TempDir(), p1Host, p1ID, pageRuleStray, time.Now(), "incident", "s", "b") {
+ if pageOnce(ctx, nil, t.TempDir(), p1Host, p1ID, pageRuleStray, time.Now(), "incident", "s", "b") != pageUnwired {
t.Fatal("an unwired pager reported a page")
}
})
diff --git a/internal/host/movesprobeowners.go b/internal/host/movesprobeowners.go
index b92ce3ca1..7cee17027 100644
--- a/internal/host/movesprobeowners.go
+++ b/internal/host/movesprobeowners.go
@@ -863,8 +863,9 @@ func (m *movesProbeOwners) startCheck(ctx context.Context, o hostclaim.Observed,
}
if err := moves.StartCheck(fresh.Claim, marker, files, db); err != nil {
// A refused start check pages an operator once per op (§13,
- // movespaging.go).
- m.pageStartRefused(ctx, o.Host, fresh.Claim.Op.ID)
+ // movespaging.go), and the agent's log says what became of the page.
+ op := fresh.Claim.Op.ID
+ pagingLogf("moves: %s: %s refused to start %s for %s (%s): %v", o.Host, m.Box, o.Host, op, m.pageStartRefused(ctx, o.Host, op), err)
return err
}
return nil