amadan

carlos / platform Public

carlos run: a run's start and end reach carlos logs (#325)

Human

Prompt

Can we build issue 325 ?

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

The box's runs worker emits two info-level platform events per run through the agent's EventSink: who started it, and how it ended or why it did not start. Output and argv are never logged. Census overlay run-lifecycle-logs-325 (PROPOSED-325) and B8 re-pins.
Agent notes
Copy is DRAFT, awaiting Paul's copy review (16 strings, incl. a cli.md sentence not yet written). Apply approved text verbatim to internal/host/runevents.go and the tests; the census does not pin runevents.go.
claude 5c8548a63ed6cfc12fc1a163e420aaf7b6394918 parent cd2dd6e
9 files changed, +314 −8
  • internal/host/agent.go +1 −1
  • internal/host/runevents.go +81 −0
  • internal/host/runevents_linux_test.go +70 −0
  • internal/host/runevents_test.go +122 −0
  • internal/host/runexec.go +5 −0
  • internal/host/runs.go +14 −4
  • internal/provision/plan14_root_reads_test.go +11 −1
  • internal/provision/plan9_b8_census_test.go +4 −2
  • internal/provision/testdata/plan14-root-reads-run-lifecycle-logs-325.tsv +6 −0

CI passed — run details

CI log 
=== gate ===
cd launchctx && go vet ./... && go test ./... -count=1
ok  	amadan.net/carlos/platform.git/launchctx	0.011s
?   	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
ok  	github.com/carlosframework/platform	301.322s
?   	github.com/carlosframework/platform/cmd/changelog	[no test files]
ok  	github.com/carlosframework/platform/cmd/console	2.659s
ok  	github.com/carlosframework/platform/cmd/moveprobe	92.275s
ok  	github.com/carlosframework/platform/cmd/zddprobe	0.703s
ok  	github.com/carlosframework/platform/internal/activator	251.657s
ok  	github.com/carlosframework/platform/internal/agentsock	0.017s
ok  	github.com/carlosframework/platform/internal/alerting	0.004s
ok  	github.com/carlosframework/platform/internal/analytics	0.021s
ok  	github.com/carlosframework/platform/internal/appconfig	2.415s
ok  	github.com/carlosframework/platform/internal/apperr	0.085s
ok  	github.com/carlosframework/platform/internal/applog	0.145s
ok  	github.com/carlosframework/platform/internal/awsinv	0.004s
ok  	github.com/carlosframework/platform/internal/boxchoice	0.004s
ok  	github.com/carlosframework/platform/internal/boxid	0.530s
?   	github.com/carlosframework/platform/internal/boxid/boxidtest	[no test files]
?   	github.com/carlosframework/platform/internal/boxid/internal/signtest	[no test files]
ok  	github.com/carlosframework/platform/internal/boxvolumes	0.008s
ok  	github.com/carlosframework/platform/internal/caps	0.014s
ok  	github.com/carlosframework/platform/internal/certwarm	0.004s
ok  	github.com/carlosframework/platform/internal/cgroup	0.697s
ok  	github.com/carlosframework/platform/internal/changelog	0.314s
ok  	github.com/carlosframework/platform/internal/claimactivation	0.781s
ok  	github.com/carlosframework/platform/internal/clamd	0.054s
?   	github.com/carlosframework/platform/internal/cliflag	[no test files]
ok  	github.com/carlosframework/platform/internal/console	407.223s
?   	github.com/carlosframework/platform/internal/controlname	[no test files]
?   	github.com/carlosframework/platform/internal/controlsock	[no test files]
ok  	github.com/carlosframework/platform/internal/dbdoor	5.921s
ok  	github.com/carlosframework/platform/internal/dbdoor/dbdoortest	0.010s
ok  	github.com/carlosframework/platform/internal/dbverify	0.004s
ok  	github.com/carlosframework/platform/internal/dnsrec	0.004s
ok  	github.com/carlosframework/platform/internal/docsite	0.005s
ok  	github.com/carlosframework/platform/internal/domains	2.340s
ok  	github.com/carlosframework/platform/internal/doorkey	0.008s
ok  	github.com/carlosframework/platform/internal/economics	0.005s
ok  	github.com/carlosframework/platform/internal/edge	45.011s
?   	github.com/carlosframework/platform/internal/edgeproof	[no test files]
ok  	github.com/carlosframework/platform/internal/edgesfile	0.009s
ok  	github.com/carlosframework/platform/internal/fleetapi	0.140s
ok  	github.com/carlosframework/platform/internal/gate	1.659s
ok  	github.com/carlosframework/platform/internal/genselect	0.025s
ok  	github.com/carlosframework/platform/internal/geo	0.011s
ok  	github.com/carlosframework/platform/internal/geoip	0.030s
ok  	github.com/carlosframework/platform/internal/historyreadback	0.162s
ok  	github.com/carlosframework/platform/internal/host	181.233s
ok  	github.com/carlosframework/platform/internal/hostactors	5.433s
ok  	github.com/carlosframework/platform/internal/hostactors/awsmembership	0.005s
ok  	github.com/carlosframework/platform/internal/hostbox	2.675s
ok  	github.com/carlosframework/platform/internal/hostclaim	0.578s
ok  	github.com/carlosframework/platform/internal/hostenv	0.008s
ok  	github.com/carlosframework/platform/internal/hostevidence	0.006s
ok  	github.com/carlosframework/platform/internal/hostexec	4.681s
ok  	github.com/carlosframework/platform/internal/hostfence	0.035s
ok  	github.com/carlosframework/platform/internal/hostfiles	10.453s
ok  	github.com/carlosframework/platform/internal/hostfloor	0.015s
ok  	github.com/carlosframework/platform/internal/hostguard	0.995s
ok  	github.com/carlosframework/platform/internal/hostops	1.580s
?   	github.com/carlosframework/platform/internal/hostops/fencerelease	[no test files]
ok  	github.com/carlosframework/platform/internal/hostops/internal/fencerelease	0.002s
ok  	github.com/carlosframework/platform/internal/hostquarantine	0.003s
ok  	github.com/carlosframework/platform/internal/hostrelocate	0.469s
ok  	github.com/carlosframework/platform/internal/hostresolve	0.131s
ok  	github.com/carlosframework/platform/internal/hostwrite	0.005s
ok  	github.com/carlosframework/platform/internal/infraview	0.004s
ok  	github.com/carlosframework/platform/internal/instancectl	5.225s
ok  	github.com/carlosframework/platform/internal/instanceexec	2.726s
ok  	github.com/carlosframework/platform/internal/instancefs	0.005s
ok  	github.com/carlosframework/platform/internal/instancekey	0.003s
ok  	github.com/carlosframework/platform/internal/instanceupdates	0.011s
ok  	github.com/carlosframework/platform/internal/layout	1.558s
ok  	github.com/carlosframework/platform/internal/lbhealth	0.003s
ok  	github.com/carlosframework/platform/internal/lease	9.794s
ok  	github.com/carlosframework/platform/internal/lease/leasetest	0.009s
ok  	github.com/carlosframework/platform/internal/ledger	0.014s
ok  	github.com/carlosframework/platform/internal/mail	0.178s
ok  	github.com/carlosframework/platform/internal/maintenance	0.078s
ok  	github.com/carlosframework/platform/internal/maintenanceexec	5.508s
ok  	github.com/carlosframework/platform/internal/maintenanceguard	0.065s
ok  	github.com/carlosframework/platform/internal/metrics	0.005s
ok  	github.com/carlosframework/platform/internal/moves	21.210s
ok  	github.com/carlosframework/platform/internal/moves/archive	0.769s
ok  	github.com/carlosframework/platform/internal/objstore	0.193s
ok  	github.com/carlosframework/platform/internal/ops	0.184s
ok  	github.com/carlosframework/platform/internal/park	0.216s
ok  	github.com/carlosframework/platform/internal/privatefile	0.004s
ok  	github.com/carlosframework/platform/internal/provision	28.843s
ok  	github.com/carlosframework/platform/internal/publicrelease	0.008s
?   	github.com/carlosframework/platform/internal/regionname	[no test files]
ok  	github.com/carlosframework/platform/internal/registry	5.413s
ok  	github.com/carlosframework/platform/internal/relay	7.225s
ok  	github.com/carlosframework/platform/internal/release	23.962s
ok  	github.com/carlosframework/platform/internal/rollout	3.645s
ok  	github.com/carlosframework/platform/internal/rolloutwords	0.003s
ok  	github.com/carlosframework/platform/internal/rootaws	0.007s
ok  	github.com/carlosframework/platform/internal/rootparticipation	0.057s
ok  	github.com/carlosframework/platform/internal/rootstate	0.026s
ok  	github.com/carlosframework/platform/internal/runs	0.562s
ok  	github.com/carlosframework/platform/internal/s3compat	0.005s
ok  	github.com/carlosframework/platform/internal/safefile	0.005s
ok  	github.com/carlosframework/platform/internal/schedule	2.486s
ok  	github.com/carlosframework/platform/internal/seeds	0.011s
ok  	github.com/carlosframework/platform/internal/sim/hostlife	8.863s
ok  	github.com/carlosframework/platform/internal/sim/litestreamfacts	3.609s
ok  	github.com/carlosframework/platform/internal/status	0.067s
ok  	github.com/carlosframework/platform/internal/steering	0.005s
ok  	github.com/carlosframework/platform/internal/stopevidence	0.381s
ok  	github.com/carlosframework/platform/internal/svcrole	0.002s
ok  	github.com/carlosframework/platform/internal/telemetry	0.004s
ok  	github.com/carlosframework/platform/internal/termfence	0.004s
ok  	github.com/carlosframework/platform/internal/tunnelclient	0.004s
ok  	github.com/carlosframework/platform/internal/unixdial	0.002s
ok  	github.com/carlosframework/platform/internal/updatewords	0.004s
ok  	github.com/carlosframework/platform/internal/usage	0.004s
ok  	github.com/carlosframework/platform/internal/version	0.001s
ok  	github.com/carlosframework/platform/internal/vet	1.543s
=== cross ===
--- shard 0 of 5 ---
cross-compiling darwin/arm64
--- shard 1 of 5 ---
cross-compiling darwin/amd64
--- shard 2 of 5 ---
cross-compiling linux/arm64
linux/arm64 carlos binary: 49414306 bytes (ceiling 52000000)
--- shard 3 of 5 ---
cross-compiling windows/amd64
--- shard 4 of 5 ---
cross-compiling windows/arm64
=== minio-contract ===
minio contract: arm64, minio RELEASE.2025-09-07T16-13-09Z, mc RELEASE.2025-08-13T08-35-41Z
  minio: cached, digest verified
  mc: cached, digest verified
  minio healthy on 127.0.0.1:20999
