amadan

carlos / platform Public

Merge remote-tracking branch 'origin/main' into sec-mail-user-boundary

# Conflicts:
#	internal/provision/testdata/plan14-root-reads-chain.tsv
claude 91f85c064dba242da8b34f84fa53e53e88f2d736 parent 60f767dparent b612e71
9 files changed, +77 −8
  • docs/superpowers/notes/census-proposal-sec-mail-user-boundary.md +1 −1
  • docs/superpowers/notes/census-proposal-wake-latency-2.md +16 −0
  • internal/activator/backend_exec.go +11 −2
  • internal/activator/prepare.go +15 −2
  • internal/activator/swaphold.go +6 −0
  • internal/instancectl/gen.go +6 −2
  • internal/lease/lease.go +7 −0
  • internal/provision/testdata/plan14-root-reads-chain.tsv +2 −1
  • internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv +13 −0

CI passed — run details

CI log 
=== gate ===
.amadan/test-gate.sh
=== launchctx (0 s)
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]
=== vet (14 s)
=== gofmt (0 s)
gofmt -l .: clean
=== rest (170 s)
?   	github.com/carlosframework/platform/cmd/changelog	[no test files]
ok  	github.com/carlosframework/platform/cmd/console	3.442s
ok  	github.com/carlosframework/platform/cmd/moveprobe	11.691s
ok  	github.com/carlosframework/platform/cmd/zddprobe	0.747s
ok  	github.com/carlosframework/platform/internal/activator	60.278s
ok  	github.com/carlosframework/platform/internal/agentsock	0.018s
ok  	github.com/carlosframework/platform/internal/alerting	0.003s
ok  	github.com/carlosframework/platform/internal/analytics	0.019s
ok  	github.com/carlosframework/platform/internal/appconfig	2.763s
ok  	github.com/carlosframework/platform/internal/apperr	0.088s
ok  	github.com/carlosframework/platform/internal/applog	0.165s
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	1.016s
?   	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.011s
ok  	github.com/carlosframework/platform/internal/caps	0.017s
ok  	github.com/carlosframework/platform/internal/certwarm	0.005s
ok  	github.com/carlosframework/platform/internal/cgroup	0.737s
ok  	github.com/carlosframework/platform/internal/changelog	0.434s
ok  	github.com/carlosframework/platform/internal/claimactivation	1.068s
ok  	github.com/carlosframework/platform/internal/clamd	0.055s
?   	github.com/carlosframework/platform/internal/cliflag	[no test files]
?   	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	8.200s
ok  	github.com/carlosframework/platform/internal/dbdoor/dbdoortest	0.015s
ok  	github.com/carlosframework/platform/internal/dbquery	0.006s
ok  	github.com/carlosframework/platform/internal/dbreads	2.088s
?   	github.com/carlosframework/platform/internal/dbreads/dbreadstest	[no test files]
ok  	github.com/carlosframework/platform/internal/dbverify	0.008s
ok  	github.com/carlosframework/platform/internal/dnsrec	0.005s
ok  	github.com/carlosframework/platform/internal/docsite	0.010s
ok  	github.com/carlosframework/platform/internal/domains	2.702s
ok  	github.com/carlosframework/platform/internal/doorkey	0.010s
ok  	github.com/carlosframework/platform/internal/economics	0.008s
ok  	github.com/carlosframework/platform/internal/edge	45.760s
?   	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.163s
ok  	github.com/carlosframework/platform/internal/gate	1.673s
ok  	github.com/carlosframework/platform/internal/genselect	0.027s
ok  	github.com/carlosframework/platform/internal/geo	0.018s
ok  	github.com/carlosframework/platform/internal/geoip	0.038s
ok  	github.com/carlosframework/platform/internal/historyreadback	0.277s
ok  	github.com/carlosframework/platform/internal/host	146.040s
ok  	github.com/carlosframework/platform/internal/hostactors	5.848s
ok  	github.com/carlosframework/platform/internal/hostactors/awsmembership	0.008s
ok  	github.com/carlosframework/platform/internal/hostbox	2.982s
ok  	github.com/carlosframework/platform/internal/hostclaim	0.779s
ok  	github.com/carlosframework/platform/internal/hostenv	0.006s
ok  	github.com/carlosframework/platform/internal/hostevidence	0.008s
ok  	github.com/carlosframework/platform/internal/hostexec	5.321s
ok  	github.com/carlosframework/platform/internal/hostfence	0.066s
ok  	github.com/carlosframework/platform/internal/hostfiles	10.361s
ok  	github.com/carlosframework/platform/internal/hostfloor	0.022s
ok  	github.com/carlosframework/platform/internal/hostguard	1.047s
ok  	github.com/carlosframework/platform/internal/hostops	1.960s
?   	github.com/carlosframework/platform/internal/hostops/fencerelease	[no test files]
ok  	github.com/carlosframework/platform/internal/hostops/internal/fencerelease	0.003s
ok  	github.com/carlosframework/platform/internal/hostquarantine	0.005s
ok  	github.com/carlosframework/platform/internal/hostrelocate	0.667s
ok  	github.com/carlosframework/platform/internal/hostresolve	0.176s
ok  	github.com/carlosframework/platform/internal/hostwrite	0.008s
ok  	github.com/carlosframework/platform/internal/infraview	0.004s
ok  	github.com/carlosframework/platform/internal/instancectl	5.236s
ok  	github.com/carlosframework/platform/internal/instanceexec	2.756s
ok  	github.com/carlosframework/platform/internal/instancefs	0.010s
ok  	github.com/carlosframework/platform/internal/instancekey	0.002s
ok  	github.com/carlosframework/platform/internal/instanceupdates	0.008s
ok  	github.com/carlosframework/platform/internal/layout	1.756s
ok  	github.com/carlosframework/platform/internal/lbhealth	0.004s
ok  	github.com/carlosframework/platform/internal/lease	10.129s
ok  	github.com/carlosframework/platform/internal/lease/leasetest	0.540s
ok  	github.com/carlosframework/platform/internal/ledger	0.030s
ok  	github.com/carlosframework/platform/internal/mail	0.198s
ok  	github.com/carlosframework/platform/internal/maintenance	0.102s
ok  	github.com/carlosframework/platform/internal/maintenanceexec	5.609s
ok  	github.com/carlosframework/platform/internal/maintenanceguard	0.077s
ok  	github.com/carlosframework/platform/internal/metrics	0.007s
ok  	github.com/carlosframework/platform/internal/moves	22.116s
ok  	github.com/carlosframework/platform/internal/moves/archive	1.016s
ok  	github.com/carlosframework/platform/internal/objstore	0.239s
ok  	github.com/carlosframework/platform/internal/ops	0.204s
ok  	github.com/carlosframework/platform/internal/park	0.289s
ok  	github.com/carlosframework/platform/internal/plans	0.006s
ok  	github.com/carlosframework/platform/internal/privatefile	0.004s
ok  	github.com/carlosframework/platform/internal/provision	22.436s
ok  	github.com/carlosframework/platform/internal/publicrelease	0.017s
?   	github.com/carlosframework/platform/internal/regionname	[no test files]
ok  	github.com/carlosframework/platform/internal/registry	5.658s
ok  	github.com/carlosframework/platform/internal/relay	7.234s
ok  	github.com/carlosframework/platform/internal/release	25.872s
ok  	github.com/carlosframework/platform/internal/rollout	3.830s
ok  	github.com/carlosframework/platform/internal/rolloutwords	0.004s
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.027s
ok  	github.com/carlosframework/platform/internal/runs	0.592s
ok  	github.com/carlosframework/platform/internal/s3compat	0.007s
ok  	github.com/carlosframework/platform/internal/safefile	0.006s
ok  	github.com/carlosframework/platform/internal/schedule	2.707s
ok  	github.com/carlosframework/platform/internal/seeds	0.013s
ok  	github.com/carlosframework/platform/internal/sim/engines	2.583s
ok  	github.com/carlosframework/platform/internal/sim/hostlife	11.296s
ok  	github.com/carlosframework/platform/internal/sim/litestreamfacts	3.708s
ok  	github.com/carlosframework/platform/internal/status	0.067s
ok  	github.com/carlosframework/platform/internal/steering	0.008s
ok  	github.com/carlosframework/platform/internal/stopevidence	0.075s
ok  	github.com/carlosframework/platform/internal/svcrole	0.002s
ok  	github.com/carlosframework/platform/internal/telemetry	0.005s
ok  	github.com/carlosframework/platform/internal/termfence	0.005s
ok  	github.com/carlosframework/platform/internal/tunnelclient	0.004s
ok  	github.com/carlosframework/platform/internal/unixdial	0.004s
ok  	github.com/carlosframework/platform/internal/updatewords	0.006s
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.687s
=== internal_console@0 (87 s)
ok  	github.com/carlosframework/platform/internal/console	84.884s
=== internal_console@1 (44 s)
ok  	github.com/carlosframework/platform/internal/console	42.189s
=== internal_console@2 (41 s)
ok  	github.com/carlosframework/platform/internal/console	39.200s
=== internal_console@3 (42 s)
ok  	github.com/carlosframework/platform/internal/console	40.465s
=== internal_console@4 (42 s)
ok  	github.com/carlosframework/platform/internal/console	40.577s
=== internal_console@5 (43 s)
ok  	github.com/carlosframework/platform/internal/console	40.759s
=== internal_console@6 (38 s)
ok  	github.com/carlosframework/platform/internal/console	35.908s
=== internal_console@7 (46 s)
ok  	github.com/carlosframework/platform/internal/console	44.143s
=== root@0 (110 s)
ok  	github.com/carlosframework/platform	108.111s
=== root@1 (84 s)
ok  	github.com/carlosframework/platform	82.575s
=== root@2 (93 s)
ok  	github.com/carlosframework/platform	91.027s
=== 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: 50659490 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.025s
=== RUN   TestT4StorageProbeMinio
2026/10/24 21:21:04 moves: T4: STORE: list: operation error S3: ListObjectsV2, https response error StatusCode: 403, RequestID: 18E194025992A8A7, 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.022s
=== RUN   TestS3StoreMinioContract
=== RUN   TestS3StoreMinioContract/conditional_get_and_etag_listing
=== RUN   TestS3StoreMinioContract/bump_through_every_mutation_path
--- PASS: TestS3StoreMinioContract (0.03s)
    --- PASS: TestS3StoreMinioContract/conditional_get_and_etag_listing (0.01s)
    --- PASS: TestS3StoreMinioContract/bump_through_every_mutation_path (0.02s)
