Keep calls and hand acts on the bus, answer status at once, record durations (hq to-be 45 Phase 0)

A controller restart lost every call's outcome, `status` composed the mesh
while its caller waited (18.6s live on 2026-10-06, past the 10s window), a
repair by hand left no trace, and the core's bounds had nothing measured to
be set from.

- calls: kept in the controller's bucket mesh-controller_calls (last 1000 or
  14 days, answers bounded to 64 KiB), read by id across a restart; a
  controller starting marks a stopped one's running calls abandoned; each
  call names its caller from the inbox its answer goes to.
- status: the serving controller composes it at start, after news from a
  machine, a build or an acting verb, and every minute; the verb answers the
  last composition at once with when and how long it took. Composing resolves
  each machine once instead of twice.
- hand-act log in mesh-controller_hand-acts: push (required through the seat),
  plans stop/close, broker consumer-reset and the new hand-act record take
  --why/--cause/--condition; `hand-acts` lists them and repeated causes;
  status counts the week's.
- durations (migration 0066): apply (send to first report), heartbeat gap,
  plan tier and build, recorded as heard; `durations` summarises them.
- the controller's seat row takes this binary's definition of its own verbs,
  so the console no longer judges calls against an older build's schema.
- the controller is granted its two buckets' subjects.

internal/link/calls.go

