amadan
Wake latency pass 1: no per-wake daemon-reload, 5→50 ms health poll, per-step wake timing (census-ruling-wake-latency-1)
Squashed from wake-latency-1 into main.
11 files changed,
+355
−21
docs/superpowers/notes/census-proposal-wake-latency-1.md+64 −0internal/activator/activator.go+15 −0internal/activator/backend_exec.go+24 −1internal/activator/backend_unit.go+3 −1internal/activator/healthpoll_test.go+24 −0internal/activator/wakesteps.go+40 −0internal/activator/wakesteps_test.go+30 −0internal/instancectl/gen.go+44 −10internal/instancectl/server_gen_test.go+86 −9internal/provision/plan14_root_reads_test.go+15 −0internal/provision/testdata/plan14-root-reads-wake-latency-1.tsv+10 −0
CI passed — run details
CI log
=== gate ===
.amadan/test-gate.sh
=== launchctx (1 s)
ok amadan.net/carlos/platform.git/launchctx 0.012s
? amadan.net/carlos/platform.git/launchctx/controlname [no test files]
? amadan.net/carlos/platform.git/launchctx/wireid [no test files]
=== vet (18 s)
=== gofmt (1 s)
gofmt -l .: clean
=== rest (167 s)
? github.com/carlosframework/platform/cmd/changelog [no test files]
ok github.com/carlosframework/platform/cmd/console 3.926s
ok github.com/carlosframework/platform/cmd/moveprobe 12.280s
ok github.com/carlosframework/platform/cmd/zddprobe 0.782s
ok github.com/carlosframework/platform/internal/activator 58.072s
ok github.com/carlosframework/platform/internal/agentsock 0.035s
ok github.com/carlosframework/platform/internal/alerting 0.004s
ok github.com/carlosframework/platform/internal/analytics 0.047s
ok github.com/carlosframework/platform/internal/appconfig 3.019s
ok github.com/carlosframework/platform/internal/apperr 0.147s
ok github.com/carlosframework/platform/internal/applog 0.220s
ok github.com/carlosframework/platform/internal/awsinv 0.006s
ok github.com/carlosframework/platform/internal/boxchoice 0.005s
ok github.com/carlosframework/platform/internal/boxid 0.918s
? 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.009s
ok github.com/carlosframework/platform/internal/caps 0.015s
ok github.com/carlosframework/platform/internal/certwarm 0.005s
ok github.com/carlosframework/platform/internal/cgroup 0.815s
ok github.com/carlosframework/platform/internal/changelog 0.576s
ok github.com/carlosframework/platform/internal/claimactivation 1.257s
ok github.com/carlosframework/platform/internal/clamd 0.065s
? 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.024s
ok github.com/carlosframework/platform/internal/dbdoor/dbdoortest 0.010s
ok github.com/carlosframework/platform/internal/dbquery 0.006s
ok github.com/carlosframework/platform/internal/dbreads 2.132s
? github.com/carlosframework/platform/internal/dbreads/dbreadstest [no test files]
ok github.com/carlosframework/platform/internal/dbverify 0.004s
ok github.com/carlosframework/platform/internal/dnsrec 0.005s
ok github.com/carlosframework/platform/internal/docsite 0.007s
ok github.com/carlosframework/platform/internal/domains 3.078s
ok github.com/carlosframework/platform/internal/doorkey 0.010s
ok github.com/carlosframework/platform/internal/economics 0.018s
ok github.com/carlosframework/platform/internal/edge 45.509s
? 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.131s
ok github.com/carlosframework/platform/internal/gate 1.655s
ok github.com/carlosframework/platform/internal/genselect 0.015s
ok github.com/carlosframework/platform/internal/geo 0.018s
ok github.com/carlosframework/platform/internal/geoip 0.030s
ok github.com/carlosframework/platform/internal/historyreadback 0.152s
ok github.com/carlosframework/platform/internal/host 138.422s
ok github.com/carlosframework/platform/internal/hostactors 6.286s
ok github.com/carlosframework/platform/internal/hostactors/awsmembership 0.008s
ok github.com/carlosframework/platform/internal/hostbox 3.144s
ok github.com/carlosframework/platform/internal/hostclaim 0.770s
ok github.com/carlosframework/platform/internal/hostenv 0.005s
ok github.com/carlosframework/platform/internal/hostevidence 0.010s
ok github.com/carlosframework/platform/internal/hostexec 5.281s
ok github.com/carlosframework/platform/internal/hostfence 0.052s
ok github.com/carlosframework/platform/internal/hostfiles 10.306s
ok github.com/carlosframework/platform/internal/hostfloor 0.017s
ok github.com/carlosframework/platform/internal/hostguard 1.050s
ok github.com/carlosframework/platform/internal/hostops 1.983s
? 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.005s
ok github.com/carlosframework/platform/internal/hostrelocate 0.618s
ok github.com/carlosframework/platform/internal/hostresolve 0.232s
ok github.com/carlosframework/platform/internal/hostwrite 0.004s
ok github.com/carlosframework/platform/internal/infraview 0.002s
ok github.com/carlosframework/platform/internal/instancectl 5.242s
ok github.com/carlosframework/platform/internal/instanceexec 2.811s
ok github.com/carlosframework/platform/internal/instancefs 0.006s
ok github.com/carlosframework/platform/internal/instancekey 0.004s
ok github.com/carlosframework/platform/internal/instanceupdates 0.011s
ok github.com/carlosframework/platform/internal/layout 1.699s
ok github.com/carlosframework/platform/internal/lbhealth 0.005s
ok github.com/carlosframework/platform/internal/lease 10.280s
ok github.com/carlosframework/platform/internal/lease/leasetest 0.542s
ok github.com/carlosframework/platform/internal/ledger 0.015s
ok github.com/carlosframework/platform/internal/mail 0.253s
ok github.com/carlosframework/platform/internal/maintenance 0.096s
ok github.com/carlosframework/platform/internal/maintenanceexec 5.644s
ok github.com/carlosframework/platform/internal/maintenanceguard 0.088s
ok github.com/carlosframework/platform/internal/metrics 0.005s
ok github.com/carlosframework/platform/internal/moves 22.445s
ok github.com/carlosframework/platform/internal/moves/archive 0.956s
ok github.com/carlosframework/platform/internal/objstore 0.273s
ok github.com/carlosframework/platform/internal/ops 0.265s
ok github.com/carlosframework/platform/internal/park 0.280s
ok github.com/carlosframework/platform/internal/plans 0.011s
ok github.com/carlosframework/platform/internal/privatefile 0.005s
ok github.com/carlosframework/platform/internal/provision 23.278s
ok github.com/carlosframework/platform/internal/publicrelease 0.021s
? github.com/carlosframework/platform/internal/regionname [no test files]
ok github.com/carlosframework/platform/internal/registry 5.527s
ok github.com/carlosframework/platform/internal/relay 7.240s
ok github.com/carlosframework/platform/internal/release 26.292s
ok github.com/carlosframework/platform/internal/rollout 3.844s
ok github.com/carlosframework/platform/internal/rolloutwords 0.004s
ok github.com/carlosframework/platform/internal/rootaws 0.011s
ok github.com/carlosframework/platform/internal/rootparticipation 0.058s
ok github.com/carlosframework/platform/internal/rootstate 0.030s
ok github.com/carlosframework/platform/internal/runs 0.606s
ok github.com/carlosframework/platform/internal/s3compat 0.007s
ok github.com/carlosframework/platform/internal/safefile 0.004s
ok github.com/carlosframework/platform/internal/schedule 2.623s
ok github.com/carlosframework/platform/internal/seeds 0.011s
ok github.com/carlosframework/platform/internal/sim/engines 2.607s
ok github.com/carlosframework/platform/internal/sim/hostlife 10.681s
ok github.com/carlosframework/platform/internal/sim/litestreamfacts 4.060s
ok github.com/carlosframework/platform/internal/status 0.092s
ok github.com/carlosframework/platform/internal/steering 0.009s
ok github.com/carlosframework/platform/internal/stopevidence 0.292s
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.005s
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.649s
=== internal_console@0 (87 s)
ok github.com/carlosframework/platform/internal/console 86.047s
=== internal_console@1 (43 s)
ok github.com/carlosframework/platform/internal/console 41.830s
=== internal_console@2 (41 s)
ok github.com/carlosframework/platform/internal/console 39.407s
=== internal_console@3 (41 s)
ok github.com/carlosframework/platform/internal/console 39.756s
=== internal_console@4 (42 s)
ok github.com/carlosframework/platform/internal/console 40.494s
=== internal_console@5 (40 s)
ok github.com/carlosframework/platform/internal/console 38.987s
=== internal_console@6 (37 s)
ok github.com/carlosframework/platform/internal/console 35.446s
=== internal_console@7 (46 s)
ok github.com/carlosframework/platform/internal/console 44.453s
=== root@0 (109 s)
ok github.com/carlosframework/platform 107.631s
=== root@1 (82 s)
ok github.com/carlosframework/platform 80.940s
=== root@2 (92 s)
ok github.com/carlosframework/platform 90.751s
=== 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: 50528418 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: downloading https://github.com/minio/minio/releases/download/RELEASE.2025-09-07T16-13-09Z/minio.linux-arm64.RELEASE.2025-09-07T16-13-09Z
minio: downloaded, digest verified
mc: downloading https://github.com/minio/mc/releases/download/RELEASE.2025-08-13T08-35-41Z/mc.linux-arm64.RELEASE.2025-08-13T08-35-41Z
mc: downloaded, digest verified
minio healthy on 127.0.0.1:20999
Added `local` successfully.
Bucket created successfully `local/contract-bucket`.
Bucket created successfully `local/denied-bucket`.
Created policy `contract-only` successfully.
Added user `scopeduser` successfully.
Attached Policies: [contract-only]
To User: scopeduser
buckets and scoped user ready
=== RUN TestDeliveredContractMinio
=== RUN TestDeliveredContractMinio/put
=== RUN TestDeliveredContractMinio/get_round-trips_the_body
=== RUN TestDeliveredContractMinio/list_shows_the_key
=== RUN TestDeliveredContractMinio/head_and_list_agree_on_the_version
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_its_own_object
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/not_by_PutObjectTagging
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/and_not_by_x-amz-tagging_on_upload
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CreateMultipartUpload
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CopyObject_with_a_REPLACE_tagging_directive
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/but_multipart_itself_is_allowed
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_copy_itself_is_allowed
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/a_POST-policy_forged_tag_with_a_matching_version_is_still_not_a_verdict
=== RUN TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_an_ordinary_tagged-with-something-else_upload_is_allowed
=== RUN TestDeliveredContractMinio/delete_removes_it
=== RUN TestDeliveredContractMinio/cross-bucket_denial
--- PASS: TestDeliveredContractMinio (0.02s)
--- PASS: TestDeliveredContractMinio/put (0.00s)
--- PASS: TestDeliveredContractMinio/get_round-trips_the_body (0.00s)
--- PASS: TestDeliveredContractMinio/list_shows_the_key (0.00s)
--- PASS: TestDeliveredContractMinio/head_and_list_agree_on_the_version (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/not_by_PutObjectTagging (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_its_own_object/and_not_by_x-amz-tagging_on_upload (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route (0.01s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CreateMultipartUpload (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/not_by_CopyObject_with_a_REPLACE_tagging_directive (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/but_multipart_itself_is_allowed (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_copy_itself_is_allowed (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/a_POST-policy_forged_tag_with_a_matching_version_is_still_not_a_verdict (0.00s)
--- PASS: TestDeliveredContractMinio/the_app_cannot_tag_by_any_other_route/and_an_ordinary_tagged-with-something-else_upload_is_allowed (0.00s)
--- PASS: TestDeliveredContractMinio/delete_removes_it (0.00s)
--- PASS: TestDeliveredContractMinio/cross-bucket_denial (0.00s)
PASS
ok github.com/carlosframework/platform/internal/objstore 0.022s
=== RUN TestT4StorageProbeMinio
2026/10/24 18:33:34 moves: T4: STORE: list: operation error S3: ListObjectsV2, https response error StatusCode: 403, RequestID: 18E18ADE6059627A, HostID: 7c420053e0fbcd7f41653fdd92ffa2802c903d05303b1aa15adc2e8bb65d183f, api error SignatureDoesNotMatch: The request signature we calculated does not match the signature you provided. Check your key and signing method.
--- PASS: TestT4StorageProbeMinio (0.00s)
PASS
ok github.com/carlosframework/platform/internal/host 0.020s
=== RUN TestS3StoreMinioContract
=== RUN TestS3StoreMinioContract/conditional_get_and_etag_listing
=== RUN TestS3StoreMinioContract/bump_through_every_mutation_path
--- PASS: TestS3StoreMinioContract (0.02s)
--- PASS: TestS3StoreMinioContract/conditional_get_and_etag_listing (0.01s)
--- PASS: TestS3StoreMinioContract/bump_through_every_mutation_path (0.01s)
PASS
ok github.com/carlosframework/platform/internal/release 0.028s
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 18:33:36 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000000 txid.db=0000000000000001
2026/10/24 18:33:36 INFO ltx file uploaded system=store db=source.db replica=file level=0 minTXID=0000000000000001 maxTXID=0000000000000001 size=720
2026/10/24 18:33:36 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000001 txid.db=0000000000000001
2026/10/24 18:33:36 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000001 txid.db=0000000000000002
2026/10/24 18:33:36 INFO ltx file uploaded system=store db=source.db replica=file level=0 minTXID=0000000000000002 maxTXID=0000000000000002 size=370
2026/10/24 18:33:36 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000002 txid.db=0000000000000002
2026/10/24 18:33:36 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000002 txid.db=0000000000000003
2026/10/24 18:33:36 INFO ltx file uploaded system=store db=source.db replica=file level=0 minTXID=0000000000000003 maxTXID=0000000000000003 size=454
2026/10/24 18:33:36 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000003 txid.db=0000000000000003
2026/10/24 18:33:36 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000000 txid.db=0000000000000001
2026/10/24 18:33:36 INFO ltx file uploaded system=store db=source.db replica=file level=0 minTXID=0000000000000001 maxTXID=0000000000000001 size=720
2026/10/24 18:33:36 INFO replica sync system=store db=source.db replica=file txid.replica=0000000000000001 txid.db=0000000000000001
2026/10/24 18:33:36 console: CARLOS_SECRETS_PUBKEY is unset, so no region outside the home can be chosen automatically
2026/10/24 18:33:36 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%3A36729: could not determine target mailbox
agent.go:135: dbreads: dbr_coq5k7tsaafdqeisaag7x3wgoa: planned 3 files (1544 bytes) and restored to 3 in 9ms
agent.go:135: dbreads: dbr_coq5k7tsaafdqeisaag7x3wgoa: output 5 bytes in 1 confirmed chunks in 1ms
2026/10/24 18:33:37 console: db read dbr_coq5k7tsaafdqeisaag7x3wgoa: relayed 1 chunks (102 bytes) in 1.004s, ended done
agent.go:135: dbreads: dbr_ltv65lpcvoswpsazem7k64l454: planned 1 files (720 bytes) and restored to 1 in 7ms
agent.go:135: dbreads: dbr_ltv65lpcvoswpsazem7k64l454: output 5 bytes in 1 confirmed chunks in 1ms
2026/10/24 18:33:38 console: db read dbr_ltv65lpcvoswpsazem7k64l454: relayed 1 chunks (102 bytes) in 1.004s, ended done
agent.go:135: dbreads: dbr_h4tk3iddmihrcv355hsxb7wi4m: planned 3 files (1544 bytes) and held through 3 in 8ms
agent.go:135: dbreads: dbr_h4tk3iddmihrcv355hsxb7wi4m: output 1544 bytes in 1 confirmed chunks in 1ms
2026/10/24 18:33:39 console: db read dbr_h4tk3iddmihrcv355hsxb7wi4m: relayed 1 chunks (1641 bytes) in 1.004s, ended done
=== RUN TestDBForwardMinio/by_disconnect
=== NAME TestDBForwardMinio
agent.go:135: dbreads: dbr_d6td3wqwipyinq2u5hf4abo77e: planned 3 files (1544 bytes) and restored to 3 in 9ms
2026/10/24 18:33:39 console: db read dbr_d6td3wqwipyinq2u5hf4abo77e: relayed 0 chunks (0 bytes) in 13ms, ended client gone
agent.go:135: dbreads: dbr_d6td3wqwipyinq2u5hf4abo77e: output 5 bytes in 1 confirmed chunks in 16ms
=== RUN TestDBForwardMinio/by_timeout
=== NAME TestDBForwardMinio
agent.go:135: dbreads: dbr_escwmqpgzez2pyq7h6bm3vieya: planned 3 files (1544 bytes) and restored to 3 in 9ms
2026/10/24 18:33:59 console: db read dbr_escwmqpgzez2pyq7h6bm3vieya: relayed 0 chunks (0 bytes) in 19.213s, ended no-result
agent.go:135: dbreads: dbr_escwmqpgzez2pyq7h6bm3vieya: output 5 bytes in 1 confirmed chunks in 19.186s
--- PASS: TestDBForwardMinio (22.55s)
--- PASS: TestDBForwardMinio/by_disconnect (0.13s)
--- PASS: TestDBForwardMinio/by_timeout (19.32s)
PASS
ok github.com/carlosframework/platform/internal/console 22.567s
minio contract: PASS
diff --git a/docs/superpowers/notes/census-proposal-wake-latency-1.md b/docs/superpowers/notes/census-proposal-wake-latency-1.md| new file mode 100644 |
| index 000000000..522f74564 |
| --- /dev/null |
| +++ b/docs/superpowers/notes/census-proposal-wake-latency-1.md |
| @@ -0,0 +1,64 @@ |
| +# Census: wake latency, pass 1 |
| + |
| +Status: ACCEPTED as proposed by the census owner on #280, 2026-10-24, as |
| +`census-ruling-wake-latency-1`. Every row now carries |
| +`rev3=census-ruling-wake-latency-1`; the `@legacy` fingerprints were |
| +recomputed and the seal moved to |
| +`09e20ea4bbc534710334e632e903878656dabfb5817d4d96c6e7c56508172148`. |
| + |
| +The census owner's rationale (the recommendation, accepted): clock reads and |
| +journal lines only, no read added or moved, the same class as the accepted |
| +envelope re-pins. |
| + |
| +The branch is `wake-latency-1`, cut from amadan `main` at 64a002c8. A dev |
| +wake took 843 ms for an app that boots in milliseconds, and a box-wide |
| +`systemctl daemon-reload` inside instance-control's generation start took |
| +297 ms of it (dev box journal, 2026-10-24 11:16:31). The branch: |
| + |
| +- starts a generation without the reload when systemd already reads its |
| + drop-in (`internal/instancectl/gen.go`, `startGen` and |
| + `genDropInApplied`): one `systemctl show` of Slice, NeedDaemonReload and |
| + the tier's three memory lines, and a reload only when any of them is not |
| + the drop-in's, then the same check again before the start; |
| +- backs off health probes from 5 ms to 50 ms instead of a fixed 150 ms |
| + (`waitHealthy`, `waitHealthyAddr`); |
| +- logs per-step wake timing to the journal (`wakeSteps`). |
| + |
| +It adds one root-read overlay, |
| +`internal/provision/testdata/plan14-root-reads-wake-latency-1.tsv`, loaded |
| +last in `TestPlan14RootReadCensus`, after `db-region-forward-3` (the overlay |
| +main loads last at 64a002c8). |
| + |
| +## Root reads |
| + |
| +Executing identity, for every unit: the agent (`/opt/carlos/carlos agent`, |
| +`carlos-edge.service`, user carlos). |
| + |
| +| unit | change | proposed disposition | |
| +|---|---|---| |
| +| `internal/activator/activator.go` `Service.doWake` | marks the end of each wake step on the wake's timer: `a.now()` and a slice append, journal only. No read added, no step moved | re-frozen at `census-ruling-292fix` with this change appended | |
| +| `internal/activator/activator.go` `Service.wake` | logs that timer's breakdown after a successful wake. No read added | re-frozen at `census-ruling-carlos-run` with this change appended | |
| +| `internal/activator/backend_exec.go` `ExecBackend.startUnitAt` | times the unit's launch and its health wait with `time.Now()`, and logs both after a successful health wait. The log names `rt.Host`, which is the new `registry:Host` site. No read added, no behaviour changed | re-frozen at J1 (`root-route`) with this change appended | |
| + |
| +Frozen declarations are added, so the seal moves from |
| +`79cb56b4c7d3a8e155d1eff1902715d818fcf4c09b1d8a82921c413b116938a9` |
| +(`db-region-forward-3`'s, checked before the overlay loads) to |
| +`09e20ea4bbc534710334e632e903878656dabfb5817d4d96c6e7c56508172148` (it |
| +was `5976190a…4b1a` while the rows were PROPOSED). |
| + |
| +Two envelopes are re-pinned: |
| + |
| +| envelope | why | |
| +|---|---| |
| +| `internal/activator` | the units above, `wakesteps.go`, and the health-probe backoff in `backend_exec.go` and `backend_unit.go` | |
| +| `internal/instancectl` | `startGen`'s drop-in check in `gen.go`, and the timings on its start log line | |
| + |
| +`startGen` is outside the scanner's units: its `systemctl` calls run as |
| +instance-control (`carlos-instance-control.service`, root), the same calls |
| +in a different order, and the reload is now conditional. Review: Astra round |
| +1 found one P2 (NeedDaemonReload is mtime-based, so a reused and |
| +still-loaded generation could read as applied). It was fixed by checking the |
| +tier's memory lines, and round 2 was clean. |
| + |
| +Record-write census (9B8): unchanged. Claim routes: unchanged. go.mod: |
| +unchanged. |
diff --git a/internal/activator/activator.go b/internal/activator/activator.go| index dbd881d66..8aa16e0f5 100644 |
| --- a/internal/activator/activator.go |
| +++ b/internal/activator/activator.go |
| @@ -1799,6 +1799,9 @@ func (a *Service) wake(e *actEntry) { |
| } |
| } else { |
| emitEvent(a.Logs, e.route, "info", wakeEventMessage(w, e.worker)) |
| + if steps := w.steps.String(); steps != "" { |
| + log.Printf("activator: %s: woke in %s: %s", e.host, w.wakeTook.Round(time.Millisecond), steps) |
| + } |
| } |
| var ( |
| @@ -2063,6 +2066,8 @@ type wokenInstance struct { |
| // `carlos logs` already carries the line. |
| spawnTook time.Duration |
| wakeTook time.Duration |
| + // steps is the operator's breakdown of wakeTook, journal only. |
| + steps wakeSteps |
| // planned is the generation a planned wake left serving; failed and |
| // failReason name a first wake's build that failed; fellBack says the |
| @@ -2098,6 +2103,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| // it was (seeded pre-land re-review, P2; census ruling 292fix). |
| w := &wokenInstance{stopOutcome: &stopObservation{}} |
| w.stopOutcome.notStarted() |
| + w.steps.begin(a.now()) |
| if ctx.Err() != nil || !a.wakeAllowed(host) { |
| return w, ErrFenced |
| } |
| @@ -2239,6 +2245,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| // single writer. Contention is not retried here — on one box it means a |
| // previous incarnation hasn't released; tell the client to come back after |
| // the TTL instead of stalling its request. |
| + w.steps.mark(a.now(), "checks") |
| *w.stopOutcome = stopObservation{} |
| lease, err := a.backend.Acquire(ctx, rt) |
| if err != nil { |
| @@ -2253,6 +2260,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| } |
| return w, err |
| } |
| + w.steps.mark(a.now(), "lease") |
| if ctx.Err() != nil || !a.wakeAllowed(host) { |
| w.stopOutcome.leaseReleased = a.giveBack(ctx, host, lease) |
| @@ -2295,6 +2303,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| } |
| return w, fmt.Errorf("restore %s: %w", host, err) |
| } |
| + w.steps.mark(a.now(), "restore") |
| if ctx.Err() != nil || !a.wakeAllowed(host) { |
| w.stopOutcome.leaseReleased = a.giveBack(ctx, host, lease) |
| return w, ErrFenced |
| @@ -2354,6 +2363,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| ctx = wctx |
| } |
| } |
| + w.steps.mark(a.now(), "identity") |
| // 3. First-boot seed, strictly between the restore and the spawn — so it |
| // runs before Start's first health probe, and a brand-new instance is born |
| @@ -2386,6 +2396,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| return w, fmt.Errorf("seed %s: %w", host, err) |
| } |
| w.stopOutcome.uncertain = false |
| + w.steps.mark(a.now(), "seed") |
| } |
| // 4. Spawn before replication starts: a fresh instance creates its own DB |
| @@ -2527,6 +2538,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| spawnVer, w.gen = g.Build, g |
| } |
| spawnTook := a.now().Sub(spawnStart) |
| + w.steps.mark(a.now(), "spawn") |
| w.proc = proc |
| if err != nil { |
| // A start whose kill was unproven may have left its generation |
| @@ -2575,6 +2587,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| a.cleanupFailedWake(ctx, rt, w, lease) |
| return w, fmt.Errorf("start %s: %w", host, serr) |
| } |
| + w.steps.mark(a.now(), "settle") |
| } |
| if ctx.Err() != nil || !a.wakeAllowed(host) { |
| @@ -2601,6 +2614,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| log.Printf("activator: %s: seed placement not recorded yet: %v", host, err) |
| } |
| } |
| + w.steps.mark(a.now(), "replicate") |
| // 6. Co-spawn the sidecar, last — only once the instance is healthy and |
| // replicating, so the sidecar always boots against a live instance (its |
| @@ -2633,6 +2647,7 @@ func (a *Service) doWake(ctx context.Context, e *actEntry) (*wokenInstance, erro |
| } else { |
| w.sidecar = sc |
| } |
| + w.steps.mark(a.now(), "sidecar") |
| } |
| return w, nil |
| } |
diff --git a/internal/activator/backend_exec.go b/internal/activator/backend_exec.go| index 738ff0ccc..6656e8ee9 100644 |
| --- a/internal/activator/backend_exec.go |
| +++ b/internal/activator/backend_exec.go |
| @@ -2547,11 +2547,13 @@ func (b *ExecBackend) spawnUnitFrom(ctx context.Context, rt registry.Route, sock |
| // recorded (StartGenExe), which root binds in place of the link. tier is |
| // exe's own; zero is the live tier (b.tier). |
| func (b *ExecBackend) startUnitAt(ctx context.Context, rt registry.Route, sock string, n uint64, exe *instancectl.StagedExe, tier cgroup.Limit) (Proc, string, error) { |
| + began := time.Now() |
| p, spawnVer, err := b.spawnUnitFrom(ctx, rt, sock, n, exe, tier) |
| if err != nil { |
| return p, "", err |
| } |
| up := p.(*unitProc) |
| + launched := time.Now() |
| if err := waitHealthyCtx(ctx, sock, spawnHealthTimeout); err != nil { |
| // Set before the Stop call below, closing the same race Stop's own |
| // internal set leaves open by a few instructions: observe runs |
| @@ -2582,6 +2584,10 @@ func (b *ExecBackend) startUnitAt(ctx context.Context, rt registry.Route, sock s |
| } |
| return nil, "", err |
| } |
| + // The spawn's own split, for the journal: the unit's launch (instance |
| + // control's half included) and then the app's boot to its socket. |
| + log.Printf("activator: %s: %s launched in %s, healthy %s later", rt.Host, unitName(instancectl.RoleRun, rt.Host, n), |
| + launched.Sub(began).Round(time.Millisecond), time.Since(launched).Round(time.Millisecond)) |
| b.normalizeSocketMode(rt, sock, up) |
| return up, spawnVer, nil |
| } |
| @@ -3239,6 +3245,7 @@ func waitHealthy(socket string, timeout time.Duration) error { |
| deadline := time.Now().Add(timeout) |
| client := socketClient(socket) |
| var last error |
| + var poll time.Duration |
| for time.Now().Before(deadline) { |
| resp, err := client.Get("http://carlos/") |
| if err == nil { |
| @@ -3250,11 +3257,27 @@ func waitHealthy(socket string, timeout time.Duration) error { |
| } else { |
| last = err |
| } |
| - time.Sleep(150 * time.Millisecond) |
| + poll = nextHealthPoll(poll) |
| + time.Sleep(poll) |
| } |
| return fmt.Errorf("instance not healthy within %s: %v", timeout, last) |
| } |
| +// The wait between health probes. A request is held open for the whole of |
| +// a wake, and a fixed 150 ms gap cost it 75 ms on average after the app was |
| +// already listening. A refused dial costs microseconds, so the wait starts |
| +// short and doubles to a ceiling that keeps a slow boot from being probed |
| +// in a busy loop. |
| +const ( |
| + healthPollMin = 5 * time.Millisecond |
| + healthPollMax = 50 * time.Millisecond |
| +) |
| + |
| +// nextHealthPoll is the wait after one of d; zero gives the first. |
| +func nextHealthPoll(d time.Duration) time.Duration { |
| + return min(max(2*d, healthPollMin), healthPollMax) |
| +} |
| + |
| // waitHealthyCtx is waitHealthy bounded by ctx as well as its own timeout, so |
| // an aborted wake doesn't keep probing a socket nobody wants anymore. |
| func waitHealthyCtx(ctx context.Context, socket string, timeout time.Duration) error { |
diff --git a/internal/activator/backend_unit.go b/internal/activator/backend_unit.go| index b970b8c0b..e6b64abb3 100644 |
| --- a/internal/activator/backend_unit.go |
| +++ b/internal/activator/backend_unit.go |
| @@ -251,6 +251,7 @@ func waitHealthyAddr(addr string, timeout time.Duration) error { |
| deadline := time.Now().Add(timeout) |
| client := &http.Client{Timeout: 3 * time.Second} |
| var last error |
| + var poll time.Duration |
| for time.Now().Before(deadline) { |
| resp, err := client.Get("http://" + addr + "/") |
| if err == nil { |
| @@ -262,7 +263,8 @@ func waitHealthyAddr(addr string, timeout time.Duration) error { |
| } else { |
| last = err |
| } |
| - time.Sleep(150 * time.Millisecond) |
| + poll = nextHealthPoll(poll) |
| + time.Sleep(poll) |
| } |
| return fmt.Errorf("instance not healthy within %s: %v", timeout, last) |
| } |
diff --git a/internal/activator/healthpoll_test.go b/internal/activator/healthpoll_test.go| new file mode 100644 |
| index 000000000..0ad398ecc |
| --- /dev/null |
| +++ b/internal/activator/healthpoll_test.go |
| @@ -0,0 +1,24 @@ |
| +package activator |
| + |
| +import ( |
| + "testing" |
| + "time" |
| +) |
| + |
| +// The wait between health probes starts short, so a fast app is noticed |
| +// within milliseconds of binding, and doubles to a ceiling, so a slow one |
| +// is not probed in a busy loop. |
| +func TestHealthPollBacksOffFromShortToACeiling(t *testing.T) { |
| + var got []time.Duration |
| + d := time.Duration(0) |
| + for range 7 { |
| + d = nextHealthPoll(d) |
| + got = append(got, d) |
| + } |
| + want := []time.Duration{5, 10, 20, 40, 50, 50, 50} |
| + for i := range want { |
| + if got[i] != want[i]*time.Millisecond { |
| + t.Fatalf("delays = %v, want %v ms", got, want) |
| + } |
| + } |
| +} |
diff --git a/internal/activator/wakesteps.go b/internal/activator/wakesteps.go| new file mode 100644 |
| index 000000000..68dd3528b |
| --- /dev/null |
| +++ b/internal/activator/wakesteps.go |
| @@ -0,0 +1,40 @@ |
| +package activator |
| + |
| +import ( |
| + "strings" |
| + "time" |
| +) |
| + |
| +// wakeSteps times one wake step by step for the operator's journal. The |
| +// member's wake event carries the total and the spawn (wakeEventMessage); |
| +// this says where the rest went, which is what a slow wake's diagnosis |
| +// needs and what no single figure can show. |
| +type wakeSteps struct { |
| + last time.Time |
| + steps []wakeStep |
| +} |
| + |
| +type wakeStep struct { |
| + name string |
| + took time.Duration |
| +} |
| + |
| +// begin starts the clock. A mark before it records nothing. |
| +func (s *wakeSteps) begin(now time.Time) { s.last = now } |
| + |
| +// mark closes the step called name at now and starts the next. |
| +func (s *wakeSteps) mark(now time.Time, name string) { |
| + if s.last.IsZero() { |
| + return |
| + } |
| + s.steps = append(s.steps, wakeStep{name, now.Sub(s.last)}) |
| + s.last = now |
| +} |
| + |
| +func (s *wakeSteps) String() string { |
| + parts := make([]string, len(s.steps)) |
| + for i, st := range s.steps { |
| + parts[i] = st.name + " " + st.took.Round(time.Millisecond).String() |
| + } |
| + return strings.Join(parts, ", ") |
| +} |
diff --git a/internal/activator/wakesteps_test.go b/internal/activator/wakesteps_test.go| new file mode 100644 |
| index 000000000..1ac2c04c2 |
| --- /dev/null |
| +++ b/internal/activator/wakesteps_test.go |
| @@ -0,0 +1,30 @@ |
| +package activator |
| + |
| +import ( |
| + "testing" |
| + "time" |
| +) |
| + |
| +// Each mark records the time since the one before it, under the step's |
| +// name, so the line reads as where the wake spent its time. |
| +func TestWakeStepsNameTheTimeSinceThePreviousMark(t *testing.T) { |
| + t0 := time.Unix(1000, 0) |
| + var s wakeSteps |
| + s.begin(t0) |
| + s.mark(t0.Add(3*time.Millisecond), "checks") |
| + s.mark(t0.Add(83*time.Millisecond), "lease") |
| + s.mark(t0.Add(83400*time.Microsecond), "restore") |
| + s.mark(t0.Add(752*time.Millisecond), "spawn") |
| + if got, want := s.String(), "checks 3ms, lease 80ms, restore 0s, spawn 669ms"; got != want { |
| + t.Errorf("String = %q, want %q", got, want) |
| + } |
| +} |
| + |
| +// A wake that never began (the claim path, a nil entry) has nothing to say. |
| +func TestWakeStepsWithoutABeginRecordNothing(t *testing.T) { |
| + var s wakeSteps |
| + s.mark(time.Unix(1000, 0), "lease") |
| + if got := s.String(); got != "" { |
| + t.Errorf("String = %q, want empty", got) |
| + } |
| +} |
diff --git a/internal/instancectl/gen.go b/internal/instancectl/gen.go| index 5adf3fb58..c23172173 100644 |
| --- a/internal/instancectl/gen.go |
| +++ b/internal/instancectl/gen.go |
| @@ -18,8 +18,8 @@ import ( |
| // template carlos-instance-gen@<iid>:<n>.service cannot key its slice and |
| // data mounts by itself: systemd has no specifier for part of an instance |
| // string. So before each start this service writes a runtime drop-in with |
| -// everything the template leaves out, reloads, checks that systemd took |
| -// it, and only then starts the unit. |
| +// everything the template leaves out, checks that systemd took it |
| +// (reloading first only when it has not), and only then starts the unit. |
| // ErrGenUnproven is StartGen's answer when the start failed after systemd |
| // may have started the unit and the stop that followed did not prove the |
| @@ -113,6 +113,26 @@ func (s *Server) slicePopulated(host string) bool { |
| return !strings.Contains(string(b), "populated 0") |
| } |
| +// genDropInApplied reports whether systemd's view of unit is the drop-in |
| +// just written (GenDropIn). The unit's name fixes the host and generation, |
| +// and so every line of the drop-in but the tier's: the slice says systemd |
| +// read a drop-in at all, and the memory lines say it was this tier's. |
| +// NeedDaemonReload=no says no file changed since systemd loaded the unit, |
| +// though only by mtime, which is why the tier is checked as well (Astra |
| +// review: a reused, still-loaded generation and a clock that went back). |
| +// Any failure to answer is a no. |
| +func (s *Server) genDropInApplied(ctx context.Context, host, unit string, tier cgroup.Limit) (slice string, ok bool) { |
| + out, err := s.Systemctl(ctx, "show", "-p", "Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax", unit) |
| + if err != nil { |
| + return "", false |
| + } |
| + m := parseShow(out) |
| + max := strconv.FormatInt(tier.MemoryMax, 10) |
| + return m["Slice"], m["Slice"] == SliceName(host) && m["NeedDaemonReload"] == "no" && |
| + m["MemoryMax"] == max && m["MemorySwapMax"] == max && |
| + m["MemoryHigh"] == strconv.FormatInt(cgroup.HighOf(tier.MemoryMax), 10) |
| +} |
| + |
| // startGen is /start with a generation. The host slice is the parent (spec |
| // §7.3): a cold start sets it to the tier. A start that finds the slice |
| // populated leaves it alone, because a swap raised it with /parent before |
| @@ -126,6 +146,8 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) { |
| } |
| s.markGenStarting(unit, true) |
| defer s.markGenStarting(unit, false) |
| + // Timed for the start's log line: a wake waits on all of this. |
| + began, reload := time.Now(), "skipped" |
| // A refusal for the disk writes nothing. An exe layout that fails |
| // half-way may have made its directory, so that failure cleans up too. |
| // A staged executable is validated before anything is laid out |
| @@ -150,13 +172,23 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) { |
| fail(http.StatusBadGateway, "drop-in: "+err.Error()) |
| return |
| } |
| - if out, err := s.Systemctl(ctx, "daemon-reload"); err != nil { |
| - fail(http.StatusBadGateway, "daemon-reload: "+strings.TrimSpace(out+" "+err.Error())) |
| - return |
| - } |
| - if got := s.showValue(ctx, "Slice", unit); got != SliceName(req.host) { |
| - fail(http.StatusBadGateway, "not starting "+unit+": its drop-in did not apply (slice "+strconv.Quote(got)+")") |
| - return |
| + // 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 |
| + // common case needs no reload, which on a small box was a third of the |
| + // whole wake. The check is the same either way (genDropInApplied). |
| + slice, applied := s.genDropInApplied(ctx, req.host, unit, req.tier) |
| + if !applied { |
| + reloadStart := time.Now() |
| + if out, err := s.Systemctl(ctx, "daemon-reload"); err != nil { |
| + fail(http.StatusBadGateway, "daemon-reload: "+strings.TrimSpace(out+" "+err.Error())) |
| + return |
| + } |
| + if slice, applied = s.genDropInApplied(ctx, req.host, unit, req.tier); !applied { |
| + fail(http.StatusBadGateway, "not starting "+unit+": its drop-in did not apply (slice "+strconv.Quote(slice)+")") |
| + return |
| + } |
| + reload = time.Since(reloadStart).Round(time.Millisecond).String() |
| } |
| if !s.slicePopulated(req.host) { |
| if err := s.setTier(ctx, req.host, req.tier); err != nil { |
| @@ -168,6 +200,7 @@ func (s *Server) startGen(w http.ResponseWriter, r *http.Request, req request) { |
| // answer says. A failure past this point kills it and proves it empty |
| // before its files go; one that cannot prove that keeps the files and |
| // says so (statusGenUnproven). |
| + startAt := time.Now() |
| if out, err := s.Systemctl(ctx, "start", unit); err != nil { |
| s.abandonGen(ctx, w, req.host, unit, "start: "+strings.TrimSpace(out+" "+err.Error())) |
| return |
| @@ -177,7 +210,8 @@ 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", req.host, unit, req.tier.MemoryMax) |
| + 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)) |
| writeJSON(w, http.StatusOK, StartResponse{InvocationID: strings.TrimSpace(inv)}) |
| } |
diff --git a/internal/instancectl/server_gen_test.go b/internal/instancectl/server_gen_test.go| index 3ec774378..6f2f61937 100644 |
| --- a/internal/instancectl/server_gen_test.go |
| +++ b/internal/instancectl/server_gen_test.go |
| @@ -19,6 +19,9 @@ const genHost = "bill-2.example.com" |
| var genUnit = GenUnitName(genHost, 7) |
| +// genTierShow is systemd's answer for the default tier's memory lines. |
| +const genTierShow = "MemoryMax=536870912\nMemoryHigh=483183819\nMemorySwapMax=536870912\n" |
| + |
| func genServer(t *testing.T, ctl *fakeCtl) (*Server, string, string) { |
| t.Helper() |
| dropins, exe := t.TempDir(), t.TempDir() |
| @@ -28,11 +31,11 @@ func genServer(t *testing.T, ctl *fakeCtl) (*Server, string, string) { |
| func genCtl() *fakeCtl { |
| return &fakeCtl{answers: map[string]string{ |
| - "show -p Slice --value": SliceName(genHost) + "\n", |
| - "show -p InvocationID --value": "abc123\n", |
| - "list-units": "", |
| - "list-jobs": "", |
| - "show -p ActiveState --value": "inactive\n", |
| + "show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax": "Slice=" + SliceName(genHost) + "\nNeedDaemonReload=no\n" + genTierShow, |
| + "show -p InvocationID --value": "abc123\n", |
| + "list-units": "", |
| + "list-jobs": "", |
| + "show -p ActiveState --value": "inactive\n", |
| }} |
| } |
| @@ -54,7 +57,9 @@ MemorySwapMax=536870912 |
| } |
| } |
| -func TestGenStartWritesTheDropInReloadsChecksTheSliceThenStarts(t *testing.T) { |
| +// The wake path's case: a generation's unit is new, so systemd reads its |
| +// drop-in on the first reference and the box-wide reload is skipped. |
| +func TestGenStartWritesTheDropInChecksItThenStartsWithoutAReload(t *testing.T) { |
| ctl := genCtl() |
| s, sock, dropins := genServer(t, ctl) |
| inv, err := NewClient(sock).StartGen(context.Background(), genHost, 7, cgroup.TierDefault.MemoryMax) |
| @@ -69,8 +74,7 @@ func TestGenStartWritesTheDropInReloadsChecksTheSliceThenStarts(t *testing.T) { |
| t.Fatalf("exe app link = %q, %v", target, err) |
| } |
| want := strings.Join([]string{ |
| - "daemon-reload", |
| - "show -p Slice --value " + genUnit, |
| + "show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax " + genUnit, |
| `set-property --runtime carlos-instances-bill\x2d2.example.com.slice MemoryMax=536870912 MemoryHigh=483183819 MemorySwapMax=536870912 CPUWeight=100 CPUQuota=100% IOWeight=100`, |
| "start " + genUnit, |
| "show -p InvocationID --value " + genUnit, |
| @@ -80,6 +84,78 @@ func TestGenStartWritesTheDropInReloadsChecksTheSliceThenStarts(t *testing.T) { |
| } |
| } |
| +// staleUntilReload makes systemd hold a stale copy of the unit (answer) |
| +// until a daemon-reload, after which the drop-in reads as applied. |
| +func staleUntilReload(ctl *fakeCtl, answer string) { |
| + ctl.answers["show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax"] = answer |
| + ctl.before = map[string]func(){"daemon-reload": func() { |
| + ctl.mu.Lock() |
| + defer ctl.mu.Unlock() |
| + ctl.answers["show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax"] = "Slice=" + SliceName(genHost) + "\nNeedDaemonReload=no\n" + genTierShow |
| + }} |
| +} |
| + |
| +// systemd still holding the unit loaded from older files says so with |
| +// NeedDaemonReload, or shows a slice the drop-in does not name. Either way |
| +// the start reloads, checks again, and only then starts. |
| +func TestGenStartReloadsWhenSystemdHoldsAStaleCopy(t *testing.T) { |
| + for name, answer := range map[string]string{ |
| + "files changed since load": "Slice=" + SliceName(genHost) + "\nNeedDaemonReload=yes\n" + genTierShow, |
| + "loaded without drop-in": `Slice=system-carlos\x2dinstance\x2dgen.slice` + "\nNeedDaemonReload=no\n" + genTierShow, |
| + "show failed to answer": "", |
| + } { |
| + t.Run(name, func(t *testing.T) { |
| + ctl := genCtl() |
| + staleUntilReload(ctl, answer) |
| + _, sock, _ := genServer(t, ctl) |
| + if _, err := NewClient(sock).StartGen(context.Background(), genHost, 7, cgroup.TierDefault.MemoryMax); err != nil { |
| + t.Fatal(err) |
| + } |
| + want := strings.Join([]string{ |
| + "show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax " + genUnit, |
| + "daemon-reload", |
| + "show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax " + genUnit, |
| + }, "\n") |
| + if got := ctl.joined(); !strings.HasPrefix(got, want+"\n") || !strings.Contains(got, "\nstart "+genUnit) { |
| + t.Errorf("calls =\n%s\nwant them to begin\n%s\nand then start", got, want) |
| + } |
| + }) |
| + } |
| +} |
| + |
| +// systemd's change check is by mtime, so a reused generation still loaded |
| +// with an older tier, whose rewritten drop-in is not newer (a clock that |
| +// went back), reads NeedDaemonReload=no. The drop-in's other lines follow |
| +// from the unit's name; its memory lines are checked against the tier. |
| +func TestGenStartReloadsWhenSystemdHoldsAnotherTier(t *testing.T) { |
| + ctl := genCtl() |
| + staleUntilReload(ctl, "Slice="+SliceName(genHost)+"\nNeedDaemonReload=no\nMemoryMax=1073741824\nMemoryHigh=966367641\nMemorySwapMax=1073741824\n") |
| + _, sock, _ := genServer(t, ctl) |
| + if _, err := NewClient(sock).StartGen(context.Background(), genHost, 7, cgroup.TierDefault.MemoryMax); err != nil { |
| + t.Fatal(err) |
| + } |
| + if got := ctl.joined(); !strings.Contains(got, "daemon-reload\n") { |
| + t.Errorf("started on systemd's stale tier without a reload:\n%s", got) |
| + } |
| +} |
| + |
| +// A reload that leaves systemd still saying its files changed proves |
| +// nothing about what it loaded: refuse rather than start on a guess. |
| +func TestGenStartRefusesWhenTheReloadDidNotSettle(t *testing.T) { |
| + ctl := genCtl() |
| + ctl.answers["show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax"] = "Slice=" + SliceName(genHost) + "\nNeedDaemonReload=yes\n" + genTierShow |
| + s, sock, dropins := genServer(t, ctl) |
| + if _, err := NewClient(sock).StartGen(context.Background(), genHost, 7, cgroup.TierDefault.MemoryMax); err == nil { |
| + t.Fatal("started a generation systemd still held a stale copy of") |
| + } |
| + if strings.Contains(ctl.joined(), "start "+genUnit) { |
| + t.Errorf("the unit was started:\n%s", ctl.joined()) |
| + } |
| + if dropIn, exe := genFilesPresent(t, s, dropins); dropIn || exe { |
| + t.Errorf("files left behind: drop-in %v exe %v", dropIn, exe) |
| + } |
| +} |
| + |
| // A successor's start during an overlap: the slice holds the incumbent, |
| // and its raised limit is the swap's. The start leaves it alone. |
| func TestGenStartLeavesAPopulatedSliceAlone(t *testing.T) { |
| @@ -123,7 +199,7 @@ func TestGenStartResetsAnEmptySlice(t *testing.T) { |
| // and an empty /data. Refuse, and leave nothing behind. |
| func TestGenStartRefusesWhenTheDropInDidNotApply(t *testing.T) { |
| ctl := genCtl() |
| - ctl.answers["show -p Slice --value"] = `system-carlos\x2dinstance\x2dgen.slice` + "\n" |
| + ctl.answers["show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax"] = `Slice=system-carlos\x2dinstance\x2dgen.slice` + "\nNeedDaemonReload=no\n" + genTierShow |
| s, sock, dropins := genServer(t, ctl) |
| if _, err := NewClient(sock).StartGen(context.Background(), genHost, 7, cgroup.TierDefault.MemoryMax); err == nil { |
| t.Fatal("started a generation whose drop-in did not apply") |
| @@ -388,6 +464,7 @@ func TestGenStartDropInWriteFailureRemovesTheFiles(t *testing.T) { |
| func TestGenStartDaemonReloadFailureRemovesTheFiles(t *testing.T) { |
| ctl := genCtl() |
| + ctl.answers["show -p Slice,NeedDaemonReload,MemoryMax,MemoryHigh,MemorySwapMax"] = "Slice=" + SliceName(genHost) + "\nNeedDaemonReload=yes\n" + genTierShow |
| ctl.fail = map[string]error{"daemon-reload": errors.New("bus gone")} |
| s, sock, dropins := genServer(t, ctl) |
| _, err := NewClient(sock).StartGen(context.Background(), genHost, 7, cgroup.TierDefault.MemoryMax) |
diff --git a/internal/provision/plan14_root_reads_test.go b/internal/provision/plan14_root_reads_test.go| index f74e754c9..fc34b82d5 100644 |
| --- a/internal/provision/plan14_root_reads_test.go |
| +++ b/internal/provision/plan14_root_reads_test.go |
| @@ -1441,6 +1441,21 @@ func TestPlan14RootReadCensus(t *testing.T) { |
| t.Fatal(err) |
| } |
| seal = "79cb56b4c7d3a8e155d1eff1902715d818fcf4c09b1d8a82921c413b116938a9" |
| + // Census overlay wake-latency-1 (wake latency pass 1), loaded last, |
| + // after db-region-forward-3. census-ruling-wake-latency-1, accepted as |
| + // proposed by the census owner on #280, 2026-10-24 |
| + // (docs/superpowers/notes/census-proposal-wake-latency-1.md). doWake, |
| + // wake and startUnitAt are re-frozen with per-step wake timing appended: |
| + // clock reads and journal lines, no read added. The internal/activator |
| + // and internal/instancectl envelopes are re-pinned. Frozen declarations |
| + // are added, so the seal moves; db-region-forward-3's is checked first. |
| + if errs := checkRootReadLegacy(inv, seal); len(errs) != 0 { |
| + t.Fatal(errs) |
| + } |
| + if err = loadRootReadInventory(filepath.Join(root, "internal/provision/testdata/plan14-root-reads-wake-latency-1.tsv"), &inv, true); err != nil { |
| + t.Fatal(err) |
| + } |
| + seal = "09e20ea4bbc534710334e632e903878656dabfb5817d4d96c6e7c56508172148" |
| errs := append(compareRootReads(got, inv), checkRootReadLegacy(inv, seal)...) |
| errs = append(errs, checkRootReadDeclarations(got, inv)...) |
| if len(errs) > 0 { |
diff --git a/internal/provision/testdata/plan14-root-reads-wake-latency-1.tsv b/internal/provision/testdata/plan14-root-reads-wake-latency-1.tsv| new file mode 100644 |
| index 000000000..d03f7208f |
| --- /dev/null |
| +++ b/internal/provision/testdata/plan14-root-reads-wake-latency-1.tsv |
| @@ -0,0 +1,10 @@ |
| +# Census overlay wake-latency-1 (wake latency pass 1: a generation starts without a box-wide daemon-reload when systemd already reads its drop-in; health probes back off from 5 ms; per-step wake timing in the journal), loaded LAST in TestPlan14RootReadCensus, after db-region-forward-3, the overlay main loads last at 64a002c8. census-ruling-wake-latency-1, accepted as proposed by the census owner on #280, 2026-10-24 (docs/superpowers/notes/census-proposal-wake-latency-1.md). |
| +# Service.doWake, Service.wake and ExecBackend.startUnitAt are re-frozen at their accepted dispositions with the timing appended: clock reads and journal lines only, no read added, removed or reordered. Frozen declarations are added, so the seal moves; db-region-forward-3's is checked first. Envelopes internal/activator (the timing, the health backoff) and internal/instancectl (startGen's drop-in check) are re-pinned. |
| +@legacy 9e3f18aa71907fbaa1bd94c6d420cceac6c3b5f809915a0ba86bc231d729b212 internal/activator/activator.go Service.doWake legacy accepted-legacy accepted-legacy;rev3=census-ruling-292fix;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): main's body (census ruling 292's legacy start mark and lease give-back; census ruling owed's pending record) with the seeded change ruled under census-ruling-seeded-instances (the refreshed row checked against the row the wake began from, twice; the seed's first upload recorded after the wake), and now one more line on a failed start: a start its pre-exec gate refused (launchNotStarted: the exec gate, the pending record or its recheck answered no before root was asked) is recorded as known not started (stopObservation.notStarted) instead of uncertain, only when the wake has started nothing else (wakeStartedNothing); otherwise it goes through cleanupFailedWake and its proofs. A refusal before its lease (step 1), which has started nothing, is recorded the same way. Read sites unchanged; no new read and no root decision;rev3=census-ruling-wake-latency-1;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=marks the end of each wake step on the woken instance's journal timer (wakeSteps: a.now() and a slice append, journal only); no read added, no step reordered registry:DBPath@1300,registry:DBPath@1316,registry:DBPath@1443,registry:DBPath@1454,registry:DBPath@22081,registry:Host@1129,registry:Host@1204,registry:Host@1282,registry:Host@1434,registry:Host@174,registry:Host@1768,registry:Host@2628,registry:Host@4603,registry:Replication@22116,registry:Seed@12122,registry:Socket@1329,registry:Socket@1345,registry:Socket@1468,registry:Socket@1479,whole:Route@10056,whole:Route@10248,whole:Route@10938,whole:Route@12223,whole:Route@1227,whole:Route@12294,whole:Route@14710,whole:Route@159,whole:Route@16568,whole:Route@1663,whole:Route@1668,whole:Route@17214,whole:Route@1722,whole:Route@1728,whole:Route@1794,whole:Route@1802,whole:Route@18521,whole:Route@18675,whole:Route@19031,whole:Route@19125,whole:Route@19841,whole:Route@20496,whole:Route@21495,whole:Route@21677,whole:Route@22190,whole:Route@22549,whole:Route@23521,whole:Route@23616,whole:Route@2518,whole:Route@3972,whole:Route@4231,whole:Route@4493,whole:Route@4498,whole:Route@4555,whole:Route@4561,whole:Route@4630,whole:Route@4638,whole:Route@5426,whole:Route@6494,whole:Route@7559,whole:Route@8440 28b4040841dc7824fd2f2bf259446d17ea66ca2932b67521b38d337c55fd50a8 |
| +@legacy 7377249f1ac50bddc95e84c96bf641513f8bbfd489731d6b4ad627d4e9b8d098 internal/activator/activator.go Service.wake 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; the stop now carries its reason for a run it interrupts (beginStopLocked's why argument); read sites unchanged, offsets moved;rev3=census-ruling-wake-latency-1;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=logs that timer's breakdown to the journal after a successful wake (w.steps.String(), e.host, w.wakeTook); no read added registry:Socket@6955,registry:Socket@7116,whole:Route@2091,whole:Route@2148,whole:Route@5492,whole:Route@6908,whole:Route@6957,whole:Route@7118,whole:Route@8441,whole:Route@8462 bce391d35720996a8c650b24f350959f7294171f76071bd0037ac801124e3d9a |
| +@legacy fa32fa2f7102b48f474e81a5d426d5025ba77eb5a0612bdc7f7ef4f14a946d4f internal/activator/backend_exec.go ExecBackend.startUnitAt legacy accepted-legacy accepted-legacy;rev3=J1;basis=root-route;rev3=census-ruling-wake-latency-1;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=times the unit's launch and its health wait with time.Now() and logs both, with rt.Host and the unit name, after a successful health wait (the new registry:Host site); no read added, no behaviour changed registry:Host@1384,registry:Host@2097,registry:Host@2136,whole:Route@2265,whole:Route@231 4ea2538e564e29f9ea7ba935775fbeef8cb602d7f0d00ad04bef84792d3b2803 |
| +internal/activator/activator.go Service.doWake legacy accepted-legacy accepted-legacy;rev3=census-ruling-292fix;basis=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos): main's body (census ruling 292's legacy start mark and lease give-back; census ruling owed's pending record) with the seeded change ruled under census-ruling-seeded-instances (the refreshed row checked against the row the wake began from, twice; the seed's first upload recorded after the wake), and now one more line on a failed start: a start its pre-exec gate refused (launchNotStarted: the exec gate, the pending record or its recheck answered no before root was asked) is recorded as known not started (stopObservation.notStarted) instead of uncertain, only when the wake has started nothing else (wakeStartedNothing); otherwise it goes through cleanupFailedWake and its proofs. A refusal before its lease (step 1), which has started nothing, is recorded the same way. Read sites unchanged; no new read and no root decision;rev3=census-ruling-wake-latency-1;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=marks the end of each wake step on the woken instance's journal timer (wakeSteps: a.now() and a slice append, journal only); no read added, no step reordered registry:DBPath@1300,registry:DBPath@1316,registry:DBPath@1443,registry:DBPath@1454,registry:DBPath@22081,registry:Host@1129,registry:Host@1204,registry:Host@1282,registry:Host@1434,registry:Host@174,registry:Host@1768,registry:Host@2628,registry:Host@4603,registry:Replication@22116,registry:Seed@12122,registry:Socket@1329,registry:Socket@1345,registry:Socket@1468,registry:Socket@1479,whole:Route@10056,whole:Route@10248,whole:Route@10938,whole:Route@12223,whole:Route@1227,whole:Route@12294,whole:Route@14710,whole:Route@159,whole:Route@16568,whole:Route@1663,whole:Route@1668,whole:Route@17214,whole:Route@1722,whole:Route@1728,whole:Route@1794,whole:Route@1802,whole:Route@18521,whole:Route@18675,whole:Route@19031,whole:Route@19125,whole:Route@19841,whole:Route@20496,whole:Route@21495,whole:Route@21677,whole:Route@22190,whole:Route@22549,whole:Route@23521,whole:Route@23616,whole:Route@2518,whole:Route@3972,whole:Route@4231,whole:Route@4493,whole:Route@4498,whole:Route@4555,whole:Route@4561,whole:Route@4630,whole:Route@4638,whole:Route@5426,whole:Route@6494,whole:Route@7559,whole:Route@8440 28b4040841dc7824fd2f2bf259446d17ea66ca2932b67521b38d337c55fd50a8 |
| +internal/activator/activator.go Service.wake 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; the stop now carries its reason for a run it interrupts (beginStopLocked's why argument); read sites unchanged, offsets moved;rev3=census-ruling-wake-latency-1;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=logs that timer's breakdown to the journal after a successful wake (w.steps.String(), e.host, w.wakeTook); no read added registry:Socket@6955,registry:Socket@7116,whole:Route@2091,whole:Route@2148,whole:Route@5492,whole:Route@6908,whole:Route@6957,whole:Route@7118,whole:Route@8441,whole:Route@8462 bce391d35720996a8c650b24f350959f7294171f76071bd0037ac801124e3d9a |
| +internal/activator/backend_exec.go ExecBackend.startUnitAt legacy accepted-legacy accepted-legacy;rev3=J1;basis=root-route;rev3=census-ruling-wake-latency-1;identity=the agent (/opt/carlos/carlos agent, carlos-edge.service, user carlos);basis=times the unit's launch and its health wait with time.Now() and logs both, with rt.Host and the unit name, after a successful health wait (the new registry:Host site); no read added, no behaviour changed registry:Host@1384,registry:Host@2097,registry:Host@2136,whole:Route@2265,whole:Route@231 4ea2538e564e29f9ea7ba935775fbeef8cb602d7f0d00ad04bef84792d3b2803 |
| +@coverage internal/activator cd29cfafc2b10f03be81bec326b082219b615d25512d02bf941ae35e56483f52 |
| +@coverage internal/instancectl f0e91529abcdeb4ead7761ac3017c5ff75a0d809f5b09ea25c9681535fa88d6c |