amadan

carlos / platform Public

run-lifecycle-logs-325

Squashed from run-lifecycle-logs-325 into main.
claude f54aa2fc50b8481b9ba4b6bfe09a21bc7c7172e2 parent 3d444a1
10 files changed, +486 −14
  • docs/site/cli.md +2 −0
  • internal/host/agent.go +1 −1
  • internal/host/runevents.go +88 −0
  • internal/host/runevents_linux_test.go +114 −0
  • internal/host/runevents_test.go +206 −0
  • internal/host/runexec.go +15 −5
  • internal/host/runs.go +36 −6
  • internal/provision/plan14_root_reads_test.go +14 −0
  • 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 ===
go: downloading github.com/aws/aws-sdk-go-v2 v1.44.0
go: downloading github.com/aws/aws-sdk-go-v2/config v1.32.6
go: downloading github.com/aws/aws-sdk-go-v2/service/route53 v1.64.1
go: downloading github.com/aws/aws-sdk-go-v2/service/ec2 v1.324.0
go: downloading github.com/superfly/ltx v0.5.1
go: downloading golang.org/x/crypto v0.53.0
go: downloading github.com/aws/aws-sdk-go-v2/service/sns v1.43.0
go: downloading github.com/benbjohnson/litestream v0.5.14
go: downloading github.com/oschwald/maxminddb-golang v1.13.1
go: downloading github.com/aws/aws-sdk-go-v2/service/autoscaling v1.74.0
go: downloading github.com/aws/aws-sdk-go-v2/service/acm v1.45.0
go: downloading github.com/aws/aws-sdk-go-v2/service/cloudwatch v1.68.0
go: downloading golang.org/x/sys v0.46.0
go: downloading modernc.org/sqlite v1.55.0
go: downloading github.com/aws/aws-sdk-go-v2/service/ssm v1.74.0
go: downloading github.com/aws/smithy-go v1.28.1
go: downloading github.com/aws/aws-sdk-go-v2/service/s3 v1.105.0
go: downloading github.com/aws/aws-sdk-go-v2/service/iam v1.58.2
go: downloading github.com/aws/aws-sdk-go-v2/service/resourcegroupstaggingapi v1.37.0
go: downloading github.com/aws/aws-sdk-go-v2/service/sts v1.45.6
go: downloading github.com/aws/aws-sdk-go-v2/credentials v1.19.6
go: downloading github.com/klauspost/compress v1.18.0
go: downloading golang.org/x/net v0.56.0
go: downloading github.com/pion/logging v0.2.4
go: downloading github.com/pion/stun/v3 v3.0.1
go: downloading github.com/pion/turn/v4 v4.1.4
go: downloading github.com/aws/aws-sdk-go-v2/service/sesv2 v1.66.6
go: downloading github.com/aws/aws-sdk-go-v2/service/costexplorer v1.67.5
go: downloading github.com/aws/aws-sdk-go-v2/internal/configsources v1.4.40
go: downloading github.com/aws/aws-sdk-go-v2/feature/ec2/imds v1.18.16
go: downloading github.com/aws/aws-sdk-go-v2/internal/ini v1.8.4
go: downloading github.com/aws/aws-sdk-go-v2/service/signin v1.0.4
go: downloading github.com/aws/aws-sdk-go-v2/service/sso v1.30.8
go: downloading github.com/aws/aws-sdk-go-v2/service/ssooidc v1.35.12
go: downloading github.com/aws/aws-sdk-go-v2/aws/protocol/eventstream v1.7.14
go: downloading github.com/aws/aws-sdk-go-v2/internal/v4a v1.4.38
go: downloading github.com/aws/aws-sdk-go-v2/service/internal/accept-encoding v1.13.19
go: downloading github.com/aws/aws-sdk-go-v2/service/internal/checksum v1.9.23
go: downloading github.com/aws/aws-sdk-go-v2/service/internal/presigned-url v1.13.40
go: downloading github.com/aws/aws-sdk-go-v2/service/internal/s3shared v1.19.31
go: downloading github.com/pion/randutil v0.1.0
go: downloading github.com/pion/transport/v4 v4.0.1
go: downloading github.com/pierrec/lz4/v4 v4.1.22
go: downloading github.com/aws/aws-sdk-go-v2/internal/endpoints/v2 v2.7.40
go: downloading github.com/pion/transport/v3 v3.0.8
go: downloading github.com/pion/dtls/v3 v3.0.7
go: downloading github.com/wlynxg/anet v0.0.5
go: downloading github.com/prometheus/client_golang v1.17.0
go: downloading golang.org/x/sync v0.21.0
go: downloading github.com/aws/aws-sdk-go-v2/feature/s3/manager v1.20.18
go: downloading github.com/mattn/go-isatty v0.0.20
go: downloading github.com/lmittmann/tint v1.1.3
go: downloading github.com/cespare/xxhash/v2 v2.3.0
go: downloading github.com/prometheus/procfs v0.12.0
go: downloading github.com/prometheus/common v0.45.0
go: downloading google.golang.org/protobuf v1.36.10
go: downloading github.com/beorn7/perks v1.0.1
go: downloading github.com/prometheus/client_model v0.5.0
go: downloading github.com/matttproud/golang_protobuf_extensions/v2 v2.0.0
go: downloading golang.org/x/text v0.38.0
go: downloading modernc.org/libc v1.74.1
go: downloading github.com/dustin/go-humanize v1.0.1
go: downloading github.com/google/uuid v1.6.0
go: downloading modernc.org/memory v1.11.0
go: downloading modernc.org/mathutil v1.7.1
go: downloading github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec
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 ./...
go: downloading golang.org/x/tools v0.47.0
go: downloading golang.org/x/mod v0.37.0
gofmt -l .: clean
go test ./... -count=1 -timeout 30m
ok  	github.com/carlosframework/platform	333.653s
?   	github.com/carlosframework/platform/cmd/changelog	[no test files]
ok  	github.com/carlosframework/platform/cmd/console	2.843s
ok  	github.com/carlosframework/platform/cmd/moveprobe	93.315s
ok  	github.com/carlosframework/platform/cmd/zddprobe	0.706s
ok  	github.com/carlosframework/platform/internal/activator	250.724s
ok  	github.com/carlosframework/platform/internal/agentsock	0.015s
ok  	github.com/carlosframework/platform/internal/alerting	0.004s
ok  	github.com/carlosframework/platform/internal/analytics	0.024s
ok  	github.com/carlosframework/platform/internal/appconfig	2.492s
ok  	github.com/carlosframework/platform/internal/apperr	0.094s
ok  	github.com/carlosframework/platform/internal/applog	0.156s
ok  	github.com/carlosframework/platform/internal/awsinv	0.004s
ok  	github.com/carlosframework/platform/internal/boxchoice	0.006s
ok  	github.com/carlosframework/platform/internal/boxid	0.794s
?   	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.002s
ok  	github.com/carlosframework/platform/internal/cgroup	0.706s
ok  	github.com/carlosframework/platform/internal/changelog	0.347s
ok  	github.com/carlosframework/platform/internal/claimactivation	0.834s
ok  	github.com/carlosframework/platform/internal/clamd	0.056s
?   	github.com/carlosframework/platform/internal/cliflag	[no test files]
ok  	github.com/carlosframework/platform/internal/console	443.250s
?   	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.665s
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.003s
ok  	github.com/carlosframework/platform/internal/docsite	0.006s
ok  	github.com/carlosframework/platform/internal/domains	2.403s
ok  	github.com/carlosframework/platform/internal/doorkey	0.006s
ok  	github.com/carlosframework/platform/internal/economics	0.004s
ok  	github.com/carlosframework/platform/internal/edge	45.135s
?   	github.com/carlosframework/platform/internal/edgeproof	[no test files]
ok  	github.com/carlosframework/platform/internal/edgesfile	0.008s
ok  	github.com/carlosframework/platform/internal/fleetapi	0.134s
ok  	github.com/carlosframework/platform/internal/gate	1.657s
ok  	github.com/carlosframework/platform/internal/genselect	0.018s
ok  	github.com/carlosframework/platform/internal/geo	0.022s
ok  	github.com/carlosframework/platform/internal/geoip	0.032s
ok  	github.com/carlosframework/platform/internal/historyreadback	0.156s
ok  	github.com/carlosframework/platform/internal/host	194.121s
ok  	github.com/carlosframework/platform/internal/hostactors	6.379s
ok  	github.com/carlosframework/platform/internal/hostactors/awsmembership	0.005s
ok  	github.com/carlosframework/platform/internal/hostbox	2.853s
ok  	github.com/carlosframework/platform/internal/hostclaim	0.691s
ok  	github.com/carlosframework/platform/internal/hostenv	0.005s
ok  	github.com/carlosframework/platform/internal/hostevidence	0.007s
ok  	github.com/carlosframework/platform/internal/hostexec	5.179s
ok  	github.com/carlosframework/platform/internal/hostfence	0.038s
ok  	github.com/carlosframework/platform/internal/hostfiles	10.942s
ok  	github.com/carlosframework/platform/internal/hostfloor	0.017s
ok  	github.com/carlosframework/platform/internal/hostguard	1.015s
ok  	github.com/carlosframework/platform/internal/hostops	1.687s
?   	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.002s
ok  	github.com/carlosframework/platform/internal/hostrelocate	0.567s
ok  	github.com/carlosframework/platform/internal/hostresolve	0.159s
ok  	github.com/carlosframework/platform/internal/hostwrite	0.002s
ok  	github.com/carlosframework/platform/internal/infraview	0.002s
ok  	github.com/carlosframework/platform/internal/instancectl	5.258s
ok  	github.com/carlosframework/platform/internal/instanceexec	2.780s
ok  	github.com/carlosframework/platform/internal/instancefs	0.007s
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.622s
ok  	github.com/carlosframework/platform/internal/lbhealth	0.006s
ok  	github.com/carlosframework/platform/internal/lease	10.050s
ok  	github.com/carlosframework/platform/internal/lease/leasetest	0.500s
ok  	github.com/carlosframework/platform/internal/ledger	0.028s
ok  	github.com/carlosframework/platform/internal/mail	0.194s
ok  	github.com/carlosframework/platform/internal/maintenance	0.090s
ok  	github.com/carlosframework/platform/internal/maintenanceexec	5.735s
ok  	github.com/carlosframework/platform/internal/maintenanceguard	0.068s
ok  	github.com/carlosframework/platform/internal/metrics	0.005s
ok  	github.com/carlosframework/platform/internal/moves	21.802s
ok  	github.com/carlosframework/platform/internal/moves/archive	0.924s
ok  	github.com/carlosframework/platform/internal/objstore	0.283s
ok  	github.com/carlosframework/platform/internal/ops	0.174s
ok  	github.com/carlosframework/platform/internal/park	0.285s
ok  	github.com/carlosframework/platform/internal/privatefile	0.005s
ok  	github.com/carlosframework/platform/internal/provision	93.302s
ok  	github.com/carlosframework/platform/internal/publicrelease	0.009s
?   	github.com/carlosframework/platform/internal/regionname	[no test files]
ok  	github.com/carlosframework/platform/internal/registry	5.724s
ok  	github.com/carlosframework/platform/internal/relay	7.278s
ok  	github.com/carlosframework/platform/internal/release	26.853s
ok  	github.com/carlosframework/platform/internal/rollout	3.713s
ok  	github.com/carlosframework/platform/internal/rolloutwords	0.005s
ok  	github.com/carlosframework/platform/internal/rootaws	0.008s
ok  	github.com/carlosframework/platform/internal/rootparticipation	0.062s
ok  	github.com/carlosframework/platform/internal/rootstate	0.033s
ok  	github.com/carlosframework/platform/internal/runs	0.583s
ok  	github.com/carlosframework/platform/internal/s3compat	0.011s
ok  	github.com/carlosframework/platform/internal/safefile	0.004s
ok  	github.com/carlosframework/platform/internal/schedule	2.627s
ok  	github.com/carlosframework/platform/internal/seeds	0.017s
ok  	github.com/carlosframework/platform/internal/sim/hostlife	12.285s
ok  	github.com/carlosframework/platform/internal/sim/litestreamfacts	4.112s
ok  	github.com/carlosframework/platform/internal/status	0.062s
ok  	github.com/carlosframework/platform/internal/steering	0.006s
ok  	github.com/carlosframework/platform/internal/stopevidence	0.277s
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.005s
ok  	github.com/carlosframework/platform/internal/version	0.002s
ok  	github.com/carlosframework/platform/internal/vet	1.581s
=== 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: 49807522 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.03s)
    --- 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.02s)
        --- 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.034s