@@ -7,7 +7,9 @@ import (
 	"fmt"
 	"log"
 	"regexp"
+	"sort"
 	"strconv"
+	"strings"
 	"sync"
 	"time"
 
@@ -33,8 +35,9 @@ import (
 // either. A variable so a test need not wait.
 var AnswerWithin = 10 * time.Second
 
-// KeptCalls is how many calls are kept, newest first; keptAnswer the largest answer kept of a call
-// whose caller was sent it. One its caller never had is kept whole.
+// KeptCalls is how many calls this process keeps in memory, newest first — to match a refusal to its
+// call, and to answer at once; the bus keeps the last thousand (Durably). keptAnswer is the largest
+// answer kept of a call whose caller was sent it. One its caller never had is kept whole.
 const (
 	KeptCalls  = 100
 	keptAnswer = 64 << 10
@@ -47,6 +50,10 @@ const (
 	// CallFinishedAfter is a call that finished after its caller was told it was still running: its
 	// answer is here and nowhere else.
 	CallFinishedAfter = "finished after its caller was answered"
+	// CallAbandoned is a call whose controller stopped before it finished (novox/hq to-be 45 §6): a
+	// controller starting finds it running under another and says so, rather than leaving it running
+	// for ever in the record.
+	CallAbandoned = "abandoned: the controller running it stopped before it finished"
 )
 
 // Call is one call of a role's tool, as `calls` shows it.
@@ -65,10 +72,27 @@ type Call struct {
 	// Refused is the bus refusing the answer this holder sent: the caller got nothing, and this is
 	// the only place that says what it would have.
 	Refused string `json:"answer refused by the bus,omitempty"`
+	// Caller is the bus principal that asked, read from the inbox its answer went to — every principal
+	// is granted only its own (novox/hq to-be 45 §7: a hand act says who).
+	Caller string `json:"caller,omitempty"`
+	// Holder is the controller process that served it, so one starting can tell its own running
+	// calls from those a stopped one left.
+	Holder string `json:"holder,omitempty"`
 
 	reply string // the subject the answer went to, which the bus names when it refuses it
 }
 
+// CallKeeper keeps calls where the process serving them does not: the controller's bucket on the
+// bus (novox/hq to-be 45 §6). A call is kept whole on every change — begun, finished, refused — so a
+// controller replaced at any moment leaves the last word on each.
+type CallKeeper interface {
+	Keep(ctx context.Context, c Call) error
+	// Kept is one call with its whole answer.
+	Kept(ctx context.Context, id string) (Call, bool, error)
+	// Recent is the kept calls, newest first, without their answers.
+	Recent(ctx context.Context) ([]Call, error)
+}
+
 // CallLog keeps the latest calls a holder served.
 type CallLog struct {
 	mu    sync.Mutex
@@ -78,6 +102,15 @@ type CallLog struct {
 	// Follow is the tool that reads this log back, named in a running answer — set by a holder that
 	// serves one (the controller's `calls`); without it, the answer points at the holder's journal.
 	Follow string
+
+	// keeper keeps every call beyond this process, when Durably was given one; writes go through
+	// one goroutine, in order, so a call's last state is the one kept.
+	keeper  CallKeeper
+	holder  string
+	writes  chan Call
+	logger  *log.Logger
+	lost    int // writes the keeper could not take, said once each
+	keepErr error
 }
 
 // Calls is this process's log: one holder process serves its seats on one connection.
@@ -85,16 +118,130 @@ var Calls = NewCallLog()
 
 func NewCallLog() *CallLog { return &CallLog{now: time.Now} }
 
+// keepTries is how many times one call's state is offered to the keeper before it is said lost: the
+// bus reloading its user list refuses for a moment, and that is exactly when a push runs.
+const keepTries = 5
+
+// Durably keeps every call from now on with keeper as well as in memory, under this process's name,
+// and marks running the calls a controller before this one left running: it stopped, so they cannot
+// finish (novox/hq to-be 45 §6). Said, naming each.
+func (l *CallLog) Durably(ctx context.Context, keeper CallKeeper, holder string, logger *log.Logger) error {
+	l.mu.Lock()
+	l.keeper, l.holder, l.logger = keeper, holder, logger
+	if l.writes == nil {
+		l.writes = make(chan Call, 256)
+		go l.keepWrites()
+	}
+	l.mu.Unlock()
+	kept, err := keeper.Recent(ctx)
+	if err != nil {
+		return fmt.Errorf("reading the calls kept on the bus: %w", err)
+	}
+	for _, c := range kept {
+		if c.State != CallRunning || c.Holder == holder {
+			continue
+		}
+		whole, found, err := keeper.Kept(ctx, c.ID)
+		if err != nil || !found {
+			whole = c
+		}
+		whole.State = CallAbandoned
+		if err := keeper.Keep(ctx, whole); err != nil {
+			return fmt.Errorf("marking %s abandoned: %w", c.ID, err)
+		}
+		if logger != nil {
+			logger.Printf("%s (%s.%s, asked %s by %s) was running under %s, which stopped: marked abandoned — "+
+				"it may have done part of what it was asked, and nothing will finish it", c.ID, c.Seat, c.Verb,
+				c.Started.Format(time.RFC3339), orSomebody(c.Caller), orSomebody(c.Holder))
+		}
+	}
+	return nil
+}
+
+func orSomebody(s string) string {
+	if s == "" {
+		return "an unnamed caller"
+	}
+	return s
+}
+
+// keep queues one call's state for the keeper. Never blocks a call: a queue that is full is a keeper
+// that is not taking writes, and that is said rather than waited on.
+func (l *CallLog) keep(c Call) {
+	if l.writes == nil {
+		return
+	}
+	select {
+	case l.writes <- c:
+	default:
+		l.lost++
+		if l.logger != nil {
+			l.logger.Printf("%s (%s.%s) is kept in memory only: the bus is not taking calls' records (%d not kept)",
+				c.ID, c.Seat, c.Verb, l.lost)
+		}
+	}
+}
+
+func (l *CallLog) keepWrites() {
+	for c := range l.writes {
+		var err error
+		for try := 0; try < keepTries; try++ {
+			ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+			err = l.keeper.Keep(ctx, c)
+			cancel()
+			if err == nil {
+				break
+			}
+			time.Sleep(time.Duration(try+1) * time.Second)
+		}
+		if err != nil && l.logger != nil {
+			l.logger.Printf("%s (%s.%s, %s) could not be kept on the bus after %d tries: %v — `calls` "+
+				"answers it from memory until this controller stops", c.ID, c.Seat, c.Verb, c.State, keepTries, err)
+		}
+	}
+}
+
+// callerOf is the bus principal an answer goes to: every principal's inbox is `_INBOX.<its user>.`
+// followed by the client's own random token, and a user may itself hold dots.
+func callerOf(reply string) string {
+	rest, ok := strings.CutPrefix(reply, "_INBOX.")
+	if !ok {
+		return ""
+	}
+	tokens := strings.Split(rest, ".")
+	for i, t := range tokens {
+		if i > 0 && isNUID(t) {
+			return strings.Join(tokens[:i], ".")
+		}
+	}
+	return ""
+}
+
+// isNUID is the client library's random inbox token: twenty-two letters and digits.
+func isNUID(t string) bool {
+	if len(t) != 22 {
+		return false
+	}
+	for _, r := range t {
+		if !(r >= '0' && r <= '9' || r >= 'a' && r <= 'z' || r >= 'A' && r <= 'Z') {
+			return false
+		}
+	}
+	return true
+}
+
 func (l *CallLog) begin(seat, verb string, args json.RawMessage, reply string) *Call {
 	l.mu.Lock()
 	defer l.mu.Unlock()
 	l.next++
 	c := &Call{ID: "call-" + strconv.FormatInt(l.now().UnixNano(), 10) + "-" + strconv.FormatUint(l.next, 10),
-		Seat: seat, Verb: verb, Args: args, Started: l.now(), State: CallRunning, reply: reply}
+		Seat: seat, Verb: verb, Args: args, Started: l.now(), State: CallRunning, reply: reply,
+		Caller: callerOf(reply), Holder: l.holder}
 	l.calls = append(l.calls, c)
 	if len(l.calls) > KeptCalls {
 		l.calls = l.calls[len(l.calls)-KeptCalls:]
 	}
+	l.keep(*c)
 	return c
 }
 
@@ -117,29 +264,67 @@ func (l *CallLog) finish(c *Call, answer []byte, failed, answeredAlready bool) {
 	} else {
 		c.State = CallAnswered
 	}
+	l.keep(*c)
 }
 
-// Recent is the kept calls, newest first, as copies.
-func (l *CallLog) Recent() []Call {
+// Recent is the kept calls, newest first, as copies: this process's from memory, and, when they are
+// kept durably, every other the bus holds — a call a controller before this one served included.
+// Memory wins for a call in both, being the newer word on it. A bus that cannot be read is said in
+// the error beside what memory holds, never answered as no calls.
+func (l *CallLog) Recent() ([]Call, error) {
 	l.mu.Lock()
-	defer l.mu.Unlock()
 	out := make([]Call, 0, len(l.calls))
+	seen := map[string]bool{}
 	for i := len(l.calls) - 1; i >= 0; i-- {
 		out = append(out, *l.calls[i])
+		seen[l.calls[i].ID] = true
 	}
-	return out
-}
-
-// Get is one kept call.
-func (l *CallLog) Get(id string) (Call, bool) {
-	l.mu.Lock()
-	defer l.mu.Unlock()
-	for _, c := range l.calls {
-		if c.ID == id {
-			return *c, true
+	keeper := l.keeper
+	l.mu.Unlock()
+	if keeper == nil {
+		return out, nil
+	}
+	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+	defer cancel()
+	kept, err := keeper.Recent(ctx)
+	if err != nil {
+		return out, fmt.Errorf("the calls kept on the bus could not be read, so only this controller's own "+
+			"are listed: %w", err)
+	}
+	for _, c := range kept {
+		if !seen[c.ID] {
+			out = append(out, c)
 		}
 	}
-	return Call{}, false
+	sort.SliceStable(out, func(i, j int) bool { return out[i].Started.After(out[j].Started) })
+	return out, nil
+}
+
+// Get is one kept call: from memory, or from the bus when this process did not serve it.
+func (l *CallLog) Get(id string) (Call, bool, error) {
+	l.mu.Lock()
+	for _, c := range l.calls {
+		if c.ID == id {
+			found := *c
+			l.mu.Unlock()
+			return found, true, nil
+		}
+	}
+	keeper := l.keeper
+	l.mu.Unlock()
+	if keeper == nil {
+		return Call{}, false, nil
+	}
+	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+	defer cancel()
+	return keeper.Kept(ctx, id)
+}
+
+// IsDurable says whether calls outlive this process.
+func (l *CallLog) IsDurable() bool {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	return l.keeper != nil
 }
 
 // kept is what a call's arguments are kept as: each argument by name, a value only when it is short
@@ -195,6 +380,7 @@ func (l *CallLog) Refusal(err error, logger *log.Logger) bool {
 	at := l.now()
 	hit.Refused = fmt.Sprintf("%s: %s", at.Format(time.RFC3339), err)
 	id, verb, took := hit.ID, hit.Seat+"."+hit.Verb, at.Sub(hit.Started).Round(time.Second)
+	l.keep(*hit)
 	l.mu.Unlock()
 	if logger != nil {
 		// Said in the mesh's words, beside the library's own line: which call, and where its answer is.
@@ -277,6 +463,8 @@ func (l *CallLog) serveCall(seat, verb string, args json.RawMessage, reply strin
 		args = json.RawMessage(`{}`)
 	}
 	c := l.begin(seat, verb, kept(args), reply)
+	// Who asked travels with the call, so an act it does by hand says so (novox/hq to-be 45 §7).
+	ctx = context.WithValue(ctx, callerKey{}, c.Caller)
 	acknowledged := make(chan struct{})
 	var once sync.Once
 	ctx = context.WithValue(ctx, answerNowKey{}, func() { once.Do(func() { close(acknowledged) }) })

internal/link/calls_kept.go

@@ -0,0 +1,115 @@
+package link
+
+import (
+	"context"
+	"encoding/json"
+	"errors"
+	"fmt"
+	"sort"
+
+	"github.com/nats-io/nats.go"
+	"github.com/nats-io/nats.go/jetstream"
+
+	"github.com/novox/mesh-controller/internal/broker"
+)
+
+// Calls kept on the bus (novox/hq to-be 45 §6).
+//
+// **Two keys a call**: `<id>` holds the record — verb, arguments as kept, caller, state, times — and
+// `<id>.answer` the answer, bounded. A listing watches the records alone, so reading the last thousand
+// calls reads the last thousand small records and not a thousand answers; one call asked by id reads
+// both. A call's id is one token, so the record's key never holds a dot and `*` matches records only.
+
+// BusCalls keeps calls in the controller's calls bucket.
+type BusCalls struct {
+	kv jetstream.KeyValue
+}
+
+// CallsOnTheBus opens the calls bucket the controller asserts at its start.
+func CallsOnTheBus(ctx context.Context, conn *nats.Conn) (*BusCalls, error) {
+	api, err := jetstream.New(conn)
+	if err != nil {
+		return nil, err
+	}
+	kv, err := api.KeyValue(ctx, broker.CallsBucket)
+	if err != nil {
+		return nil, fmt.Errorf("the calls bucket %s is not on the bus — the controller asserts it at its "+
+			"start, so one older than this has not: %w", broker.CallsBucket, err)
+	}
+	return &BusCalls{kv: kv}, nil
+}
+
+const answerKey = ".answer"
+
+// Keep writes a call's record, and its answer when it has one.
+func (b *BusCalls) Keep(ctx context.Context, c Call) error {
+	answer := c.Answer
+	c.Answer = nil
+	if len(answer) > 0 {
+		if len(answer) > broker.CallAnswerBytes {
+			answer, _ = json.Marshal(map[string]any{"cut": fmt.Sprintf("an answer of %d bytes; the first %d "+
+				"are kept", len(answer), broker.CallAnswerBytes), "start": string(answer[:broker.CallAnswerBytes])})
+		}
+		// The answer before the record, so a record saying a call finished never points at an answer
+		// not yet written.
+		if _, err := b.kv.Put(ctx, c.ID+answerKey, answer); err != nil {
+			return err
+		}
+	}
+	record, err := json.Marshal(c)
+	if err != nil {
+		return err
+	}
+	_, err = b.kv.Put(ctx, c.ID, record)
+	return err
+}
+
+// Kept is one call, with its answer.
+func (b *BusCalls) Kept(ctx context.Context, id string) (Call, bool, error) {
+	entry, err := b.kv.Get(ctx, id)
+	if errors.Is(err, jetstream.ErrKeyNotFound) || errors.Is(err, jetstream.ErrInvalidKey) {
+		return Call{}, false, nil
+	}
+	if err != nil {
+		return Call{}, false, err
+	}
+	var c Call
+	if err := json.Unmarshal(entry.Value(), &c); err != nil {
+		return Call{}, false, fmt.Errorf("the record of %s on the bus is not a call: %w", id, err)
+	}
+	answer, err := b.kv.Get(ctx, id+answerKey)
+	switch {
+	case err == nil:
+		c.Answer = json.RawMessage(answer.Value())
+	case !errors.Is(err, jetstream.ErrKeyNotFound):
+		return Call{}, false, err
+	}
+	return c, true, nil
+}
+
+// Recent is every call the bucket holds, newest first, without answers: read once through a watch
+// of the records, which hands over the current value of each and then says it has.
+func (b *BusCalls) Recent(ctx context.Context) ([]Call, error) {
+	w, err := b.kv.Watch(ctx, "*", jetstream.IgnoreDeletes())
+	if err != nil {
+		return nil, err
+	}
+	defer func() { _ = w.Stop() }()
+	var out []Call
+	for {
+		select {
+		case <-ctx.Done():
+			return nil, fmt.Errorf("reading the calls bucket: %w", ctx.Err())
+		case entry := <-w.Updates():
+			if entry == nil {
+				// Every current value handed over.
+				sort.SliceStable(out, func(i, j int) bool { return out[i].Started.After(out[j].Started) })
+				return out, nil
+			}
+			var c Call
+			if json.Unmarshal(entry.Value(), &c) == nil && c.ID != "" {
+				out = append(out, c)
+			}
+		}
+	}
+}

internal/link/calls_kept_test.go

@@ -0,0 +1,152 @@
+package link
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"log"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/nats-io/nats.go/jetstream"
+
+	"github.com/novox/mesh-controller/internal/broker"
+)
+
+// The calls bucket against a real server (novox/hq to-be 45 §6): whether a call's outcome is
+// readable by id from a controller that did not serve it is a claim about what the bus keeps.
+
+func callsBucket(t *testing.T) *BusCalls {
+	t.Helper()
+	js := aBus(t)
+	api, err := jetstream.New(js.Conn())
+	if err != nil {
+		t.Fatal(err)
+	}
+	_ = api.DeleteKeyValue(t.Context(), broker.CallsBucket)
+	if err := js.EnsureControllerBuckets(); err != nil {
+		t.Fatal(err)
+	}
+	keeper, err := CallsOnTheBus(t.Context(), js.Conn())
+	if err != nil {
+		t.Fatal(err)
+	}
+	return keeper
+}
+
+// waitKept waits until the keeper holds a call in a state, the writes being queued.
+func waitKept(t *testing.T, keeper CallKeeper, id, state string) Call {
+	t.Helper()
+	deadline := time.Now().Add(5 * time.Second)
+	for {
+		c, found, err := keeper.Kept(context.Background(), id)
+		if err == nil && found && c.State == state {
+			return c
+		}
+		if time.Now().After(deadline) {
+			t.Fatalf("%s never kept as %q: %+v %v %v", id, state, c, found, err)
+		}
+		time.Sleep(20 * time.Millisecond)
+	}
+}
+
+// **A controller restart keeps every call's outcome** (to-be 45 Phase 0): a call one controller
+// answered is read whole by id from the next, and a call it left running is said abandoned rather
+// than running for ever.
+func TestNatsACallsOutcomeOutlivesItsController(t *testing.T) {
+	keeper := callsBucket(t)
+	first := NewCallLog()
+	if err := first.Durably(t.Context(), keeper, "controller@one", nil); err != nil {
+		t.Fatal(err)
+	}
+	a := newAnswers(t)
+	first.serveCall("mesh-controller", "push", json.RawMessage(`{"node":"anchor","values":"secret"}`),
+		"_INBOX.node-tools.g14.Pe3sGzAtv8jUBYQ6sKSvKz.1",
+		func(context.Context, json.RawMessage) (any, error) { return "anchor told", nil }, a.respond, nil)
+	recent, _ := first.Recent()
+	finished := waitKept(t, keeper, recent[0].ID, CallAnswered)
+	// A second call, still running when its controller stops.
+	left := first.begin("mesh-controller", "plans", json.RawMessage(`{}`), "")
+	waitKept(t, keeper, left.ID, CallRunning)
+
+	var said bytes.Buffer
+	second := NewCallLog()
+	if err := second.Durably(t.Context(), keeper, "controller@two", log.New(&said, "", 0)); err != nil {
+		t.Fatal(err)
+	}
+	c, found, err := second.Get(finished.ID)
+	if err != nil || !found {
+		t.Fatalf("the next controller cannot read %s: %v %v", finished.ID, found, err)
+	}
+	if !strings.Contains(string(c.Answer), "anchor told") || c.Caller != "node-tools.g14" || c.Holder != "controller@one" {
+		t.Fatalf("kept %+v", c)
+	}
+	if strings.Contains(string(c.Args), "secret") {
+		t.Fatalf("a setting was kept: %s", c.Args)
+	}
+	abandoned, _, _ := second.Get(left.ID)
+	if abandoned.State != CallAbandoned || !strings.Contains(said.String(), left.ID) {
+		t.Fatalf("a call left running reads %q, and was said: %q", abandoned.State, said.String())
+	}
+	listed, err := second.Recent()
+	if err != nil || len(listed) != 2 {
+		t.Fatalf("the next controller lists %d calls: %v", len(listed), err)
+	}
+	// Its own running calls are not its predecessor's: a controller starting again under the same
+	// name leaves them alone.
+	mine := second.begin("mesh-controller", "status", nil, "")
+	waitKept(t, keeper, mine.ID, CallRunning)
+	if err := second.Durably(t.Context(), keeper, "controller@two", nil); err != nil {
+		t.Fatal(err)
+	}
+	if c, _, _ := keeper.Kept(t.Context(), mine.ID); c.State != CallRunning {
+		t.Fatalf("a controller marked its own running call %q", c.State)
+	}
+}
+
+// The bucket holds the last thousand calls or fourteen days: a call is two keys, so the stream under
+// it holds twice as many messages, and asserting it again keeps the count.
+func TestNatsTheCallsBucketIsBounded(t *testing.T) {
+	callsBucket(t)
+	js := aBus(t)
+	if err := js.EnsureControllerBuckets(); err != nil {
+		t.Fatal(err)
+	}
+	info, err := js.Context().StreamInfo("KV_" + broker.CallsBucket)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if info.Config.MaxMsgs != 2*broker.KeptCallsDurably || info.Config.MaxAge != broker.CallsKeptFor {
+		t.Fatalf("kept %d messages for %s", info.Config.MaxMsgs, info.Config.MaxAge)
+	}
+}
+
+// An answer larger than the bound is cut and says so, and the record is still written.
+func TestNatsAnAnswerLargerThanTheBoundIsCut(t *testing.T) {
+	keeper := callsBucket(t)
+	big, _ := json.Marshal(map[string]string{"result": strings.Repeat("x", broker.CallAnswerBytes+10)})
+	c := Call{ID: "call-1-1", Seat: "mesh-controller", Verb: "plan", State: CallAnswered, Answer: big}
+	if err := keeper.Keep(t.Context(), c); err != nil {
+		t.Fatal(err)
+	}
+	got, found, err := keeper.Kept(t.Context(), "call-1-1")
+	if err != nil || !found || !strings.Contains(string(got.Answer), "the first") {
+		t.Fatalf("%v %v %.200s", found, err, got.Answer)
+	}
+}
+
+// Who asked is read from the inbox the answer goes to.
+func TestTheCallerIsTheInboxsPrincipal(t *testing.T) {
+	for reply, want := range map[string]string{
+		"_INBOX.node-tools.g14.Pe3sGzAtv8jUBYQ6sKSvKz.1": "node-tools.g14",
+		"_INBOX.jochen.Pe3sGzAtv8jUBYQ6sKSvKz":           "jochen",
+		"_INBOX.x.1":                                     "",
+		"mesh.control.one":                               "",
+		"":                                               "",
+	} {
+		if got := callerOf(reply); got != want {
+			t.Errorf("%q: %q, want %q", reply, got, want)
+		}
+	}
+}

internal/link/calls_test.go

@@ -62,7 +62,7 @@ func TestACallThatFinishesInTimeAnswersInFull(t *testing.T) {
 	if got := a.only()["result"]; got != "all well" {
 		t.Fatalf("answered %v", got)
 	}
-	recent := l.Recent()
+	recent, _ := l.Recent()
 	if len(recent) != 1 || recent[0].State != CallAnswered || string(recent[0].Args) != "{}" {
 		t.Fatalf("kept %+v", recent)
 	}
@@ -90,12 +90,12 @@ func TestACallThatOutlastsTheWindowSaysItIsRunningAndKeepsItsAnswer(t *testing.T
 	if got["running"] != true || id == "" || !strings.Contains(got["output"].(string), id) {
 		t.Fatalf("the running answer does not name its call: %v", got)
 	}
-	if c, _ := l.Get(id); c.State != CallRunning {
+	if c, _, _ := l.Get(id); c.State != CallRunning {
 		t.Fatalf("while it runs it is kept as %q", c.State)
 	}
 	close(release)
 	<-finished
-	c, ok := l.Get(id)
+	c, ok, _ := l.Get(id)
 	if !ok || c.State != CallFinishedAfter || !strings.Contains(string(c.Answer), "anchor told") {
 		t.Fatalf("its answer was not kept: %+v", c)
 	}
@@ -125,7 +125,7 @@ func TestAnAcknowledgedCallIsAnsweredBeforeItGoesOn(t *testing.T) {
 	if got := a.only()["result"].(map[string]any); got["running"] != true {
 		t.Fatalf("an acknowledged call answered %v", got)
 	}
-	if c := l.Recent()[0]; c.State != CallFinishedAfter || !strings.Contains(string(c.Answer), "sent") {
+	if c := recentOf(l)[0]; c.State != CallFinishedAfter || !strings.Contains(string(c.Answer), "sent") {
 		t.Fatalf("kept %+v", c)
 	}
 }
@@ -143,7 +143,7 @@ func TestARefusedAnswerIsKeptAgainstItsCall(t *testing.T) {
 	if !l.Refusal(refusal, log.New(&logged, "", 0)) {
 		t.Fatal("the refusal of a kept call's answer was not recognised")
 	}
-	c := l.Recent()[0]
+	c := recentOf(l)[0]
 	if c.Refused == "" || !strings.Contains(logged.String(), c.ID) {
 		t.Fatalf("the refusal is not kept or not said: %+v / %q", c, logged.String())
 	}
@@ -167,8 +167,13 @@ func TestTheLogKeepsTheNewest(t *testing.T) {
 	for i := 0; i < KeptCalls+5; i++ {
 		l.begin("s", "v", nil, "")
 	}
-	recent := l.Recent()
+	recent, _ := l.Recent()
 	if len(recent) != KeptCalls || !strings.HasSuffix(recent[0].ID, "-105") || !strings.HasSuffix(recent[KeptCalls-1].ID, "-6") {
 		t.Fatalf("kept %d, newest %s, oldest %s", len(recent), recent[0].ID, recent[len(recent)-1].ID)
 	}
 }
+
+func recentOf(l *CallLog) []Call {
+	out, _ := l.Recent()
+	return out
+}

internal/link/enrolment.go

@@ -380,6 +380,10 @@ func (e Enrolment) Heard(ctx context.Context, report Report) (news bool, err err
 	if report.Applied == nil && report.Refused == "" && len(report.Failed) == 0 {
 		if report.Superseded != "" {
 			log.Printf("%s set aside declaration %s for the newer %s", report.Node, report.Declared, report.Superseded)
+		} else if err := e.Inventory.RecordHeartbeatGap(ctx, report.Node, node.LastSeen); err != nil {
+			// The silence before this word, which the machine-silent bound will be set from (novox/hq
+			// to-be 45 Phase 0). A measurement lost is said and costs the report nothing.
+			log.Printf("the silence before %s's word could not be recorded: %v", report.Node, err)
 		}
 		return false, e.Inventory.Seen(ctx, node.ID)
 	}
@@ -435,6 +439,11 @@ func (e Enrolment) Heard(ctx context.Context, report Report) (news bool, err err
 	if err != nil {
 		return false, err
 	}
+	// And how long the machine took, from the send to this first account of it (novox/hq to-be 45
+	// Phase 0): what the sent-not-reported bound will be set from. Said if lost, never a failure.
+	if err := e.Inventory.RecordApplyDuration(ctx, report.Node, report.Declared, doing.Outcome); err != nil {
+		log.Printf("how long %s took to apply could not be recorded: %v", report.Node, 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

internal/link/handacts.go

@@ -0,0 +1,162 @@
+package link
+
+import (
+	"context"
+	"encoding/json"
+	"errors"
+	"fmt"
+	"os"
+	"sort"
+	"strconv"
+	"strings"
+	"sync/atomic"
+	"time"
+
+	"github.com/nats-io/nats.go"
+	"github.com/nats-io/nats.go/jetstream"
+
+	"github.com/novox/mesh-controller/internal/broker"
+)
+
+// The hand-act log (novox/hq to-be 45 §7).
+//
+// **A repair a person makes by hand is the record of a healer the mesh does not have yet.** Tonight's
+// pushes of one machine, plans closed because a report never came, a consumer re-made because it fell
+// a week behind — each was done, and the only trace was a chat. So every verb that repairs by hand
+// asks why, and writes one entry: who, which verb and arguments, why, when, the condition it
+// addresses if one is named, and a cause — a word that, recorded twice in a fortnight, says a healer
+// is wanted (S15, from Phase 3). `hand-act record` is the same entry for an act done outside the mesh.
+// The controller is the bucket's only writer; its verbs are the way in.
+
+// HandAct is one entry.
+type HandAct struct {
+	ID string    `json:"id"`
+	At time.Time `json:"at"`
+	// By is who: the bus principal a seat call came from, or the account and machine at a shell.
+	By string `json:"by"`
+	// Verb and Args are the act as given: `push`, `plans close`, `broker consumer-reset`, or
+	// `hand-act record` with what was done outside the mesh.
+	Verb string   `json:"verb"`
+	Args []string `json:"arguments,omitempty"`
+	Why  string   `json:"why"`
+	// Cause is the condition kind, or a word the person gives; the verb's own name when neither.
+	Cause string `json:"cause"`
+	// Condition is the condition's key the act addresses, when it names one.
+	Condition string `json:"condition,omitempty"`
+}
+
+// CallerVar carries a seat call's caller to the command the controller runs for it, so an act done
+// through the console says who asked rather than "the controller".
+const CallerVar = "MESH_CALLER"
+
+// Caller is who is acting in this process: the seat call's caller when the controller ran it for
+// one, otherwise the account and machine at the shell.
+func Caller() string {
+	if c := strings.TrimSpace(os.Getenv(CallerVar)); c != "" {
+		return c
+	}
+	user := os.Getenv("USER")
+	if user == "" {
+		user = "an unnamed account"
+	}
+	host, _ := os.Hostname()
+	return fmt.Sprintf("%s at a shell on %s", user, host)
+}
+
+type callerKey struct{}
+
+// CallerIn is the caller of the seat call ctx belongs to, empty outside one.
+func CallerIn(ctx context.Context) string {
+	c, _ := ctx.Value(callerKey{}).(string)
+	return c
+}
+
+var handActSeq atomic.Uint64
+
+// RecordHandAct writes one entry. Its key is its time and a sequence, so the bucket lists in order.
+func RecordHandAct(ctx context.Context, conn *nats.Conn, act HandAct) (HandAct, error) {
+	if strings.TrimSpace(act.Why) == "" {
+		return act, errors.New("an act by hand says why: --why <text>")
+	}
+	if act.At.IsZero() {
+		act.At = time.Now().UTC()
+	}
+	if act.ID == "" {
+		act.ID = "act-" + strconv.FormatInt(act.At.UnixNano(), 10) + "-" + strconv.FormatUint(handActSeq.Add(1), 10)
+	}
+	if act.By == "" {
+		act.By = Caller()
+	}
+	if act.Cause == "" {
+		act.Cause = act.Verb
+	}
+	kv, err := handActs(ctx, conn)
+	if err != nil {
+		return act, err
+	}
+	body, err := json.Marshal(act)
+	if err != nil {
+		return act, err
+	}
+	_, err = kv.Put(ctx, act.ID, body)
+	return act, err
+}
+
+// HandActs is every entry since a moment, oldest first.
+func HandActs(ctx context.Context, conn *nats.Conn, since time.Time) ([]HandAct, error) {
+	kv, err := handActs(ctx, conn)
+	if err != nil {
+		return nil, err
+	}
+	w, err := kv.WatchAll(ctx, jetstream.IgnoreDeletes())
+	if err != nil {
+		return nil, err
+	}
+	defer func() { _ = w.Stop() }()
+	var out []HandAct
+	for {
+		select {
+		case <-ctx.Done():
+			return nil, fmt.Errorf("reading the hand-act log: %w", ctx.Err())
+		case entry := <-w.Updates():
+			if entry == nil {
+				sort.SliceStable(out, func(i, j int) bool { return out[i].At.Before(out[j].At) })
+				return out, nil
+			}
+			var a HandAct
+			if json.Unmarshal(entry.Value(), &a) == nil && !a.At.Before(since) {
+				out = append(out, a)
+			}
+		}
+	}
+}
+
+// RepeatedCauses are the causes recorded more than once within the fortnight before now, with how
+// often: each is a repair done by hand again, which is what S15 will raise as a healer wanted.
+func RepeatedCauses(acts []HandAct, now time.Time) map[string]int {
+	counts := map[string]int{}
+	for _, a := range acts {
+		if now.Sub(a.At) <= 14*24*time.Hour {
+			counts[a.Cause]++
+		}
+	}
+	for c, n := range counts {
+		if n < 2 {
+			delete(counts, c)
+		}
+	}
+	return counts
+}
+
+func handActs(ctx context.Context, conn *nats.Conn) (jetstream.KeyValue, error) {
+	api, err := jetstream.New(conn)
+	if err != nil {
+		return nil, err
+	}
+	kv, err := api.KeyValue(ctx, broker.HandActsBucket)
+	if err != nil {
+		return nil, fmt.Errorf("the hand-act log %s is not on the bus — the controller asserts it at its "+
+			"start, so one older than this has not: %w", broker.HandActsBucket, err)
+	}
+	return kv, nil
+}

internal/link/handacts_test.go

@@ -0,0 +1,59 @@
+package link
+
+import (
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/nats-io/nats.go/jetstream"
+
+	"github.com/novox/mesh-controller/internal/broker"
+)
+
+// The hand-act log against a real server (novox/hq to-be 45 §7): an act is written with who, why and
+// its cause, read back in order, and a cause recorded twice within a fortnight is found.
+func TestNatsAnActByHandIsKeptWithWhyAndARepeatIsFound(t *testing.T) {
+	js := aBus(t)
+	api, err := jetstream.New(js.Conn())
+	if err != nil {
+		t.Fatal(err)
+	}
+	_ = api.DeleteKeyValue(t.Context(), broker.HandActsBucket)
+	if err := js.EnsureControllerBuckets(); err != nil {
+		t.Fatal(err)
+	}
+	t.Setenv(CallerVar, "node-tools.g14, through the mesh-controller seat")
+	if _, err := RecordHandAct(t.Context(), js.Conn(), HandAct{Verb: "push", Args: []string{"anchor"}}); err == nil {
+		t.Fatal("an act without why was written")
+	}
+	first, err := RecordHandAct(t.Context(), js.Conn(), HandAct{Verb: "push", Args: []string{"anchor"},
+		Why: "it never reported the send", Cause: "sent-not-reported"})
+	if err != nil {
+		t.Fatal(err)
+	}
+	if first.By != "node-tools.g14, through the mesh-controller seat" || first.ID == "" {
+		t.Fatalf("written as %+v", first)
+	}
+	if _, err := RecordHandAct(t.Context(), js.Conn(), HandAct{Verb: "plans close", Args: []string{"plan-1"},
+		Why: "waiting on the same report"}); err != nil {
+		t.Fatal(err)
+	}
+	if _, err := RecordHandAct(t.Context(), js.Conn(), HandAct{Verb: "push", Args: []string{"ace"},
+		Why: "again", Cause: "sent-not-reported", At: time.Now().UTC().Add(time.Second)}); err != nil {
+		t.Fatal(err)
+	}
+	acts, err := HandActs(t.Context(), js.Conn(), time.Now().Add(-time.Hour))
+	if err != nil || len(acts) != 3 || acts[0].ID != first.ID || acts[1].Cause != "plans close" {
+		t.Fatalf("%v %+v", err, acts)
+	}
+	repeated := RepeatedCauses(acts, time.Now())
+	if len(repeated) != 1 || repeated["sent-not-reported"] != 2 {
+		t.Fatalf("repeated %v", repeated)
+	}
+	if old, _ := HandActs(t.Context(), js.Conn(), time.Now().Add(time.Hour)); len(old) != 0 {
+		t.Fatalf("acts before the moment asked were listed: %+v", old)
+	}
+	if !strings.HasPrefix(acts[2].ID, "act-") {
+		t.Fatalf("%q", acts[2].ID)
+	}
+}