Added `local` successfully.
Bucket created successfully `local/contract-bucket`.
Bucket created successfully `local/denied-bucket`.
Created policy `contract-only` successfully.
Added user `scopeduser` successfully.
Attached Policies: [contract-only]
To User: scopeduser
  buckets and scoped user ready
=== RUN   TestDeliveredContractMinio
=== RUN   TestDeliveredContractMinio/put
=== RUN   TestDeliveredContractMinio/get_round-trips_the_body
=== RUN   TestDeliveredContractMinio/list_shows_the_key
=== RUN   TestDeliveredContractMinio/head_and_list_agree_on_the_version
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_its_own_object
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/not_by_PutObjectTagging
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/and_not_by_x-amz-tagging_on_upload
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CreateMultipartUpload
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CopyObject_with_a_REPLACE_tagging_directive
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/but_multipart_itself_is_allowed
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_copy_itself_is_allowed
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/a_POST-policy_forged_tag_with_a_matching_version_is_still_not_a_verdict
=== RUN   TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_an_ordinary_tagged-with-something-else_upload_is_allowed
=== RUN   TestDeliveredContractMinio/delete_removes_it
=== RUN   TestDeliveredContractMinio/cross-bucket_denial
--- PASS: TestDeliveredContractMinio (0.02s)
    --- PASS: TestDeliveredContractMinio/put (0.00s)
    --- PASS: TestDeliveredContractMinio/get_round-trips_the_body (0.00s)
    --- PASS: TestDeliveredContractMinio/list_shows_the_key (0.00s)
    --- PASS: TestDeliveredContractMinio/head_and_list_agree_on_the_version (0.00s)
    --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object (0.00s)
        --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/not_by_PutObjectTagging (0.00s)
        --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/and_not_by_x-amz-tagging_on_upload (0.00s)
    --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route (0.01s)
        --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CreateMultipartUpload (0.00s)
        --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CopyObject_with_a_REPLACE_tagging_directive (0.00s)
        --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/but_multipart_itself_is_allowed (0.00s)
        --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_copy_itself_is_allowed (0.00s)
        --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/a_POST-policy_forged_tag_with_a_matching_version_is_still_not_a_verdict (0.00s)
        --- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_an_ordinary_tagged-with-something-else_upload_is_allowed (0.00s)
    --- PASS: TestDeliveredContractMinio/delete_removes_it (0.00s)
    --- PASS: TestDeliveredContractMinio/cross-bucket_denial (0.00s)