PASS
ok  	github.com/carlosframework/platform/internal/release	0.032s
Bucket created successfully `local/dbf-deploy`.
Bucket created successfully `local/dbf-data-ie`.
Bucket created successfully `local/dbf-data-uk`.
local/dbf-deploy versioning is enabled
Created policy `dbf-console` successfully.
Created policy `dbf-ukbox` successfully.
Added user `dbfconsole` successfully.
Added user `dbfukbox` successfully.
Attached Policies: [dbf-console]
To User: dbfconsole
Attached Policies: [dbf-ukbox]
To User: dbfukbox
=== RUN   TestDBForwardMinio
2026/10/24 21:21:06 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000000 txid.db=0000000000000001
2026/10/24 21:21:06 INFO ltx file uploaded system=store db=source.db replica=file level=0 minTXID=0000000000000001 maxTXID=0000000000000001 size=720
2026/10/24 21:21:06 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000001 txid.db=0000000000000001
2026/10/24 21:21:06 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000001 txid.db=0000000000000002
2026/10/24 21:21:06 INFO ltx file uploaded system=store db=source.db replica=file level=0 minTXID=0000000000000002 maxTXID=0000000000000002 size=370
2026/10/24 21:21:06 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000002 txid.db=0000000000000002
2026/10/24 21:21:06 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000002 txid.db=0000000000000003
2026/10/24 21:21:06 INFO ltx file uploaded system=store db=source.db replica=file level=0 minTXID=0000000000000003 maxTXID=0000000000000003 size=454
2026/10/24 21:21:06 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000003 txid.db=0000000000000003
2026/10/24 21:21:06 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000000 txid.db=0000000000000001
2026/10/24 21:21:06 INFO ltx file uploaded system=store db=source.db replica=file level=0 minTXID=0000000000000001 maxTXID=0000000000000001 size=720
2026/10/24 21:21:06 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000001 txid.db=0000000000000001
2026/10/24 21:21:06 console: CARLOS_SECRETS_PUBKEY is unset, so no region outside the home can be chosen automatically
2026/10/24 21:21:06 console: could not notify member@example.com of a CLI token issue: keymail: lookup member@example.com: keymail: GET /api/federation/lookup?addr=member%40example.com&from=console%40127.0.0.1%3A37961: could not determine target mailbox
    agent.go:135: dbreads: dbr_qvmtgvl7m32bra6dgk3qadcx5q: planned 3 files (1544 bytes) and restored to 3 in 10ms
    agent.go:135: dbreads: dbr_qvmtgvl7m32bra6dgk3qadcx5q: output 5 bytes in 1 confirmed chunks in 1ms