=== RUN   TestT4StorageProbeMinio
2026/10/21 12:44:06 moves: T4: STORE: list: operation error S3: ListObjectsV2, https response error StatusCode: 403, RequestID: 18E08C0EA8808D5F, 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.01s)
PASS
ok  	github.com/carlosframework/platform/internal/host	0.025s
minio contract: PASS
diff --git a/docs/site/cli.md b/docs/site/cli.md
index f44e5112f..782888cec 100644
--- a/docs/site/cli.md
+++ b/docs/site/cli.md
@@ -559,6 +559,8 @@ A hibernating instance is woken first. A live one keeps serving, and the command
carlos run exits with the command's own status, 128 plus the signal number when a signal ended it, 124 when it timed out, 125 when it was interrupted or the instance let go of it without a result, 130 when you cancelled it, 3 when the box refused it or did not pick it up within 60 seconds, and 2 when the console refused it.
+carlos logs shows when each run started, who asked for it and how it ended. The command's output is not kept there.
+
Arguments are kept in the account's audit log, with who ran them. Never put a secret in an argument. Pass it in a --file, or keep it in the instance's environment.
### carlos schedule
diff --git a/internal/host/agent.go b/internal/host/agent.go
index 483700f2d..559c0a27c 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..338498311
--- /dev/null
+++ b/internal/host/runevents.go
@@ -0,0 +1,88 @@
+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 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. A cancel or a deadline that
+// lands during that same start is written as cancelled or timed out with
+// no handle, and its line says "before it started", as the CLI says of the
+// same result: the result does not record whether the start was reached,
+// and the line restates the result, never more.
+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..16f51b560
--- /dev/null
+++ b/internal/host/runevents_linux_test.go
@@ -0,0 +1,114 @@
+package host
+
+import (
+ "context"
+ "errors"
+ "reflect"
+ "strings"
+ "testing"
+ "time"
+
+ "github.com/carlosframework/platform/internal/activator"
+ "github.com/carlosframework/platform/internal/applog"
+ "github.com/carlosframework/platform/internal/instancectl"
+ "github.com/carlosframework/platform/internal/provision"
+ "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"},
+ // 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())
+ 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)
+ }
+ }
+}
+
+// A run whose result never landed logs no ending of its own: the run stays
+// picked, and the next agent's close-out writes and logs the one ending,
+// so the log never holds two that contradict each other (Astra round 3).
+func TestRunWhoseResultNeverLandedLeavesTheEndingToTheCloseOut(t *testing.T) {
+ defer func(d time.Duration) { runFinishBound = d }(runFinishBound)
+ runFinishBound = 300 * time.Millisecond
+ dir := release.NewDirStore(t.TempDir())
+ rec, req := pickedRun(t, dir, 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: "0", Code: "1"}
+ var events eventLog
+ w := execWorker(t, &failingPuts{Store: dir, part: "/result.json"}, &fakeLauncher{handle: h}, "boot-1")
+ w.events = &events
+ rt, _ := runOwnedRoute(runHost)(runHost)
+ w.execute(context.Background(), rec, req, *rt, newRunHandle())
+ if r := currentRun(t, dir); r.State != provision.RunPicked {
+ t.Fatalf("run %+v, want still picked", r)
+ }
+ // The agent restarts once storage has recovered.
+ cur, err := provision.GetRecord(context.Background(), dir, rec.Account, rec.App, rec.Host)
+ if err != nil {
+ t.Fatal(err)
+ }
+ var l execLog
+ next := testWorker(dir, runOwnedRoute(runHost), "box-1", "boot-2", &l)
+ next.events = &events
+ next.consider(context.Background(), *cur)
+ var endings []string
+ for _, e := range events.all() {
+ if !strings.Contains(e.msg, " started by ") {
+ endings = append(endings, e.msg)
+ }
+ }
+ if len(endings) != 1 || !strings.Contains(endings[0], "the box's agent restarted") {
+ t.Fatalf("endings %q, want only the close-out's", endings)
+ }
+}
diff --git a/internal/host/runevents_test.go b/internal/host/runevents_test.go
new file mode 100644
index 000000000..3375c4e4f
--- /dev/null
+++ b/internal/host/runevents_test.go
@@ -0,0 +1,206 @@
+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 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,
+ "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 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 stale pass after the run was acknowledged (its result deleted, the
+// record cleared) recreates a result, but its done CAS fails, so it logs
+// no second ending (Astra round 2, finding 2).
+func TestRunClosedOutByAStalePassAfterTheAckLogsNothing(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
+ w.consider(context.Background(), *got)
+ // The CLI acknowledges the run: the record is cleared and the result
+ // deleted, as handleAPIRunAck does.
+ if _, err := provision.SetRecordRun(context.Background(), s, "bab", "shop", runHost, provision.RunClear(id)); err != nil {
+ t.Fatal(err)
+ }
+ if err := runs.DeleteRun(context.Background(), s, "bab", "shop", id); err != nil {
+ t.Fatal(err)
+ }
+ w.consider(context.Background(), *got)
+ if ev := events.all(); len(ev) != 1 {
+ t.Fatalf("events %+v, want the first pass's ending only", ev)
+ }
+}
+
+// A done CAS whose answer was lost loses the line rather than risk a
+// second one: run lines are at most once, and result.json is the record.
+func TestRunClosedOutWithALostDoneAnswerIsNotLoggedTwice(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) != 0 {
+ t.Fatalf("events %+v, want none: the done answer was lost", ev)
+ }
+ if res, _ := runs.ReadResult(context.Background(), dir, "bab", "shop", id); res == nil || res.Interrupted != runs.InterruptedAgentRestart {
+ t.Fatalf("result %+v, want the interrupted result", res)
+ }
+}
+
+// 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..f3c0004cc 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)
@@ -440,11 +441,20 @@ func (w *runsWorker) finish(ctx context.Context, rec provision.Record, req runs.
})
if err != nil {
log.Printf("agent: runs: %s %s: result: %v", rec.Host, req.ID, err)
- } else if err := untilLanded(fctx, func(ctx context.Context) error {
- _, err := provision.SetRecordRun(ctx, w.store, rec.Account, rec.App, rec.Host, runFinishOurs(req.ID, w.box, w.boot))
- return err
- }); 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)
+ } else {
+ // The ending is logged only once the result has landed (amadan
+ // #325: run lines are at most once). A result that never landed
+ // leaves the run picked, and a later agent's closeInterrupted
+ // writes and logs its own ending; logging this one too would put
+ // two contradictory endings in the log. A run with no handle never
+ // had its unit started.
+ w.runEvent(rec, runEndedLine(req.ID, res, handle != nil))
+ if err := untilLanded(fctx, func(ctx context.Context) error {
+ _, err := provision.SetRecordRun(ctx, w.store, rec.Account, rec.App, rec.Host, runFinishOurs(req.ID, w.box, w.boot))
+ return err
+ }); 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)
+ }
}
w.cleanUp(rec, req, handle)
}
diff --git a/internal/host/runs.go b/internal/host/runs.go
index cab2cd423..f85eccefd 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())
@@ -311,12 +314,36 @@ 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)
+ // A run's log lines are at most once and best effort (amadan #325), like
+ // the rest of the platform stream; result.json and the audit log are its
+ // record. So the ending is logged only by a pass that wrote the run's
+ // result itself (read before, read back after) AND whose own done CAS
+ // landed. Every pass that still holds a picked snapshot comes back here:
+ // the create-only write answers a second time as if it had landed, a
+ // result already there is the boot's that ran the command (which logged
+ // its own ending), and a stale pass after the run was acknowledged
+ // recreates a result but its CAS fails. A lost answer anywhere loses the
+ // line rather than risk a second one.
+ 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
}
- 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) {
+ ours := false
+ 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
+ }
+ ours = got.Box == res.Box && got.Ended.Equal(res.Ended) && got.Interrupted == res.Interrupted
+ }
+ if _, err := provision.SetRecordRun(ctx, w.store, rec.Account, rec.App, rec.Host, provision.RunFinish(id)); err == nil {
+ if ours {
+ 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 +353,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 +366,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 b56965763..fbe046f3d 100644
--- a/internal/provision/plan14_root_reads_test.go
+++ b/internal/provision/plan14_root_reads_test.go
@@ -1034,6 +1034,20 @@ func TestPlan14RootReadCensus(t *testing.T) {
t.Fatal(err)
}
seal = "a21dba12b0f3cd0811c624ec352d6ff5c46936ef0da1d4ce9d31cdd13cc0f262"
+ if errs := checkRootReadLegacy(inv, seal); len(errs) != 0 {
+ t.Fatal(errs)
+ }
+ // 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, after scan-demand-revival. 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 = "cf0a526b5f7c913160b1e6a76fa34c34dacd60cbacfd8019e736c2ab852399e3"
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 5b08dd5dd..4b065caba 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 once its result has landed (at most once); record writes unchanged.
+ {"internal/host/runexec.go", "runsWorker.finish", "record-writer", "key:SetRecordRun", "42f8628f74fcdfd3a0a56d302caa6f423f6c8fe8726c3561028e94ad97037041"},
// 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): 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 and its done CAS landed (at most once); record writes unchanged.
+ {"internal/host/runs.go", "runsWorker.closeInterrupted", "record-writer", "key:SetRecordRun", "b540e246a977470c50d3ebbbef080f9b8a824490fd3bb8bd6f98537bc882adee"},
// 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..66275f483
--- /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 577cb4d70b0aa1e49d6b1ab9203295039b69e0171e63d181ee358b1ed00c2118
+@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