amadan
carlos run logs: a failed start hedges, and a restart's close-out logs its ending only when the result is its own (#325, Astra round 1)
Human
Prompt
re-up copy review?
From this commit's own message. The prompt ledger has no entries for it — which is what a squashed, rebased or amended commit looks like, and what every commit looks like in a repo without a ledger.
Summary
Astra round 1 (3 P2, all accepted): a StartCmd error can follow a unit that did start, so InterruptedStartFailed uses the CLI's hedged interrupted line, not 'did not start'; closeInterrupted logs only when it wrote the run's result (read before, read back after), so a restart after finish logs no second ending and a lost done answer no longer drops it. Tests for both recovery shapes, mutation-checked. Census re-pinned.
6 files changed,
+91
−18
internal/host/runevents.go+8 −5internal/host/runevents_linux_test.go+3 −1internal/host/runevents_test.go+53 −1internal/host/runs.go+24 −8internal/provision/plan9_b8_census_test.go+2 −2internal/provision/testdata/plan14-root-reads-run-lifecycle-logs-325.tsv+1 −1
CI cancelled — superseded by a newer push — run details
CI log
=== gate === cd launchctx && go vet ./... && go test ./... -count=1 ok amadan.net/carlos/platform.git/launchctx 0.013s ? amadan.net/carlos/platform.git/launchctx/controlname [no test files] ? amadan.net/carlos/platform.git/launchctx/wireid [no test files] go vet ./... gofmt -l .: clean go test ./... -count=1 -timeout 30m amadan: job cancelled — a newer push superseded it
diff --git a/internal/host/runevents.go b/internal/host/runevents.go| index 07991f66c..2aeebfdfc 100644 |
| --- a/internal/host/runevents.go |
| +++ b/internal/host/runevents.go |
| @@ -26,16 +26,19 @@ func runStartedLine(req runs.Request) string { |
| } |
| // runEndedLine is the line for a run's result, whatever ended it. started |
| -// says whether its unit was launched: a result written before that (a |
| -// refusal, a cancel or a timeout during the wake or the staging, a stop |
| -// that overlapped the launch) is a run that did not start, whatever its |
| -// fields say. |
| +// says whether RunCmd handed back a running unit: a result written before |
| +// that (a refusal, a cancel or a timeout during the wake or the staging, a |
| +// stop that overlapped the launch) is a run that did not start, whatever |
| +// its fields say. A failed start is the exception: StartCmd can answer an |
| +// error for a unit the control service did start (a lost response), and |
| +// RunCmd then stops it and hands back nothing, so the line hedges as the |
| +// CLI's does rather than say it never ran. |
| func runEndedLine(id string, res runs.Result, started bool) string { |
| took := res.Ended.Sub(res.Started).Round(time.Second) |
| switch { |
| case res.Refused != "": |
| return fmt.Sprintf("run %s did not start: %s", id, runRefusedWords(res)) |
| - case res.Interrupted != "" && (!started || res.Interrupted == runs.InterruptedStartFailed): |
| + case res.Interrupted != "" && !started && res.Interrupted != runs.InterruptedStartFailed: |
| return fmt.Sprintf("run %s did not start: %s", id, res.Interrupted) |
| case res.Cancelled && !started: |
| return fmt.Sprintf("run %s was cancelled before it started", id) |
diff --git a/internal/host/runevents_linux_test.go b/internal/host/runevents_linux_test.go| index 0b32b6d56..bcbda343e 100644 |
| --- a/internal/host/runevents_linux_test.go |
| +++ b/internal/host/runevents_linux_test.go |
| @@ -53,7 +53,9 @@ func TestRunNotStartedLogsOnlyItsEnd(t *testing.T) { |
| {activator.ErrCmdClaim, "did not start: the box has host claims armed"}, |
| {activator.ErrCmdNotNested, "did not start: the box is not on the nested layout yet"}, |
| {&activator.CmdStoppedError{Reason: activator.StopRestart}, "did not start: the instance was restarted"}, |
| - {errors.New("start cmd unit: 502"), "did not start: the box could not start the command"}, |
| + // A failed start may have started the unit (a lost response): the |
| + // line hedges rather than say it never ran. |
| + {errors.New("start cmd unit: 502"), "was interrupted: the box could not start the command. it may have done part of its work"}, |
| } |
| for _, c := range cases { |
| s := release.NewDirStore(t.TempDir()) |
diff --git a/internal/host/runevents_test.go b/internal/host/runevents_test.go| index 8ee61673f..955fb5fd4 100644 |
| --- a/internal/host/runevents_test.go |
| +++ b/internal/host/runevents_test.go |
| @@ -60,7 +60,7 @@ func TestRunEndedLineSaysHowTheRunEnded(t *testing.T) { |
| {runs.Result{Interrupted: activator.StopRestart, Ended: end}, false, |
| "run r1 did not start: the instance was restarted"}, |
| {runs.Result{Interrupted: runs.InterruptedStartFailed, Ended: end}, false, |
| - "run r1 did not start: the box could not start the command"}, |
| + "run r1 was interrupted: the box could not start the command. it may have done part of its work"}, |
| {runs.Result{Refused: runs.RefusedFlat}, false, "run r1 did not start: the box is not on the nested layout yet"}, |
| {runs.Result{Refused: runs.RefusedClaim}, false, "run r1 did not start: the box has host claims armed"}, |
| {runs.Result{Refused: runs.RefusedWake, Detail: "wake failed: restore"}, false, |
| @@ -115,6 +115,58 @@ func TestRunClosedOutAfterAnAgentRestartIsLoggedOnce(t *testing.T) { |
| } |
| } |
| +// A restart after the command's own result landed, but before its done |
| +// CAS did, closes the run out without a second ending: the boot that ran |
| +// the command logged it (Astra review, finding 2). |
| +func TestRunClosedOutAfterItsOwnResultLogsNothing(t *testing.T) { |
| + s := release.NewDirStore(t.TempDir()) |
| + _, id := queueRun(t, s, time.Now().Add(time.Minute)) |
| + got, err := provision.SetRecordRun(context.Background(), s, "bab", "shop", runHost, provision.RunPick(id, "box-1", "boot-old", time.Now().Add(time.Hour))) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + if err := runs.WriteResult(context.Background(), s, "bab", "shop", id, runs.Result{Exit: 0, Box: "box-1", Ended: time.Now().UTC()}); err != nil { |
| + t.Fatal(err) |
| + } |
| + var l execLog |
| + var events eventLog |
| + w := testWorker(s, runOwnedRoute(runHost), "box-1", "boot-new", &l) |
| + w.events = &events |
| + w.consider(context.Background(), *got) |
| + if ev := events.all(); len(ev) != 0 { |
| + t.Fatalf("events %+v, want none", ev) |
| + } |
| + if r := currentRun(t, s); r.State != provision.RunDone { |
| + t.Fatalf("run %+v, want done", r) |
| + } |
| + if res, _ := runs.ReadResult(context.Background(), s, "bab", "shop", id); res == nil || res.Interrupted != "" { |
| + t.Fatalf("result %+v, want the command's own", res) |
| + } |
| +} |
| + |
| +// A done CAS whose answer was lost still leaves the ending logged once: |
| +// it is logged with the result, not with the CAS (Astra review, finding 3). |
| +func TestRunClosedOutWithALostDoneAnswerIsLoggedOnce(t *testing.T) { |
| + dir := release.NewDirStore(t.TempDir()) |
| + _, id := queueRun(t, dir, time.Now().Add(time.Minute)) |
| + got, err := provision.SetRecordRun(context.Background(), dir, "bab", "shop", runHost, provision.RunPick(id, "box-1", "boot-old", time.Now().Add(time.Hour))) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + var l execLog |
| + var events eventLog |
| + w := testWorker(&lostAnswer{Store: dir, land: true}, runOwnedRoute(runHost), "box-1", "boot-new", &l) |
| + w.events = &events |
| + w.consider(context.Background(), *got) |
| + w.consider(context.Background(), *got) |
| + if r := currentRun(t, dir); r.State != provision.RunDone { |
| + t.Fatalf("run %+v, want done (the CAS landed)", r) |
| + } |
| + if ev := events.all(); len(ev) != 1 || !strings.Contains(ev[0].msg, "the box's agent restarted") { |
| + t.Fatalf("events %+v, want one interrupted ending", ev) |
| + } |
| +} |
| + |
| // A worker with no sink, as on a box with no log store, still runs. |
| func TestRunEventWithoutASinkIsANoop(t *testing.T) { |
| w := &runsWorker{} |
diff --git a/internal/host/runs.go b/internal/host/runs.go| index 7f5cf09e9..44cd4c05d 100644 |
| --- a/internal/host/runs.go |
| +++ b/internal/host/runs.go |
| @@ -314,16 +314,32 @@ func (w *runsWorker) closeInterrupted(ctx context.Context, rec provision.Record) |
| return |
| } |
| res := runs.Result{Interrupted: runs.InterruptedAgentRestart, Box: w.box, Ended: w.now().UTC(), LastSeq: last} |
| - if err := runs.WriteResult(ctx, w.store, rec.Account, rec.App, id, res); err != nil { |
| - log.Printf("agent: runs: %s %s: result: %v", rec.Host, id, err) |
| + // The ending is logged by the pass whose result is the run's, and by no |
| + // other (amadan #325). Every pass that still reads the run as picked |
| + // comes back here, and the create-only write answers a second time as |
| + // if it had landed; a result already there was written by the boot that |
| + // ran the command, which logged its own ending, or by an earlier pass |
| + // of this one. So the result is read first, and read back after the |
| + // write: a write whose answer was lost but whose result is this pass's |
| + // still logs, once. |
| + prior, err := runs.ReadResult(ctx, w.store, rec.Account, rec.App, id) |
| + if err != nil { |
| + log.Printf("agent: runs: %s %s: read the result: %v", rec.Host, id, err) |
| return |
| } |
| - // The ending is logged only by the pass whose done CAS lands: every |
| - // pass that still reads the run as picked comes back here, and the |
| - // result write answers a second time as if it had landed. |
| - if _, err := provision.SetRecordRun(ctx, w.store, rec.Account, rec.App, rec.Host, provision.RunFinish(id)); err == nil { |
| - w.runEvent(rec, runEndedLine(id, res, true)) |
| - } else if !errors.Is(err, provision.ErrRunConflict) && !errors.Is(err, os.ErrNotExist) { |
| + if prior == nil { |
| + werr := runs.WriteResult(ctx, w.store, rec.Account, rec.App, id, res) |
| + got, err := runs.ReadResult(ctx, w.store, rec.Account, rec.App, id) |
| + if err != nil || got == nil { |
| + log.Printf("agent: runs: %s %s: result: %v", rec.Host, id, errors.Join(werr, err)) |
| + return |
| + } |
| + if got.Box == res.Box && got.Ended.Equal(res.Ended) && got.Interrupted == res.Interrupted { |
| + w.runEvent(rec, runEndedLine(id, res, true)) |
| + } |
| + } |
| + if _, err := provision.SetRecordRun(ctx, w.store, rec.Account, rec.App, rec.Host, provision.RunFinish(id)); err != nil && |
| + !errors.Is(err, provision.ErrRunConflict) && !errors.Is(err, os.ErrNotExist) { |
| log.Printf("agent: runs: %s %s: done: %v", rec.Host, id, err) |
| } |
| if err := runs.RemoveRunDir(provision.InstanceDir(w.dataDir, rec.Host), id); err != nil && !errors.Is(err, os.ErrNotExist) { |
diff --git a/internal/provision/plan9_b8_census_test.go b/internal/provision/plan9_b8_census_test.go| index af50fadc4..6774775c5 100644 |
| --- a/internal/provision/plan9_b8_census_test.go |
| +++ b/internal/provision/plan9_b8_census_test.go |
| @@ -1105,8 +1105,8 @@ var plan9B8CensusInventory = []censusEntry{ |
| // Re-reviewed for run-lifecycle-logs-325 (amadan #325, proposed): emits the run's end as a member log event; record writes unchanged. |
| {"internal/host/runexec.go", "runsWorker.finish", "record-writer", "key:SetRecordRun", "8353643af2281da9b08b629d387d1d91ba0c8db2b2afbedc24cbfb3042854039"}, |
| // The box closes a run an agent restart interrupted through SetRecordRun (runFinishOurs). |
| - // Re-reviewed for run-lifecycle-logs-325 (amadan #325, proposed): emits the run's end as a member log event when its done CAS succeeds; record writes unchanged. |
| - {"internal/host/runs.go", "runsWorker.closeInterrupted", "record-writer", "key:SetRecordRun", "218a369319153fe05c320587dd425893d42eca4c320a6b1de34efae369b39188"}, |
| + // Re-reviewed for run-lifecycle-logs-325 (amadan #325, proposed): reads result.json before and after its create-only write and emits the run's end as a member log event only when the result is its own; record writes unchanged. |
| + {"internal/host/runs.go", "runsWorker.closeInterrupted", "record-writer", "key:SetRecordRun", "fdfbca50d70569c82d6846734f32ec2d518126b334034f755418fe9fd06224bc"}, |
| // The box finishes a run of this boot whose result is written through SetRecordRun (RunFinish). |
| {"internal/host/runs.go", "runsWorker.finishStranded", "record-writer", "key:SetRecordRun", "2d775d33b9ba97e4ed2953eb1880d33affcfba95fe5857dcdde72eb0f9acadf0"}, |
| // The box picks a queued run up by CAS through SetRecordRun (RunPick). |
diff --git a/internal/provision/testdata/plan14-root-reads-run-lifecycle-logs-325.tsv b/internal/provision/testdata/plan14-root-reads-run-lifecycle-logs-325.tsv| index a0402892e..371dd33f4 100644 |
| --- a/internal/provision/testdata/plan14-root-reads-run-lifecycle-logs-325.tsv |
| +++ b/internal/provision/testdata/plan14-root-reads-run-lifecycle-logs-325.tsv |
| @@ -1,6 +1,6 @@ |
| # Census overlay run-lifecycle-logs-325 (amadan #325: the box's carlos run worker emits run started and run ended as info-level member log events through the agent's EventSink), loaded LAST, after bootstrap-carlos-follows-316. Proposed; ruling asked of the census owner on #280. |
| # No root read, file read or record write is added: the events are pure string formatting plus one EventSink.Event call, so runAgent (which passes the sink to armRunsPass) and runsWorker.execute (which emits the two events) keep their class, task and read sites, and only their digests, runAgent's Route offset and the internal/host envelope move. execute is accepted-legacy, so its declaration is re-pinned and the seal moves. |
| -@coverage internal/host 7ff673c0284d13147cfca8229db948da2d180477d6ead4a80930d3b8ae807d6d |
| +@coverage internal/host fd22df93af01f39dae392f172bbc5458aeb1728017925f148240aac518c14931 |
| @legacy 6f7ae8c101088f20464d1a727c898190b04726de1f08ee6040212be2ad840caa internal/host/runexec.go runsWorker.execute legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): runs one picked run to its result in the bucket; every root action goes through instance control;rev3=PROPOSED-325;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=emits the run's start and end as member log events through the agent's EventSink; reads unchanged file:Prepare@1838,whole:Route@2539 1b075de70048003120c62153a50f6d83bd3eff6615f9ea5008ddc747846c8fbb |
| internal/host/runexec.go runsWorker.execute legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): runs one picked run to its result in the bucket; every root action goes through instance control;rev3=PROPOSED-325;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=emits the run's start and end as member log events through the agent's EventSink; reads unchanged file:Prepare@1838,whole:Route@2539 1b075de70048003120c62153a50f6d83bd3eff6615f9ea5008ddc747846c8fbb |
| internal/host/agent.go runAgent authority B,C,D,F rev3=census-ruling-seeded-instances;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): main's body with wireSeedPlacement called in the activator start's Configure step, before armMovesPass, and the startup sweep's result stored for the import rollback in Recover; read sites unchanged, offsets moved; main's B,C,D,F authority retained PROPOSED E46: captured claim selection and root journal mutation; root RPC outside service host exclusion; SQL/route data never grants root authority. Executing identity: service controller; root for inventory/retirement callbacks.;rev3=PROPOSED-325;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=passes the agent's log sink to armRunsPass; reads unchanged file:Exec@13802,file:Open@731,registry:App@10065,whole:Route@10057,whole:Route@23122 9250dbd16a071a1f01e835f0fb8419e4de59effaa6f1d178b23547957ff66d86 |