mirror of
https://github.com/block/buzz.git
synced 2026-11-01 06:51:17 +00:00
190 lines
13 KiB
Markdown
190 lines
13 KiB
Markdown
# Captured admission failure: owner reconciliation — 54b0
|
||
|
||
## Decision
|
||
|
||
No semantic correction is justified by this trace. **Gate remains OPEN: 111/112,
|
||
223752.938ms natural FULL DEFAULT concurrent installed-enabled run.** Conflicting-ID
|
||
is 2612ms against unchanged `<2500ms`; the separate original 2572ms wrong-authority
|
||
failure remains unresolved. This is not another non-recurrence report.
|
||
|
||
Source inspected at `6697ad804318a6e87c7f6da091f54f13781d2493`. Its diff from the
|
||
executed `36e2eaca0008bad9156cdc53bba67ac7cd9941ab` is only CHECKPOINT and provider
|
||
result documentation. No source/test/deadline/authority change, new timing probe,
|
||
full-suite rerun, install, or provider-scope expansion was made. Offline trace
|
||
arithmetic was checked with Node 24.15.0; pnpm 11.4.0 verified. Existing strict and
|
||
suite results remain attributable to the executed candidate, not new validation.
|
||
|
||
## Exact event association and critical path
|
||
|
||
Raw evidence: workspace `WORK_LOGS/BEEHIVE_DESIGN_183FFAF0/PROVIDER_16B4/`,
|
||
`traces/83342-conflicting-id.json`, 472 rows, zero dropped; full-default.log contains
|
||
the accepted/conflict/accepted receipts and unchanged failed assertion.
|
||
All times below are monotonic milliseconds relative to test.timer.begin. Trace
|
||
owner is Node PID **83342**: test, development relay, host and UI share one event
|
||
loop. Supervisor and fixture runner are external children; their PIDs, CPU and
|
||
syscall timings are not in this trace. Two decode rows are UI then host; the latter
|
||
is immediately followed by host.route. No cross-process clock subtraction is used.
|
||
|
||
- Start and invalid Stop operation: `faa16ef1-ee24-49f0-b231-b0416785c491`.
|
||
Envelope signature prefixes `50b325fc` and `88142874` distinguish them despite
|
||
the shared operation ID (full signatures retained in the raw trace).
|
||
- Start receipt `cb560fb8-039c-4a95-b4e7-631a8a31fc40` (signature `26cf3f89`).
|
||
- Conflict receipt `49d73b26-ca2b-4f67-8936-0ae28d8a78d8` (`0fc11afe`).
|
||
- Valid Stop `88c40dde-9ab0-461c-90c4-6cddec7aa9a1` (`9c77de4b`).
|
||
- Stop receipt `2186daa5-4252-41ba-974d-4cd405b1a35d` (`bbc87557`).
|
||
|
||
| Non-overlapping critical-path section | Start–end ms | Owner/source |
|
||
|---|---:|---|
|
||
| Submit, initial relay backlog, durable batch, reconnect, delivery | 0–153.806 | client.ts:22–39, relay.ts:commit; Start batch durable 147.894 |
|
||
| Start reservation persist | 153.846–261.832 | host.ts:409; storage.ts:6–16 |
|
||
| Preparation/actual construction gap | 261.832–380.300 | host.ts:429–460, prepareLocal:200–222 |
|
||
| Start transitioning persist | 380.300–477.196 | host.ts:460 |
|
||
| Spawn/readiness/continuation gap | 477.196–761.769 | host.ts:461–465, owned.ts:6–30, supervisor.ts:22–30 |
|
||
| Start running/history/receipt commit | 761.769–1344.750 | host.ts:496–513 |
|
||
| Seal/send accepted + inventory, dequeue/seal/send conflict | 1344.754–1349.907 | host.ts:389–400,513; client.ts:send |
|
||
| Relay remaining inventory batch then receipt batch; UI decode | 1349.907–1625.343 | relay.ts:commit, relay-storage.ts |
|
||
| Poll, assert running/revision 1, submit valid Stop | 1625.343–1643.832 | admission-cancel.test.ts:101–113 |
|
||
| Stop relay commit/delivery | 1643.832–1759.741 | durable 1756.775 |
|
||
| Stop reservation + transitioning commits | 1759.765–1915.723 | host.ts:409,501 |
|
||
| Owned Stop | 1915.733–2447.602 | owned.ts:stop; supervisor.ts:10–15 |
|
||
| Stopped/null actual/revision 2/receipt commit | 2447.627–2499.709 | host.ts:501–513 |
|
||
| Seal/send/relay persist/UI decode | 2499.715–2593.462 | receipt batch durable 2592.003 |
|
||
| Poll + stopped assertions + timer | 2593.462–2611.454 | admission-cancel.test.ts:until,113–116,136 |
|
||
|
||
Small gaps between listed intervals are ordinary uninstrumented instructions;
|
||
this is not a claim that every instruction is timed. Specifically, the shared-ID
|
||
Stop is received at 153.781 but queued behind Start until 1348.277. Its handle-to-
|
||
seal is 0.012ms. The legitimate Start is not cancelled because receive's queued-ID
|
||
reservation already belongs to Start (`host.ts:155–166`). This is the intended
|
||
fingerprint/duplicate fence, not an authority bypass to optimize away.
|
||
|
||
Initial reconnect inventory `52ea3937-77e2-4702-88b6-0b036fc3c452` (`2bdea81b`)
|
||
occupies the relay writer from 148.013 until durable 1467.313. The receipt batch
|
||
starts 1467.419, durable 1620.866. Thus conflict publication is held for the tail
|
||
of an already-started FIFO inventory snapshot, then its own snapshot, not a
|
||
second 615ms write after the Start journal. Its own snapshot includes rename
|
||
await 1508.400–1603.977 (95.577ms); this is JS await elapsed, not syscall service.
|
||
|
||
## What the measured journal regions do and do not establish
|
||
|
||
The final Start write lasts **582.982ms**. `storage.ts:6–16` has these exact regions:
|
||
|
||
| Region | Duration ms | Included work |
|
||
|---|---:|---|
|
||
| private.begin → file-sync.begin | 392.744 | trace bookkeeping, mkdirSync recursive/0700, dirname, UUID/temp naming, openSync wx/0600, JSON.stringify, writeFileSync string encoding/write(s) |
|
||
| file-sync.begin → file-sync.end | 19.850 | trace bookkeeping + fsyncSync wrapper |
|
||
| file-sync.end → dir-sync.begin | 152.055 | trace bookkeeping, closeSync(file), renameSync (nonexclusive journal path), dirname/openSync(directory) |
|
||
| dir-sync.begin → dir-sync.end | 18.321 | trace bookkeeping + fsyncSync wrapper |
|
||
| dir-sync.end → private.end | 0.011 | trace bookkeeping + closeSync(directory) |
|
||
|
||
No chmod/lstat permission-check call occurs in this write path; modes are supplied
|
||
to mkdir/open, and actual kernel permission checks are inside filesystem calls.
|
||
The initial exclusive provisioning link/unlink branch is not this terminal write.
|
||
Serialization, encoding, writeFile, open, mkdir, rename and close have no individual
|
||
stamps. CPU execution, GC, descheduling and unknown kernel waits cannot be separated.
|
||
Even the fsync figures are entry-to-return wall wrappers, not CPU or pure device time.
|
||
|
||
Instrumentation (`latency-trace.ts:8–12`) takes Date.now/performance.now, allocates a
|
||
row and pushes it into memory. Inner stamps are nested inside outer intervals:
|
||
do not sum their spans twice. No per-row console/file logging occurs. The only
|
||
trace JSON serialization/write/fsync is endTrace AFTER cleanup and the failed timer.
|
||
The fixture storage hook also pushes a bounded timestamp record and returns a
|
||
promise; its awaits and callback scheduling are not independently measured. No
|
||
measurement bounds the cost of each trace call or proves instrumentation negligible.
|
||
|
||
There is no intervening application callback between private.begin/end. A loop tick
|
||
is 582.785ms late immediately afterward: this proves the shared loop cannot progress
|
||
during synchronous journal work, not why a particular syscall took time. The relay
|
||
file.write await 734.507–1349.964 overlaps the whole terminal write. Its 615.456ms
|
||
cannot be added to 582.982ms or identified as disk time. Relay file.open await
|
||
478.140–734.498 occurs while ticks continue: 256.358ms not accounted for by that
|
||
later blocking region, but still ambiguous worker queue/kernel/callback scheduling.
|
||
|
||
The 118.468ms preparation gap includes local setup validation, access/realpath/stat,
|
||
script reads/hashes and executable reads/hashes, selection cloning and actual-run
|
||
construction. prepareLocal hashes the executable and actual construction reads it
|
||
again; that duplication is visible in source, but no trace assigns its cost or
|
||
justifies caching executable identity across mutation. The 284.572ms readiness gap
|
||
includes supervisor spawn, IPC launch, runner OS spawn notification, continuation,
|
||
cloning run history and receipt construction; it does not await the fixture's
|
||
four-second prompt. Child-side costs are unknown. The 531.869ms Stop includes the
|
||
500ms live-anchor containment timer plus IPC/group-absence polling/reaping/scheduling;
|
||
the excess 31.869ms is not a measured single subsystem delay.
|
||
|
||
## Same-capture comparison, not a counterfactual fix
|
||
|
||
The earlier wrong-authority control in PID 83342 passes in 1711.609 monotonic ms
|
||
(1712 wall). Start handle-to-seal is 431.619ms versus 1190.948ms: **759.329ms**
|
||
difference. Its three journal spans are 76.666/52.645/110.127ms versus
|
||
107.986/96.896/582.982ms. Preparation gap is nearly unchanged,
|
||
119.568 versus 118.468ms; readiness/continuation gap grows 72.588 → 284.572ms.
|
||
The final Start journal difference alone is 472.854ms; readiness difference is
|
||
211.984ms. Owned Stop differs only 3.207ms (528.663 → 531.869).
|
||
This localizes the variation beyond 'contention', but the two controls have different
|
||
rejection owners and do not prove a latency bound under async journal conversion.
|
||
|
||
## Why not patch the fixture or mechanically await persistence?
|
||
|
||
The fixture deliberately waits for accepted Start and conflict evidence before
|
||
valid revision-1 Stop, then verifies stopped/null/revision 2 before timing. The
|
||
same-ID receipt helper aliases the two IDs, but the explicit conflict-result wait
|
||
at line 109 resolves the ambiguity here; both waits complete at 1641.794/1641.841.
|
||
No missing prerequisite/order race caused this failure. Excluding Stop, moving its
|
||
wait outside the bound, or shortening containment would change the asserted journey.
|
||
|
||
Async persistence may improve management responsiveness, but must first preserve:
|
||
|
||
1. **One serialized commit owner and stable snapshots.** Today save is synchronous
|
||
in each queued handler. Merely replacing it with promises permits heartbeat,
|
||
replay and receive to see mutated undurable state. Exact immutable bytes and a
|
||
committed read view must be separated from working state; no concurrent commits.
|
||
2. **Durable before effects/report.** Reserve operation before spawn/kill; preserve
|
||
transitioning crash state; commit receipt/outbox/history before publication.
|
||
Start completion at revision 1 must not be retrospectively erased by a later
|
||
Stop, which has its own revision-2 outcome and immutable prior run history.
|
||
3. **Receive-time cancellation reservations and duplicate/CAS fences.** Receive
|
||
cannot be moved wholly behind the mutation queue: it interrupts in-flight
|
||
admission. Pending commit windows need an explicit linearization rule, especially
|
||
a valid Stop arriving after the final retraction check but before async durability.
|
||
4. **Consumed Move.** host.ts:325–369 consumes source authority plus exact grant
|
||
outbox before sending; target durably accepts assignment before launch checks,
|
||
preserves later candidate edits, and records incoming/outbox replies for replay.
|
||
Async publication cannot resurrect source authority or acknowledge an undurable
|
||
destination. Nested handle(start) must not deadlock its commit owner.
|
||
5. **Failure/uncertainty/close.** save sets persistenceFailed on any failure; handle
|
||
refuses later effects. Queue error quarantine, heartbeat, replay and close are
|
||
additional owners, not just handle's save sites. An async design needs explicit
|
||
pre-replacement failure versus uncertain replacement, visible-state fences and
|
||
close draining before lock release; unknown ownership stays quarantined/locked.
|
||
|
||
These are prerequisites, not claims that current failure paths have been newly
|
||
fully verified. Switching APIs alone cannot remove the sequential journal prerequisite
|
||
from this whole-sequence bound. Reordering the relay's already-started inventory
|
||
snapshot would also change its committed-prefix visibility guarantee.
|
||
|
||
## Next decision and surviving evidence
|
||
|
||
**Do not use another full capture as the next discriminator.** The precise unresolved
|
||
components are the 392.744/152.055ms mixed synchronous subregions and the 284.572ms
|
||
spawn/readiness gap (including the independently outstanding relay open). No existing
|
||
stamp can recover their syscall/CPU decomposition, and a deterministic synthetic
|
||
stall would only prove already-established shared-loop blocking, not that cause.
|
||
No new timing control was spent for that reason.
|
||
|
||
If responsiveness is an independently accepted product requirement, the next work is
|
||
an explicitly scoped host commit-owner design implementing the five invariants above,
|
||
with deterministic held-commit tests for receive/replay/heartbeat/close/failure/Move.
|
||
It must not be sold as a fix for this aggregate wall bound without candidate evidence.
|
||
Otherwise preserve the open gate rather than changing semantics to obtain green.
|
||
No further owner source reread or kernel-permission escalation is needed to reach
|
||
this decision. Provider review and unfinished provider local-add/conversion,
|
||
Databricks token/OAuth, mesh/compute/live acceptance remain separate work.
|
||
|
||
Workspace `ADMISSION_54B0/RECONCILE.ts` and `DECOMPOSITION.txt` reproduce the offline
|
||
six-write partition, counts, PID and zero-drop checks for both captured controls.
|
||
Original traces/full log/source+binary pin records remain untouched in PROVIDER_16B4.
|
||
SHA256: failing trace `c567ac1e2360bf4d3fdd0c8295f0b85ca3ef403a7c8233e6b41e30710e65c285`;
|
||
passing trace `c09c7aed945019c8c904bcb6f1aa7d25c1842c1d50e29fd025d5654b5487b641`;
|
||
full log `0dd8d364cc7ff96fdf01da33ba95a1816439011f7e499f8f83fa4292c91c33d9`.
|
||
Installed binary pins remain in PROVIDER_16B4/final-pins.txt (not source-built here).
|