2026/10/24 21:21:07 console: db read dbr_qvmtgvl7m32bra6dgk3qadcx5q: relayed 1 chunks (102 bytes) in 1.003s, ended done
    agent.go:135: dbreads: dbr_rdvwzdhef6wbf6d2nm6jwxzkoq: planned 1 files (720 bytes) and restored to 1 in 8ms
    agent.go:135: dbreads: dbr_rdvwzdhef6wbf6d2nm6jwxzkoq: output 5 bytes in 1 confirmed chunks in 1ms
2026/10/24 21:21:08 console: db read dbr_rdvwzdhef6wbf6d2nm6jwxzkoq: relayed 1 chunks (102 bytes) in 1.003s, ended done
    agent.go:135: dbreads: dbr_qin7tu3tdcjczxs5x4rfsrieoq: planned 3 files (1544 bytes) and held through 3 in 9ms
    agent.go:135: dbreads: dbr_qin7tu3tdcjczxs5x4rfsrieoq: output 1544 bytes in 1 confirmed chunks in 1ms
2026/10/24 21:21:09 console: db read dbr_qin7tu3tdcjczxs5x4rfsrieoq: relayed 1 chunks (1641 bytes) in 1.004s, ended done
=== RUN   TestDBForwardMinio/by_disconnect
=== NAME  TestDBForwardMinio
    agent.go:135: dbreads: dbr_ufwgt2ya4udemwusyelzagkzzu: planned 3 files (1544 bytes) and restored to 3 in 9ms
2026/10/24 21:21:10 console: db read dbr_ufwgt2ya4udemwusyelzagkzzu: relayed 0 chunks (0 bytes) in 27ms, ended client gone
    agent.go:135: dbreads: dbr_ufwgt2ya4udemwusyelzagkzzu: output 5 bytes in 1 confirmed chunks in 47ms
=== RUN   TestDBForwardMinio/by_timeout
=== NAME  TestDBForwardMinio
    agent.go:135: dbreads: dbr_hniv4wwhzskul5zdvl4izian24: planned 3 files (1544 bytes) and restored to 3 in 9ms