PASS
ok  	github.com/carlosframework/platform/internal/objstore	0.022s
=== RUN   TestT4StorageProbeMinio
2026/10/20 14:11:15 moves: T4: STORE: list: operation error S3: ListObjectsV2, https response error StatusCode: 403, RequestID: 18E0423BABE037E5, HostID: 7c420053e0fbcd7f41653fdd92ffa2802c903d05303b1aa15adc2e8bb65d183f, api error SignatureDoesNotMatch: The request signature we calculated does not match the signature you provided. Check your key and signing method.
--- PASS: TestT4StorageProbeMinio (0.00s)
PASS
ok  	github.com/carlosframework/platform/internal/host	0.021s
minio contract: PASS
diff --git a/internal/host/agent.go b/internal/host/agent.go
index bb9e33fea..eae8b60a4 100644
--- a/internal/host/agent.go
+++ b/internal/host/agent.go
@@ -605,7 +605,7 @@ func runAgent(args []string, buildClaims ClaimFactory) {
// latch: no run is picked up before the startup sweep has
// stopped a previous agent's leftover units, the cmd units
// among them.
- armRunsPass(svc, reg, dd)
+ armRunsPass(svc, reg, dd, rolloutSink)
},
Ready: func() {
close(started)
diff --git a/internal/host/runevents.go b/internal/host/runevents.go
new file mode 100644
index 000000000..07991f66c
--- /dev/null
+++ b/internal/host/runevents.go
@@ -0,0 +1,81 @@
+package host
+
+import (
+ "fmt"
+ "time"
+
+ "github.com/carlosframework/platform/internal/applog"
+ "github.com/carlosframework/platform/internal/provision"
+ "github.com/carlosframework/platform/internal/runs"
+)
+
+// A run's two lines in `carlos logs` (amadan #325): when it started and who
+// asked for it, then how it ended. The output stays in the run's chunks and
+// the argv in the audit log; neither is ever written here, since a log
+// reader is not necessarily someone the command's arguments were meant for.
+//
+// Both lines are info. The Errors and Availability views read the platform
+// stream at warn and above, and a command that failed says nothing about
+// whether the instance could serve.
+
+const runEventLevel = applog.LevelInfo
+
+// runStartedLine is the line for a run whose unit has started.
+func runStartedLine(req runs.Request) string {
+ return fmt.Sprintf("run %s started by %s", req.ID, req.By)
+}
+
+// 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.
+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):
+ 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)
+ case res.Cancelled:
+ return fmt.Sprintf("run %s was cancelled after %s", id, took)
+ case res.TimedOut && !started:
+ return fmt.Sprintf("run %s timed out before it started", id)
+ case res.TimedOut:
+ return fmt.Sprintf("run %s timed out after %s", id, took)
+ case res.Interrupted != "":
+ return fmt.Sprintf("run %s was interrupted: %s. it may have done part of its work", id, res.Interrupted)
+ case res.Signal != "":
+ return fmt.Sprintf("run %s was ended by signal %s after %s", id, res.Signal, took)
+ }
+ return fmt.Sprintf("run %s ended with exit %d after %s", id, res.Exit, took)
+}
+
+// runRefusedWords is why the box did not start the run. An unknown code
+// renders as itself, as the CLI's does.
+func runRefusedWords(res runs.Result) string {
+ switch res.Refused {
+ case runs.RefusedFlat:
+ return "the box is not on the nested layout yet"
+ case runs.RefusedClaim:
+ return "the box has host claims armed"
+ case runs.RefusedWake:
+ return fmt.Sprintf("the instance did not wake. %s", res.Detail)
+ case runs.RefusedIncarnation:
+ return "the instance was deleted and created again after the run was requested"
+ case runs.RefusedImport:
+ return "the instance is an import that is not committed yet"
+ }
+ return res.Refused
+}
+
+// runEvent publishes one of a run's lines against the record's instance.
+// A box with no log store has no sink, and emits nothing.
+func (w *runsWorker) runEvent(rec provision.Record, line string) {
+ if w.events == nil {
+ return
+ }
+ w.events.Event(rec.Account, rec.App, rec.Host, runEventLevel, line)
+}
diff --git a/internal/host/runevents_linux_test.go b/internal/host/runevents_linux_test.go
new file mode 100644
index 000000000..0b32b6d56
--- /dev/null
+++ b/internal/host/runevents_linux_test.go
@@ -0,0 +1,70 @@
+package host
+
+import (
+ "errors"
+ "reflect"
+ "strings"
+ "testing"
+
+ "github.com/carlosframework/platform/internal/activator"
+ "github.com/carlosframework/platform/internal/applog"
+ "github.com/carlosframework/platform/internal/instancectl"
+ "github.com/carlosframework/platform/internal/release"
+)
+
+// A run that starts logs its start, then its end, against the record's
+// instance, at info, through the worker's sink.
+func TestRunLogsItsStartAndItsEnd(t *testing.T) {
+ s := release.NewDirStore(t.TempDir())
+ rec, req := pickedRun(t, s, 60)
+ req.By = "member@example.com"
+ h := &fakeHandle{polls: make(chan instancectl.CmdStatus, 1)}
+ h.polls <- instancectl.CmdStatus{State: instancectl.CmdDone, InvocationID: "inv1", Result: "exit-code", Status: "3", Code: "1"}
+ var events eventLog
+ w := execWorker(t, s, &fakeLauncher{handle: h, out: "the output\n"}, "boot-1")
+ w.events = &events
+ runOn(t, w, s, rec, req, newRunHandle())
+ ev := events.all()
+ if len(ev) != 2 {
+ t.Fatalf("events %+v, want a start and an end", ev)
+ }
+ want := loggedEvent{rec.Account, rec.App, rec.Host, applog.LevelInfo, "run " + req.ID + " started by member@example.com"}
+ if ev[0] != want {
+ t.Errorf("start %+v, want %+v", ev[0], want)
+ }
+ end := ev[1]
+ if end.acct != rec.Account || end.app != rec.App || end.host != rec.Host || end.level != applog.LevelInfo ||
+ !strings.HasPrefix(end.msg, "run "+req.ID+" ended with exit 3 after ") {
+ t.Errorf("end %+v", end)
+ }
+ for _, e := range ev {
+ if strings.Contains(e.msg, "the output") || strings.Contains(e.msg, "import") {
+ t.Errorf("%q carries the run's output or its arguments", e.msg)
+ }
+ }
+}
+
+// A run the box does not start logs only that it did not start, and why.
+func TestRunNotStartedLogsOnlyItsEnd(t *testing.T) {
+ cases := []struct {
+ err error
+ want string
+ }{
+ {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"},
+ }
+ for _, c := range cases {
+ s := release.NewDirStore(t.TempDir())
+ rec, req := pickedRun(t, s, 60)
+ var events eventLog
+ w := execWorker(t, s, &fakeLauncher{err: c.err}, "boot-1")
+ w.events = &events
+ runOn(t, w, s, rec, req, newRunHandle())
+ want := []loggedEvent{{rec.Account, rec.App, rec.Host, applog.LevelInfo, "run " + req.ID + " " + c.want}}
+ if ev := events.all(); !reflect.DeepEqual(ev, want) {
+ t.Errorf("%v: events %+v, want %+v", c.err, ev, want)
+ }
+ }
+}
diff --git a/internal/host/runevents_test.go b/internal/host/runevents_test.go
new file mode 100644
index 000000000..8ee61673f
--- /dev/null
+++ b/internal/host/runevents_test.go
@@ -0,0 +1,122 @@
+package host
+
+import (
+ "context"
+ "reflect"
+ "strings"
+ "sync"
+ "testing"
+ "time"
+
+ "github.com/carlosframework/platform/internal/activator"
+ "github.com/carlosframework/platform/internal/applog"
+ "github.com/carlosframework/platform/internal/provision"
+ "github.com/carlosframework/platform/internal/release"
+ "github.com/carlosframework/platform/internal/runs"
+)
+
+// eventLog records what a worker hands its EventSink.
+type eventLog struct {
+ mu sync.Mutex
+ events []loggedEvent
+}
+
+type loggedEvent struct{ acct, app, host, level, msg string }
+
+func (l *eventLog) App(acct, app, host, line string) {}
+
+func (l *eventLog) Event(acct, app, host, level, msg string) {
+ l.mu.Lock()
+ defer l.mu.Unlock()
+ l.events = append(l.events, loggedEvent{acct, app, host, level, msg})
+}
+
+func (l *eventLog) all() []loggedEvent {
+ l.mu.Lock()
+ defer l.mu.Unlock()
+ return append([]loggedEvent(nil), l.events...)
+}
+
+func TestRunEndedLineSaysHowTheRunEnded(t *testing.T) {
+ start := time.Date(2026, 10, 20, 12, 0, 0, 0, time.UTC)
+ end := start.Add(90*time.Second + 400*time.Millisecond)
+ ran := func(r runs.Result) runs.Result { r.Started, r.Ended = start, end; return r }
+ cases := []struct {
+ res runs.Result
+ started bool
+ want string
+ }{
+ {ran(runs.Result{}), true, "run r1 ended with exit 0 after 1m30s"},
+ {ran(runs.Result{Exit: 3}), true, "run r1 ended with exit 3 after 1m30s"},
+ {ran(runs.Result{Signal: "9"}), true, "run r1 was ended by signal 9 after 1m30s"},
+ {ran(runs.Result{TimedOut: true}), true, "run r1 timed out after 1m30s"},
+ {runs.Result{TimedOut: true, Ended: end}, false, "run r1 timed out before it started"},
+ {ran(runs.Result{Cancelled: true, Exit: 143}), true, "run r1 was cancelled after 1m30s"},
+ {runs.Result{Cancelled: true, Ended: end}, false, "run r1 was cancelled before it started"},
+ {ran(runs.Result{Interrupted: activator.StopRestart}), true,
+ "run r1 was interrupted: the instance was restarted. it may have done part of its work"},
+ {runs.Result{Interrupted: runs.InterruptedAgentRestart, Ended: end}, true,
+ "run r1 was interrupted: the box's agent restarted. it may have done part of its work"},
+ {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"},
+ {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,
+ "run r1 did not start: the instance did not wake. wake failed: restore"},
+ {runs.Result{Refused: runs.RefusedIncarnation}, false,
+ "run r1 did not start: the instance was deleted and created again after the run was requested"},
+ {runs.Result{Refused: runs.RefusedImport}, false, "run r1 did not start: the instance is an import that is not committed yet"},
+ {runs.Result{Refused: "something-new"}, false, "run r1 did not start: something-new"},
+ }
+ for _, c := range cases {
+ if got := runEndedLine("r1", c.res, c.started); got != c.want {
+ t.Errorf("%+v (started %v):\n got %q\nwant %q", c.res, c.started, got, c.want)
+ }
+ }
+}
+
+// The start line names the run and who asked for it, and never the
+// command's arguments: they can carry what a log reader should not see.
+func TestRunStartedLineCarriesNoArguments(t *testing.T) {
+ req := runs.Request{ID: "r1", By: "member@example.com", Argv: []string{"import", "--token", "s3cret"}}
+ got := runStartedLine(req)
+ if got != "run r1 started by member@example.com" {
+ t.Fatalf("got %q", got)
+ }
+ for _, a := range req.Argv {
+ if strings.Contains(got, a) {
+ t.Fatalf("%q carries the argument %q", got, a)
+ }
+ }
+}
+
+// A run closed out after an agent restart is logged as interrupted once,
+// however many passes still read it as picked.
+func TestRunClosedOutAfterAnAgentRestartIsLoggedOnce(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)
+ }
+ var l execLog
+ var events eventLog
+ w := testWorker(s, runOwnedRoute(runHost), "box-1", "boot-new", &l)
+ w.events = &events
+ // got is the stale read a second pass would also have noted.
+ w.consider(context.Background(), *got)
+ w.consider(context.Background(), *got)
+ want := []loggedEvent{{"bab", "shop", runHost, applog.LevelInfo,
+ "run " + id + " was interrupted: the box's agent restarted. it may have done part of its work"}}
+ if ev := events.all(); !reflect.DeepEqual(ev, want) {
+ t.Fatalf("events %+v, want %+v", ev, want)
+ }
+}
+
+// A worker with no sink, as on a box with no log store, still runs.
+func TestRunEventWithoutASinkIsANoop(t *testing.T) {
+ w := &runsWorker{}
+ w.runEvent(provision.Record{Account: "bab", App: "shop", Host: runHost}, "run r1 started by member@example.com")
+}
diff --git a/internal/host/runexec.go b/internal/host/runexec.go
index 4b8aacf1f..c0a72d7f3 100644
--- a/internal/host/runexec.go
+++ b/internal/host/runexec.go
@@ -208,6 +208,7 @@ func (w *runsWorker) execute(ctx context.Context, rec provision.Record, req runs
return
}
log.Printf("agent: runs: %s: run %s started (%s)", rec.Host, req.ID, handle.Invocation())
+ w.runEvent(rec, runStartedLine(req))
res := runs.Result{Started: w.now().UTC()}
status, doneAt := w.follow(ctx, rec, req, handle, h, &res)
bound := time.AfterFunc(runOutputGrace, endOutput)
@@ -446,6 +447,10 @@ func (w *runsWorker) finish(ctx context.Context, rec provision.Record, req runs.
}); err != nil && !errors.Is(err, provision.ErrRunConflict) && !errors.Is(err, os.ErrNotExist) {
log.Printf("agent: runs: %s %s: done: %v", rec.Host, req.ID, err)
}
+ // What the box saw end, written or not: a result that never landed
+ // is ended as lost by the sweep, but the command's own ending was
+ // this. A run with no handle never had its unit started.
+ w.runEvent(rec, runEndedLine(req.ID, res, handle != nil))
w.cleanUp(rec, req, handle)
}
diff --git a/internal/host/runs.go b/internal/host/runs.go
index cab2cd423..7f5cf09e9 100644
--- a/internal/host/runs.go
+++ b/internal/host/runs.go
@@ -48,6 +48,9 @@ type runsWorker struct {
boot string
now func() time.Time
exec func(ctx context.Context, rec provision.Record, req runs.Request, rt registry.Route, h *runHandle)
+ // events is where a run's start and end reach `carlos logs`
+ // (runevents.go); nil on a box with no log store.
+ events activator.EventSink
// start runs a picked run's exec: on its own goroutine in the agent,
// inline in tests that count launches.
start func(func())
@@ -315,8 +318,12 @@ func (w *runsWorker) closeInterrupted(ctx context.Context, rec provision.Record)
log.Printf("agent: runs: %s %s: result: %v", rec.Host, id, err)
return
}
- 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) {
+ // 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) {
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) {
@@ -326,8 +333,10 @@ func (w *runsWorker) closeInterrupted(ctx context.Context, rec provision.Record)
}
// armRunsPass arms the runs worker on a box with an activator. Thin, like
-// armMovesPass: the behaviour is the worker's, tested there.
-func armRunsPass(svc *activator.Service, reg *registry.Registry, dataDir string) {
+// armMovesPass: the behaviour is the worker's, tested there. events must be
+// a genuinely nil interface when there is no log store, never a nil
+// *applog.Sink (the trap agent.go documents).
+func armRunsPass(svc *activator.Service, reg *registry.Registry, dataDir string, events activator.EventSink) {
if svc == nil || reg == nil {
return
}
@@ -337,6 +346,7 @@ func armRunsPass(svc *activator.Service, reg *registry.Registry, dataDir string)
return
}
w := newRunsWorker(store, reg.Get, svc, dataDir, BoxLabel(), newBootID())
+ w.events = events
armedRuns.Store(w)
log.Printf("agent: runs armed (box %s, boot %s)", w.box, w.boot)
}
diff --git a/internal/provision/plan14_root_reads_test.go b/internal/provision/plan14_root_reads_test.go
index 1175ecad9..c44caf67c 100644
--- a/internal/provision/plan14_root_reads_test.go
+++ b/internal/provision/plan14_root_reads_test.go
@@ -949,7 +949,17 @@ func TestPlan14RootReadCensus(t *testing.T) {
if err = loadRootReadInventory(filepath.Join(root, "internal/provision/testdata/plan14-root-reads-bootstrap-carlos-follows-316.tsv"), &inv, true); err != nil {
t.Fatal(err)
}
- seal = "53b3cbb6f46d657ce32f49dad84dae79316c80da949ccf37273833eef5c5b2d7"
+ // Census overlay run-lifecycle-logs-325 (amadan #325: the box's carlos
+ // run worker emits run started and run ended as member log events
+ // through the agent's EventSink), loaded last. Proposed; ruling asked of
+ // the census owner on #280. No root read, file read or record write is
+ // added: runAgent and runsWorker.execute are re-pinned at their class and
+ // task, and the internal/host envelope is re-pinned. The seal moves
+ // because execute's legacy declaration was re-pinned.
+ if err = loadRootReadInventory(filepath.Join(root, "internal/provision/testdata/plan14-root-reads-run-lifecycle-logs-325.tsv"), &inv, true); err != nil {
+ t.Fatal(err)
+ }
+ seal = "17d7b376a64068a291ff8bf2e64c8aabda9222c1376a99fb9336adc1c770460c"
errs := append(compareRootReads(got, inv), checkRootReadLegacy(inv, seal)...)
errs = append(errs, checkRootReadDeclarations(got, inv)...)
if len(errs) > 0 {
diff --git a/internal/provision/plan9_b8_census_test.go b/internal/provision/plan9_b8_census_test.go
index de6143aaf..af50fadc4 100644
--- a/internal/provision/plan9_b8_census_test.go
+++ b/internal/provision/plan9_b8_census_test.go
@@ -1102,9 +1102,11 @@ var plan9B8CensusInventory = []censusEntry{
// The run sweep clears a terminal run past retention through SetRecordRun (RunClear).
{"internal/console/runsweep.go", "Server.sweepTerminalRun", "record-writer", "key:SetRecordRun", "78e3510bbf056dbf28446391b552c87060094ca803a3b1a8b7d7013163ee136b"},
// The box records a run's end through SetRecordRun (runFinishOurs).
- {"internal/host/runexec.go", "runsWorker.finish", "record-writer", "key:SetRecordRun", "570fe08f48923e8b2d94104a2b895410fad712efc3a14c278ca5547309ceaff2"},
+ // 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).
- {"internal/host/runs.go", "runsWorker.closeInterrupted", "record-writer", "key:SetRecordRun", "ccd125779b839856806e888a8d0897bd379625756c5e3d78ba88c41b9c868f27"},
+ // 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"},
// 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
new file mode 100644
index 000000000..a0402892e
--- /dev/null
+++ b/internal/provision/testdata/plan14-root-reads-run-lifecycle-logs-325.tsv
@@ -0,0 +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
+@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