2026/10/24 21:21:30 console: db read dbr_hniv4wwhzskul5zdvl4izian24: relayed 0 chunks (0 bytes) in 19.835s, ended no-result
    agent.go:135: dbreads: dbr_hniv4wwhzskul5zdvl4izian24: output 5 bytes in 1 confirmed chunks in 19.819s
--- PASS: TestDBForwardMinio (23.22s)
    --- PASS: TestDBForwardMinio/by_disconnect (0.18s)
    --- PASS: TestDBForwardMinio/by_timeout (19.94s)
PASS
ok  	github.com/carlosframework/platform/internal/console	23.241s
minio contract: PASS
diff --git a/docs/superpowers/notes/census-proposal-sec-mail-user-boundary.md b/docs/superpowers/notes/census-proposal-sec-mail-user-boundary.md
index d3205caf6..733a8f229 100644
--- a/docs/superpowers/notes/census-proposal-sec-mail-user-boundary.md
+++ b/docs/superpowers/notes/census-proposal-sec-mail-user-boundary.md
@@ -8,6 +8,6 @@ Ruling `census-ruling-sec-mail-user-boundary`. Every change below keeps the disp
Envelopes re-pinned: `cmd/console`, `internal/mail`.
-Seal: `0ca3baafa26f59c0b7d8c6d6a39237d074afb71f885b7fbd50debebab5bf89f2` → `b64b923281b55c7309e5ecb440cbc0869127e43b6f963849eb30257abb9fba6c`.
+Seal: `27b020590845320cd37b94fdeddf61b7c6f90e12ba7841850f2e7bbd6836ecd8` → `68ca9635da386f34ef483c790af19e954122c11edc406d64cde8d55d99d12de5`.
Overlay: `internal/provision/testdata/plan14-root-reads-sec-mail-user-boundary.tsv`, appended to `internal/provision/testdata/plan14-root-reads-chain.tsv`.
diff --git a/docs/superpowers/notes/census-proposal-wake-latency-2.md b/docs/superpowers/notes/census-proposal-wake-latency-2.md
new file mode 100644
index 000000000..32d8ccb2c
--- /dev/null
+++ b/docs/superpowers/notes/census-proposal-wake-latency-2.md
@@ -0,0 +1,16 @@
+# Census approval: wake-latency-2
+
+Ruling `census-ruling-wake-latency-2`. Every change below keeps the disposition it already has, so it needs an approval, not a decision.
+
+| unit | change | read sites | what changed |
+|---|---|---|---|
+| `internal/activator/backend_exec.go` `ExecBackend.spawnUnitFrom` | body | unchanged (26) | times the launch's steps with time.Now() (build, prepare, launch file, gate, root start) and adds them to its existing "started" journal line; no read added or moved |
+| `internal/activator/prepare.go` `ExecBackend.prepareAt` | body | unchanged (1) | passes nil for prepareKeyedAt's new timing parameter; nothing else changed |
+| `internal/activator/prepare.go` `ExecBackend.prepareKeyedAt` | body | unchanged (13) | takes an optional timer and marks its steps with time.Now() (dirs, admin token, instance key, env, control socket, key gate, logs); no read added or moved |
+| `internal/activator/swaphold.go` `Service.startPinnedAt` | sites | +registry:Host | times record, staged start and health with time.Now() and logs them with rt.Host after a healthy start (the new registry:Host site is that log line); no read added or moved |
+
+Envelopes re-pinned: `internal/activator`, `internal/instancectl`, `internal/lease`.
+
+Seal: `0ca3baafa26f59c0b7d8c6d6a39237d074afb71f885b7fbd50debebab5bf89f2` → `27b020590845320cd37b94fdeddf61b7c6f90e12ba7841850f2e7bbd6836ecd8`.
+
+Overlay: `internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv`, appended to `internal/provision/testdata/plan14-root-reads-chain.tsv`.
diff --git a/internal/activator/backend_exec.go b/internal/activator/backend_exec.go
index 6656e8ee9..d6c81c739 100644
--- a/internal/activator/backend_exec.go
+++ b/internal/activator/backend_exec.go
@@ -2394,6 +2394,9 @@ func (b *ExecBackend) normalizeSocketMode(rt registry.Route, sock string, proc P
// generation-keyed files (unitGen); otherwise it is ignored. A failure
// whose kill could not prove the unit empty wraps errGenUnproven.
func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock string, n uint64, exe *instancectl.StagedExe, tier cgroup.Limit) (Proc, string, error) {
+ // The launch's own split, for the journal (wake latency, pass 2).
+ var steps wakeSteps
+ steps.begin(time.Now())
if err := b.nestedGate(rt); err != nil {
return nil, "", err
}
@@ -2421,7 +2424,9 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock
return nil, "", err
}
}
- p, ctl, logs, fileEnv, keyLayer, err := b.prepareKeyedAt(rt, instancectl.RoleRun, sock, gen)
+ steps.mark(time.Now(), "build")
+ var prep wakeSteps
+ p, ctl, logs, fileEnv, keyLayer, err := b.prepareKeyedAt(rt, instancectl.RoleRun, sock, gen, &prep)
if err != nil {
return nil, "", err
}
@@ -2434,9 +2439,11 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock
}
childVars := b.agentOwnedVars(rt, sock+".control", fileEnv, ctl != nil)
argv := []string{b.liveLink(rt.Host), "--socket", sock, "--db", p.dbPath}
+ steps.mark(time.Now(), "prepare ("+prep.String()+")")
if err := b.writeLaunchFor(p, instancectl.RoleRun, gen, rt.Host, argv, childEnv(childVars)); err != nil {
return fail(err)
}
+ steps.mark(time.Now(), "launch file")
// Read the symlink immediately before the start, same fail-safe
// direction as startChild: a concurrent repoint at worst records the
// older version (one extra convergence cycle), never the newer. A
@@ -2461,7 +2468,9 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock
}
return fail(err)
}
+ steps.mark(time.Now(), "gate")
inv, err := b.startRole(ctx, rt, instancectl.RoleRun, gen, exe, tier)
+ steps.mark(time.Now(), "root start")
// Past this call root may have started the unit: every failure below
// but ErrStagedExe (root's refusal before it laid out or started
// anything) and errNoStagedExeControl (root was never asked: the
@@ -2518,7 +2527,7 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock
if started == (cgroup.Limit{}) {
started = b.tier(rt)
}
- log.Printf("activator: %s: started %s memory.max=%d", rt.Host, unitName(instancectl.RoleRun, rt.Host, gen), started.MemoryMax)
+ log.Printf("activator: %s: started %s memory.max=%d (%s)", rt.Host, unitName(instancectl.RoleRun, rt.Host, gen), started.MemoryMax, steps.String())
up := b.newUnitProcFor(rt, instancectl.RoleRun, gen, p, inv, ctl, logs)
// The file environment this generation launched with, kept on its
// handle: a run against it composes its environment from this, never
diff --git a/internal/activator/prepare.go b/internal/activator/prepare.go
index 39eadb475..288d79507 100644
--- a/internal/activator/prepare.go
+++ b/internal/activator/prepare.go
@@ -47,7 +47,7 @@ func (b *ExecBackend) prepare(rt registry.Route, role instancectl.Role) (instanc
// it keys the log socket and the exit records cleared (zero-downtime spec
// §7.6).
func (b *ExecBackend) prepareAt(rt registry.Route, role instancectl.Role, sock string, gen uint64) (instancePaths, *edge.ControlListener, *logListener, map[string]string, error) {
- p, ctl, logs, env, _, err := b.prepareKeyedAt(rt, role, sock, gen)
+ p, ctl, logs, env, _, err := b.prepareKeyedAt(rt, role, sock, gen, nil)
return p, ctl, logs, env, err
}
@@ -55,7 +55,13 @@ func (b *ExecBackend) prepareAt(rt registry.Route, role instancectl.Role, sock s
// CARLOS_INSTANCE_KEY came from, decided by the same read (instance-key
// ruling 29). The nested run spawn keeps both on the generation's handle,
// for a run's command against that generation (StartCmd).
-func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, sock string, gen uint64) (instancePaths, *edge.ControlListener, *logListener, map[string]string, instancekey.Layer, error) {
+// steps, when not nil, times prepare's parts for the caller's journal line.
+func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, sock string, gen uint64, steps *wakeSteps) (instancePaths, *edge.ControlListener, *logListener, map[string]string, instancekey.Layer, error) {
+ if steps == nil {
+ steps = &wakeSteps{}
+ } else {
+ steps.begin(time.Now())
+ }
p := b.pathsFor(rt)
if err := os.MkdirAll(p.dataDir, 0o700); err != nil {
return p, nil, nil, nil, instancekey.LayerNone, err
@@ -66,6 +72,7 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s
if err := os.MkdirAll(filepath.Dir(b.logSocketFor(rt.Host, role, gen)), 0o700); err != nil {
return p, nil, nil, nil, instancekey.LayerNone, err
}
+ steps.mark(time.Now(), "dirs")
var env map[string]string
var keyLayer instancekey.Layer // the layer env's key came from, read with it (ruling 29)
switch role {
@@ -76,14 +83,17 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s
if err := EnsureAdminTokenBeneath(p.dataDir, rt.Host+".env"); err != nil {
return p, nil, nil, nil, instancekey.LayerNone, fmt.Errorf("admin token for %s: %w", rt.Host, err)
}
+ steps.mark(time.Now(), "admin token")
if _, err := b.ensureInstanceKeyFor(context.Background(), rt, p); err != nil { // prepareAt has no ctx to bound the mint's bucket read; configReadTimeout does
return p, nil, nil, nil, instancekey.LayerNone, fmt.Errorf("instance key for %s: %w", rt.Host, err)
}
+ steps.mark(time.Now(), "instance key")
var err error
env, keyLayer, err = b.instanceEnvLayer(rt)
if err != nil {
return p, nil, nil, nil, instancekey.LayerNone, err
}
+ steps.mark(time.Now(), "env")
case instancectl.RoleCmd:
// A run's environment is the one its generation launched with
// (merge ruling M3), which StartCmd has. The delivered files are
@@ -137,6 +147,7 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s
}
_ = os.Remove(sock)
ctl = b.listenControl(rt, sock+".control", p.envFile, gen)
+ steps.mark(time.Now(), "control socket")
}
// A replica's roles are gated like a flat launch (ruling 26): the seed
// and the sidecar have no control socket, the run role has the one just
@@ -152,6 +163,7 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s
return p, nil, nil, nil, instancekey.LayerNone, err
}
}
+ steps.mark(time.Now(), "key gate")
// The cmd role's output goes only to its own chunks, never to the
// journal or the app log, so it has no app-log listener.
var logs *logListener
@@ -165,6 +177,7 @@ func (b *ExecBackend) prepareKeyedAt(rt registry.Route, role instancectl.Role, s
return p, nil, nil, nil, instancekey.LayerNone, fmt.Errorf("log listener for %s %s: %w", rt.Host, role, err)
}
}
+ steps.mark(time.Now(), "logs")
return p, ctl, logs, env, keyLayer, nil
}
diff --git a/internal/activator/swaphold.go b/internal/activator/swaphold.go
index c55654d96..279606566 100644
--- a/internal/activator/swaphold.go
+++ b/internal/activator/swaphold.go
@@ -458,13 +458,17 @@ func (a *Service) startPinnedAt(ctx context.Context, rt registry.Route, pin Gen,
// records again). A refusal returns no process: nothing ran. If the
// backend's own exec gate then refuses, the state names a build about to
// run that did not, which the spec allows ("or one about to").
+ // Timed for the journal (wake latency, pass 2).
+ began := time.Now()
if err := a.recordBuild(ctx, rt.Host, pin.Build); err != nil {
return nil, "", pin, err
}
+ recorded := time.Now()
g, proc, err := gb.StartStaged(withExecGate(ctx, gate), rt, pin)
if err != nil {
return proc, "", pin, err
}
+ started := time.Now()
if g.N != pin.N || g.Build != pin.Build || g.StagedPath != pin.StagedPath {
return proc, "", pin, fmt.Errorf("%w: generation %d of %s from %q; the hold chose %s from %q", errPinMismatch, g.N, g.Build, g.StagedPath, pin.Build, pin.StagedPath)
}
@@ -477,6 +481,8 @@ func (a *Service) startPinnedAt(ctx context.Context, rt registry.Route, pin Gen,
if err := a.genHealthy(hctx, g); err != nil {
return proc, "", g, err
}
+ log.Printf("activator: %s: generation %d of %s: record %s, start %s, healthy %s later", rt.Host, g.N, g.Build,
+ recorded.Sub(began).Round(time.Millisecond), started.Sub(recorded).Round(time.Millisecond), time.Since(started).Round(time.Millisecond))
gb.GenReady(rt, g, proc)
return proc, g.Build, g, nil
}
diff --git a/internal/instancectl/gen.go b/internal/instancectl/gen.go
index c23172173..54b308362 100644
--- a/internal/instancectl/gen.go
+++ b/internal/instancectl/gen.go
@@ -155,6 +155,7 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) {
if s.refuseStagedExe(w, req, unit) {
return
}
+ checked := time.Now()
if s.refuseStart(w, req.host, unit, func() error {
err := s.ensureGenExeAt(req.host, req.gen, req.exe)
if err != nil {
@@ -168,10 +169,12 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) {
s.removeGenFiles(unit)
http.Error(w, msg, status)
}
+ laidOut := time.Now()
if err := s.writeGenDropIn(req.host, req.gen, req.tier); err != nil {
fail(http.StatusBadGateway, "drop-in: "+err.Error())
return
}
+ written := time.Now()
// The reload is only for a unit systemd already holds loaded from older
// files. A generation's unit is new and an inactive one is unloaded
// straight away, so the next reference reads the drop-in fresh: the
@@ -210,8 +213,9 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) {
s.abandonGen(ctx, w, req.host, unit, "show: "+err.Error())
return
}
- s.logf("instance-control: %s: started %s memory.max=%d (prepared in %s, reload %s, start %s)", req.host, unit, req.tier.MemoryMax,
- startAt.Sub(began).Round(time.Millisecond), reload, time.Since(startAt).Round(time.Millisecond))
+ ms := func(d time.Duration) time.Duration { return d.Round(time.Millisecond) }
+ s.logf("instance-control: %s: started %s memory.max=%d (prepared in %s: staged exe %s, layout %s, drop-in %s, check and tier %s; reload %s, start %s)", req.host, unit, req.tier.MemoryMax,
+ ms(startAt.Sub(began)), ms(checked.Sub(began)), ms(laidOut.Sub(checked)), ms(written.Sub(laidOut)), ms(startAt.Sub(written)), reload, ms(time.Since(startAt)))
writeJSON(w, http.StatusOK, StartResponse{InvocationID: strings.TrimSpace(inv)})
}
diff --git a/internal/lease/lease.go b/internal/lease/lease.go
index 3da80af54..11c14c5de 100644
--- a/internal/lease/lease.go
+++ b/internal/lease/lease.go
@@ -15,6 +15,7 @@ import (
"context"
"errors"
"fmt"
+ "log"
"os"
"path/filepath"
"sync"
@@ -175,10 +176,12 @@ func AcquireTTL(ctx context.Context, bucket, prefix, region string, ttl time.Dur
// and the data it guards must resolve to the same store. The region is
// resolved ONCE, here, and carried on the Held: Replicate's replica client
// has to sign for whatever this client signed for.
+ began := time.Now()
client, region, err := newLeaserClient(ctx, region)
if err != nil {
return nil, err
}
+ built := time.Now()
leaser := lss3.NewLeaser()
leaser.SetClient(client)
@@ -205,6 +208,10 @@ func AcquireTTL(ctx context.Context, bucket, prefix, region string, ttl time.Dur
_ = leaser.ReleaseLease(relCtx, cur)
return nil, err
}
+ // Journal only: the wake's lease step, split into the client and the
+ // lock's own read and conditional write.
+ log.Printf("lease: %s: acquired in %s (client %s, lock read and write %s)", prefix,
+ time.Since(began).Round(time.Millisecond), built.Sub(began).Round(time.Millisecond), time.Since(started).Round(time.Millisecond))
return &Held{leaser: leaser, region: region, rn: rn}, nil
}
diff --git a/internal/provision/testdata/plan14-root-reads-chain.tsv b/internal/provision/testdata/plan14-root-reads-chain.tsv
index 200795c50..56acc4c12 100644
--- a/internal/provision/testdata/plan14-root-reads-chain.tsv
+++ b/internal/provision/testdata/plan14-root-reads-chain.tsv
@@ -4,4 +4,5 @@
plan14-root-reads-sec-host-imdsv2-module.tsv 945934f5978ace14dc5a9bae0ed69dfabf29b994504fc843c03d4a633ecd6c6a
plan14-root-reads-sec-deps-dos-bumps.tsv 945934f5978ace14dc5a9bae0ed69dfabf29b994504fc843c03d4a633ecd6c6a
plan14-root-reads-sec-sidecar-create-gate.tsv 0ca3baafa26f59c0b7d8c6d6a39237d074afb71f885b7fbd50debebab5bf89f2
-plan14-root-reads-sec-mail-user-boundary.tsv b64b923281b55c7309e5ecb440cbc0869127e43b6f963849eb30257abb9fba6c
+plan14-root-reads-wake-latency-2.tsv 27b020590845320cd37b94fdeddf61b7c6f90e12ba7841850f2e7bbd6836ecd8
+plan14-root-reads-sec-mail-user-boundary.tsv 68ca9635da386f34ef483c790af19e954122c11edc406d64cde8d55d99d12de5
diff --git a/internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv b/internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv
new file mode 100644
index 000000000..86337c8d9
--- /dev/null
+++ b/internal/provision/testdata/plan14-root-reads-wake-latency-2.tsv
@@ -0,0 +1,13 @@
+# Census overlay wake-latency-2, written by census-propose (#369). census-ruling-wake-latency-2, approved by the census owner before the merge; the approval card is docs/superpowers/notes/census-proposal-wake-latency-2.md.
+# 3 body, 1 sites, 3 envelope: each changed unit re-frozen at its existing disposition with its claim appended.
+@legacy b2c5ff1260bffcd7f2cc4b537ebc79989befbc6aeaf04f4330d775cb30cb49fe internal/activator/backend_exec.go ExecBackend.spawnUnitFrom legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=Re-digested at the pre-land merge: the body includes main's own change under census ruling 292, with no further change from this branch. the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): main's body; it calls prepareKeyedAt and keeps the launch environment and its key layer on the generation's handle; read sites unchanged, offsets moved;rev3=census-ruling-wake-latency-2;basis=times the launch's steps with time.Now() (build, prepare, launch file, gate, root start) and adds them to its existing "started" journal line; no read added or moved registry:Host@1185,registry:Host@1662,registry:Host@1820,registry:Host@2277,registry:Host@2757,registry:Host@3753,registry:Host@4339,registry:Host@4609,registry:Host@4829,registry:Host@5014,registry:Host@5409,registry:Host@5690,registry:Host@5752,registry:Host@5910,registry:Host@5949,registry:Host@6797,registry:Host@6891,whole:Route@1349,whole:Route@1591,whole:Route@2993,whole:Route@308,whole:Route@4662,whole:Route@5843,whole:Route@6023,whole:Route@872,whole:Route@970 24ca0bdb76b85948fb34916a49eab74e5eaf4ebea02d57adc309cbe9d0adafd8
+@legacy 41bab0818501b13d67f0b5201601faa043c0097016faabe1d932155d1080e170 internal/activator/prepare.go ExecBackend.prepareAt legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): now a wrapper: its ReadDir and its Host and route reads moved, unchanged, into prepareKeyedAt;rev3=census-ruling-wake-latency-2;basis=passes nil for prepareKeyedAt's new timing parameter; nothing else changed whole:Route@227 6aa2cdbd41f356d0a7497025efacb62b05a5e4f293cb20b3423bddc4c92ae72a
+@legacy 43fecababb55813cdd4ead403f99f119705bce26992eef5bcf85e0b25ffefeb8 internal/activator/prepare.go ExecBackend.prepareKeyedAt legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=Re-digested at the pre-land merge: the body includes main's own change under census ruling zddr4, with no further change from this branch beyond carrying main's new early return into the six-value signature. the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): body of the frozen prepareAt, which is now its wrapper; it also returns the instance key's layer and reads no env for the cmd role; same reads, same nested launch paths;rev3=census-ruling-wake-latency-2;basis=takes an optional timer and marks its steps with time.Now() (dirs, admin token, instance key, env, control socket, key gate, logs); no read added or moved file:ReadDir@2531,registry:Host@1162,registry:Host@1280,registry:Host@1588,registry:Host@5195,registry:Host@5384,registry:Host@612,whole:Route@1398,whole:Route@1705,whole:Route@320,whole:Route@4244,whole:Route@4772,whole:Route@5229 8f172cc2cdb6cea7fad368c8c0a153f1e196616b39307a9bee0c6c1672f797b2
+@legacy dc96074aa3bb2b5cea94c19a05330846701676abe78a3fa42a3587dc54c8556e internal/activator/swaphold.go Service.startPinnedAt legacy accepted-legacy accepted-legacy;rev3=J1;basis=root-route;rev3=census-ruling-wake-latency-2;basis=times record, staged start and health with time.Now() and logs them with rt.Host after a healthy start (the new registry:Host site is that log line); no read added or moved registry:Host@1183,registry:Host@1964,whole:Route@1328,whole:Route@2139,whole:Route@435 20c4e4acf9186100d5f9d3e188665597bd36f790443691a9d8c84555b67ade8a
+internal/activator/backend_exec.go ExecBackend.spawnUnitFrom legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=Re-digested at the pre-land merge: the body includes main's own change under census ruling 292, with no further change from this branch. the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): main's body; it calls prepareKeyedAt and keeps the launch environment and its key layer on the generation's handle; read sites unchanged, offsets moved;rev3=census-ruling-wake-latency-2;basis=times the launch's steps with time.Now() (build, prepare, launch file, gate, root start) and adds them to its existing "started" journal line; no read added or moved registry:Host@1185,registry:Host@1662,registry:Host@1820,registry:Host@2277,registry:Host@2757,registry:Host@3753,registry:Host@4339,registry:Host@4609,registry:Host@4829,registry:Host@5014,registry:Host@5409,registry:Host@5690,registry:Host@5752,registry:Host@5910,registry:Host@5949,registry:Host@6797,registry:Host@6891,whole:Route@1349,whole:Route@1591,whole:Route@2993,whole:Route@308,whole:Route@4662,whole:Route@5843,whole:Route@6023,whole:Route@872,whole:Route@970 24ca0bdb76b85948fb34916a49eab74e5eaf4ebea02d57adc309cbe9d0adafd8
+internal/activator/prepare.go ExecBackend.prepareAt legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): now a wrapper: its ReadDir and its Host and route reads moved, unchanged, into prepareKeyedAt;rev3=census-ruling-wake-latency-2;basis=passes nil for prepareKeyedAt's new timing parameter; nothing else changed whole:Route@227 6aa2cdbd41f356d0a7497025efacb62b05a5e4f293cb20b3423bddc4c92ae72a
+internal/activator/prepare.go ExecBackend.prepareKeyedAt legacy accepted-legacy accepted-legacy;rev3=census-ruling-carlos-run;basis=Re-digested at the pre-land merge: the body includes main's own change under census ruling zddr4, with no further change from this branch beyond carrying main's new early return into the six-value signature. the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): body of the frozen prepareAt, which is now its wrapper; it also returns the instance key's layer and reads no env for the cmd role; same reads, same nested launch paths;rev3=census-ruling-wake-latency-2;basis=takes an optional timer and marks its steps with time.Now() (dirs, admin token, instance key, env, control socket, key gate, logs); no read added or moved file:ReadDir@2531,registry:Host@1162,registry:Host@1280,registry:Host@1588,registry:Host@5195,registry:Host@5384,registry:Host@612,whole:Route@1398,whole:Route@1705,whole:Route@320,whole:Route@4244,whole:Route@4772,whole:Route@5229 8f172cc2cdb6cea7fad368c8c0a153f1e196616b39307a9bee0c6c1672f797b2
+internal/activator/swaphold.go Service.startPinnedAt legacy accepted-legacy accepted-legacy;rev3=J1;basis=root-route;rev3=census-ruling-wake-latency-2;basis=times record, staged start and health with time.Now() and logs them with rt.Host after a healthy start (the new registry:Host site is that log line); no read added or moved registry:Host@1183,registry:Host@1964,whole:Route@1328,whole:Route@2139,whole:Route@435 20c4e4acf9186100d5f9d3e188665597bd36f790443691a9d8c84555b67ade8a
+@coverage internal/activator 01ef3773518c962eaf5e0bc12dce99847f6fa42326f39a5f5e201941d10eaf5c
+@coverage internal/instancectl 8b91f954d7b96ca3ff0251152d7049aa94c935680c12e7f5eb2cfc47105f1add
+@coverage internal/lease 65b4e9e54300b00e8d09af4580c7184b78977bfecff40adfdff2ab9eb571fbb2