Files
yoi/docs/report/2026-10-12-t748-suite-diagnosis.md

445 lines
28 KiB
Markdown

# T-748: default-parallel suite failure diagnosis
## Sources and preserved observations
- Original local candidate: `61533fadb6b39465af60cb55aed2b4d0650319cd`.
- Comparison source: `56795fb92cb9def9bcd701bd51d92e99526f8eff` (develop/T742).
- Same implementation branch: `work/T-748-bounded-db-execution`.
- The original `target/t748-server-tests.log` remains untouched. Its 97 FAILED
lines and 600-second timeout were symptoms, not proof of one cause.
- Initial diagnosis used `cargo test -p yoi-workspace-server -- --nocapture`,
default libtest parallelism, without changing queue limits, features, or startup
settings. `target/t748-diagnostic-environment.txt` records the environment;
this host reports 24 available CPUs. Diagnostic captures were bounded to
90/150 seconds to obtain errors before the original timeout, not counted as
successful full-suite runs.
Logs under `target/` are local diagnostic artifacts, not tracked review inputs.
This report records their meaning and the permanent regressions that reproduce it.
## 1. Different fixtures consumed one global Host admission budget
The first non-intentional errors in `target/t748-server-nocapture.log` were
`DbCapacityExceeded` in manual Worker setup (`server.rs` at the then-current
line 50614), followed by assignment fixture construction (52990/53045) and
HTTP 503 responses. The deliberate before/after-commit executor panic tests
are different: those passed and verified unknown-outcome diagnostics.
Temporary submit/start/cleanup instrumentation recorded submitting test names,
closure types, actual job IDs and the execution-owner identity. It showed a
single Host lane with `max=18`, with accepted jobs from unrelated fixtures.
A rejection snapshot contained `{32,45,46,...,61}`. The complete diagnostic
capture later contained cleanup for every submitted Host job on that owner;
it did not show permanently abandoned accepted Host jobs. Instrumentation was
removed before the source was committed/published.
`target/t748-live-process-18.txt` sampled the test process and threads at the
actual rejection. That sample had 126 threads; the Host workers were runnable,
and the process was using approximately 17 CPU cores. There was no captured
thread-creation EAGAIN/unavailable error. This evidence does not establish an
OS thread/CPU hard limit as the cause. No test processes remained after the
bounded diagnostic run or the completed suite.
A representative failure passed alone (0.56 seconds); the eight logging cases
passed with four test threads (2.46 seconds). The isolated comparison source's
full default-parallel suite passed: 931 library tests, one pre-existing ignored
migration fixture, 11 binary tests; library duration 168.74 seconds. This did
not prove that all new failures were capacity-related, but did distinguish the
new shared-admission rejection from an observed baseline failure.
### Ownership fix (`f3d4aba5`)
Production budgets remain shared and finite: DB 1 worker/32 queued, Host 2/16,
cleanup 2/16. Ordinary fixtures now explicitly own a finite DB executor and lazy
Host/cleanup owners at those same limits. API clones, child Workspace APIs, and
weak retention adapters use their injected owner. No global fixture lane cache,
parallelism reduction, unlimited queue, or capacity-wait retry was added.
The permanent saturated-Host regression fills both running slots and all 16
queued slots, cancels waiters, advances paused Tokio time, and still observes
rejection until actual completion. Another fixture and the separate cleanup lane
can progress; draining restores the original budget and completes exactly 18
accepted jobs. Existing real-SQLite cancellation/lease/drain tests remain active.
## 2. SQL offload invalidated fixture assumptions about first poll and publication
After Host isolation the default-parallel suite finished in 171.57 seconds:
954 passed, three failed, one existing ignored. Actual errors were:
- removal subscriber saw a legitimate queued Runtime stop Upsert before Removed;
- external session-open expiry exceeded its one-second bound while its DB lane
was still shared across other fixtures;
- grant replacement returned success because one initial poll had only submitted
the offloaded authority read, not reached the held original-grant lock.
The ordinary DB fixtures were isolated too. The one-second expiry assertion was
not increased. Grant testing now drains its actual authority read then polls the
saved response to reach the held lock before replacing the grant. Removal testing
observes the committed stopped projection before taking the removal baseline.
The Removed payload assertion is unchanged. These are observable synchronization,
not sleeps or retries. Focused expiry, grant, and removal tests all passed.
A captured cleanup job also attempted to poll a Tokio timer after its fixture
runtime had shut down. The terminal checker fixture now retains that original
runtime through accepted Host and cleanup jobs, then stops projection producers
and drains actual DB work before ending. Terminal SQL state is not treated as
actual cleanup completion. The subsequent full run contained only the three
intentional executor panic diagnostics, not the shutdown-context panic.
The synchronization/teardown changes are in `df9d056d`.
## 3. Restore intent's DEFERRED read-to-write upgrade returned SQLite BUSY
The next default-parallel run finished in 171.48 seconds with 956 passed, two
failed, one existing ignored. Both failures were SQLite `DatabaseBusy`, extended
code 5, not capacity rejection:
- production-profile zero-input Orchestrator restore;
- pending manual Worker claim restore reconciliation (500 instead of 409).
Both failed alone too. `target/t748-busy-origin.log` captured the error and a
backtrace through `pin_internal_worker_restore_intent` -> the transaction helper
-> internal restore -> manual claim. The journal read authority first in a
DEFERRED transaction while the offloaded projection's other SQLite connection
could write. Such an upgrade can return BUSY without invoking SQLite's busy
handler; treating this as a retryable whole mutation would be incorrect.
A new real-SQLite regression holds an IMMEDIATE writer on another connection,
registers an owned per-connection busy observer, and attempts one journal pin.
The old helper fails deterministically with BUSY/5 before waiting for ownership
(`target/t748-deferred-upgrade-red.log`, 0.23 seconds). The fixed helper waits
before its first authority read, while a current-thread timer and control task
progress. After releasing the writer it persists exactly one requested tuple;
there is no application-level mutation retry.
`f597f1b5` makes this existing mutation helper explicitly
`with_immediate_transaction`. Restore journal and deletion authority reads,
mutation and commit remain in one transaction. Focused DB/HTTP tests (8), the
original restore and claim cases, and deletion tests (13) passed.
## 4. Why a pre-dispatch failure could become the 600-second suite timeout
The original long-running logging case joined an HTTP request with a fake provider
waiting for command dispatch. On pre-dispatch rejection the HTTP future can finish
with 503 while the receiver remains Pending: its channel is still owned by the
fixture, but no command will arrive. An unbounded `join!` waits forever in that
state and hides the actual error behind the outer suite timeout.
The permanent `saturated_host_before_command_start_returns_availability_without_a_provider_operation`
regression uses the real signed HTTP route with a controlled full Host budget. It
observes the final 503/`db_capacity_exceeded` response and the still-live Pending
provider receiver, with no process or command dispatch. The original logging
fixture now asserts an early HTTP response before waiting for both branches, so
an unexpected rejection reports its body immediately rather than hanging. This
reproduces the causal timeout mechanism; the old log itself has no stack trace
from the hung provider future.
The nine logging cases pass together at default parallelism (`49bfbfb2`).
## Artifact/source isolation during comparison
Initially the archived baseline used the existing Cargo target directory. That
replaced a same-package artifact/fingerprint; one later post-fix representative
command ran the baseline's 932-test binary (and `db_executor --list` had no tests).
That result was rejected as candidate evidence. All later candidate checks/tests
use `--target-dir target/t748-candidate-build`, separate from the baseline cache.
This changes artifact location, not test parallelism, features or admission policy.
The fresh candidate build listed the expected executor tests and total test count.
## Validation and remaining composition boundary
Pre-review code source `49bfbfb2` passed the full default-parallel Server suite,
including the command-overload case: 960 passed, zero failures, one existing
ignored migration fixture; 11 binary tests, library duration 175.29 seconds.
The only captured panics were the three deliberate unknown-outcome tests.
Root `cargo check` compile closure passed (including TUI/Server), as did Workdir
default (153 tests) and `http-client` (156 tests) full suites, format/diff checks
and state-contract names (558 matches, zero unapproved, zero stale exceptions).
These commands used the isolated candidate artifact directory; libtest default
parallelism and the production budgets were unchanged. The MR records the exact
published source, which also includes this report and the boundary document.
## Post-publication independent review and causal fixes
MR `01a12d3f-e90c-7b02-9ed9-cf3bd2e822a1` seq3 independently reviewed published
source `66bb9d0b` and requested changes despite the successful original suite.
Its two major findings exposed boundaries the earlier tests did not prove:
- `T748-DB-NETWORK-LANE`: mixed Subjektiv helpers could wait for synchronous
Runtime HTTP on the sole DB worker. Fix `d3fcfb29` places session read/search,
subject projection, memory staging, and legacy consolidation-scope helpers on
the existing finite Host owner; pure DB-resident operations keep DB placement.
Whole transaction helpers remain intact, and no Runtime I/O is introduced
inside a SQL transaction.
- `T748-ASYNC-PROTOCOL-SIGNING`: cold protocol source lookup called live binding
checks and signing directly on Tokio. Fix `c0223a0d` awaits the owned DB stage.
The source API now propagates failure explicitly: an invalid live binding or
signing/admission failure cannot be hidden as `None` or a legacy bearer fallback.
Permanent real loopback HTTP regressions hold upstream Runtime replies during
session read/search, subject and legacy-scope requests, while independently
observing SQL, timer and control progress. Cancelling waiters retains the actual
Host lifecycle lease until completion. Cold protocol source tests control another
SQLite writer and shared connection mutex wait, and verify bounded overload,
fresh signing and revocation without fallback. Existing queue/cancellation and
deletion evidence now observes the actual mutation owner; the mixed fixtures
explicitly inject a small finite Host budget. Production budgets are unchanged.
Focused boundary tests passed (10). Restoring the old placement produced a
failing regression, and fixed placement passed; an earlier syntax-rejected
instrumentation attempt is excluded from evidence. Diagnostic artifacts under
`target/` are not production source or replacement domain implementations.
Exact code source `c0223a0d` then passed root `cargo check` and the original
**default-parallel** Server suite: **962 passed, zero failed, one pre-existing
ignored**, 11 binary tests; library duration **173.36 seconds**. Only the three
intentional executor panic diagnostics appeared, with no residual test processes.
Workdir default (153) and `http-client` (156) full suites, format/diff checks and
state-contract naming (558 matching lines, zero unapproved, zero stale) passed.
All used the isolated `target/t748-candidate-build` artifact directory. Logs:
`target/t748-review-fix-{root-check,full-suite,workdir-default,workdir-http,format,names}.log`.
The documentation-only publication `b10b7315` did not change that tested code.
MR seq5 independently confirmed the two old fixes and repeated the checks above,
but requested changes for a new mandatory-callback cycle; see the next section.
## Mandatory callback must be independent of its waiting Host parent
MR seq5 finding `T748-HOST-CALLBACK-CYCLE` traced Host create/restore -> Runtime
bootstrap -> mandatory Session attribution -> the same finite Host lane. Two
waiting parents could consume both workers while successfully admitted callbacks
could not run. Cancelling a waiter correctly retains the actual parent, so it is
not a solution. The Reviewer's compiled executor artifact proved this placement
cycle, not a complete create endpoint/E2E reproduction.
Fix `a2487b57` separates store-only scope discovery into typed Subject, current
Job consolidation and legacy consolidation authority. Session attribution accepts
only Subject authority and executes its whole existing SQL operation on the
independent DB lane. It rejects consolidation roles without calling Runtime.
Mixed read/search, subject projections and allowed legacy consolidation operations
keep their Runtime checks on Host; the previous DB/network fix is not undone.
The same dependency audit identified Subject resident context reads used by
Runtime bootstrap/restore. All Subject-only memory operations use store-only
Subject authority and DB ownership too (resident summary/context, proposal
validation, receipt lookup, explicit staging). Other memory operations retain
Host ownership because legacy authority can require synchronous Runtime lookup.
No transaction is split across an await and no production budget is increased.
The strengthened signed route regression holds both actual production-sized Host
workers (2/16) in `run_host_workflow` parents and retains their create admission
leases until callbacks finish. Resident and attribution routes authenticate real
Runtime source proofs, check current singleton ownership, respond successfully,
and persist both distinct Subject session attributions **before** either parent
releases capacity. It also preserves Session callback reentry during deletion
drain. Runtime's wait is modeled at this policy boundary; no product process or
complete create endpoint is spawned. Separate denial coverage proves legacy
consolidation callbacks return 403 without Runtime lookup, leave no attribution,
and do not bypass authentication (401).
Only Session attribution is an allowed deletion-drain callback; that endpoint
allowlist was not expanded. An initial fixture sent resident reads during deletion
and correctly received 409. The fixture now tests those reads before deletion,
then Session attribution while deletion waits. This is alignment with the existing
fence, not a relaxed product gate or success-picking retry. A diagnostic Python
invocation was unavailable before making any source change; only the subsequent
Deno lane-restoration runs are causal red evidence.
Restoring just Session's old Host placement fails at its expected callback
watchdog; restoring just resident memory's old Host placement fails at its own
watchdog. Fixed placement succeeds without parent bailout. Evidence:
`target/t748-callback-old-{session,resident}-placement-red.log`,
`target/t748-callback-restored-green.log`. Final focused signed callback tests (5),
DB boundaries (10), and Subjektiv regressions (25) passed.
Exact code `a2487b575df1f348251214c53da61595860fcb40` passed root `cargo check` and
original default-parallel Server **963 passed / 0 failed / 1 existing ignored**,
11 binary tests; library duration **173.01 seconds**. Only the three intentional
executor panics appeared, with no residual test processes. Workdir default153 /
http-client156, fmt/diff and naming558/0/0 passed. The isolated candidate cache
remains in use. Logs: `target/t748-callback-{root-check,full-suite,workdir-default,workdir-http}.log`.
The docs-only publication `27b6c688` changed no tested code. MR seq7 independently
confirmed the callback fix and earlier fixes, but identified another direct async
caller; its independent verdict was `request_changes`, not approval.
## Worker discovery and adjacent metadata caller audit
MR seq7 major `T748-ASYNC-WORKER-DISCOVERY` traced async discovery directly into
synchronous `workers_response`. That helper acquires the shared SQL connection
for the Worker projection snapshot, Workdir registry/links and authority projection.
The Reviewer's independently compiled public snapshot helper reproduced a
300.246ms shared-mutex stall while its Tokio timer could not progress. This was
helper-boundary evidence, not an authenticated endpoint/E2E run.
Fix `dbcea6c3` awaits the **whole existing** `workers_response` on the independent
bounded DB owner. Source-proof requirement, Workspace/query/cursor validation,
visibility filtering, pagination and control-grant behavior are unchanged. The
other production callers were traced: Worker list/resource detail already use DB;
mixed Runtime cleanup plans use Host. No network work is added to the DB owner.
The adjacent metadata audit found async `workspace_runtime_resources_response`
also directly calling synchronous Runtime summaries (including remote signed HTTP
and its awaited DB authorization). This call now uses finite Host ownership,
then the existing independent async binding read. Runtime list/detail share this
boundary. Whole SQL helpers, admission budgets and authentication fallback rules
are not changed.
The permanent post-auth discovery handler regression uses a separate SQLite
IMMEDIATE writer and busy observer to hold the actual shared connection mutex.
While the accepted discovery read is queued, current-thread timer and independent
Host control progress. A second read receives 503/`db_capacity_exceeded`; a source
without proof receives 403 before admission. Cancellation retains the actual
queued read's lease/budget until result cleanup; ordinary completion preserves the
empty filtered catalog response. Signed route proof verification remains covered
by the existing dedicated-permission test, separately from this post-auth policy
boundary so middleware's own DB wait cannot hide the handler bug.
Restoring the exact old discovery call fails its first-poll assertion after the
fixture watchdog releases the synchronous mutex wait. Restoring only the old
Runtime-summary placement fails because Tokio cannot observe the real loopback
request until the upstream watchdog releases it. Fixed summary placement lets
SQL/timer/control progress during the held signed upstream request and keeps the
actual Host lease after cancellation. Explicit upstream-release observation
prevents watchdog failure cleanup from masquerading as progress. Logs:
`target/t748-discovery-old-placement-red.log`,
`target/t748-runtime-summary-old-placement-red.log`,
`target/t748-discovery-summary-fixed-boundaries.log` (12 passed),
`target/t748-discovery-summary-policy.log` (4), and callbacks (5).
Exact code `dbcea6c34ba55453ce588d68272df238cde19f47` passed root `cargo check` and
original default-parallel Server **965 passed / 0 failed / 1 existing ignored**,
11 binary tests; library duration **175.00 seconds**. Only three deliberate
executor panics appeared, with no residual test processes. Workdir default153 /
http-client156 and fmt/diff/naming558/0/0 passed. Logs use the same isolated
candidate cache: `target/t748-discovery-summary-{root-check,full-suite,workdir-default,workdir-http}.log`.
Docs-only publication `b63bdb44` changed no tested code. MR seq9 independently
confirmed these fixes, then requested changes for Runtime management's residual
synchronous authority calls; it was not an approval of the complete source.
## Runtime management: authority, network, and accepted publication ownership
Seq9 major `T748-ASYNC-RUNTIME-MANAGEMENT` identified registration's direct
`get_validated` signing identity read and post-ping direct live-binding fence.
The Reviewer reproduced both exact compiled helpers waiting approximately 300ms
on the shared SQL mutex with no Tokio timer progress (helper-boundary, not endpoint
or E2E proof). Registration's synchronous Runtime Worker scan also requires a
network/authority boundary; ping previously used an unbounded blocking admission.
Fix `925bce2a` introduces whole owned DB stages for validated active signing
identity and the post-ping current binding fence. Runtime Worker scans and ping
use existing finite Host admission. A changed/revoked binding still produces
conflict rather than attesting the earlier connection; owner/key/CAS validation
and existing whole store transactions are retained.
The adjacent management audit also closes cancellation separation between SQL
commit and local Runtime publication. Registration and metadata updates now own
mutation, expectations/registry/subscription publication, and response observation
in one accepted Host workflow, with their SQL helper awaited on the independent
DB owner. Public Runtime resource/detail helpers admit ownership; the already-owned
workflows call explicit `_on_host` variants directly instead of reacquiring the
same lane. There is no Runtime/network await inside a SQL transaction or nested
Host admission. A cancelled waiter cannot strand a committed metadata change
without publishing the matching binding.
Launch options were another mixed Runtime summary/config helper placed on sole
DB. Its signed Runtime authorization could enqueue DB work behind its own waiting
parent. It now uses Host, preserving SQL/control progress and finite ownership.
The audit traced remaining signing validation/binding-fence calls: UI signing
operations already use DB, Runtime gate calls occur on Host, and removal already
has an owned Host workflow. DNS validation stays async; pure local registration
construction/notification stays in the accepted publication owner.
Permanent regressions cover both authority stages under a real separate SQLite
IMMEDIATE writer and shared-mutex busy observer: current-thread timer/control
progress, overload503, cancelled actual DB lease retention/cleanup, positive
validation and revoked binding409. An actual signed loopback ping is held while
SQL contention starts; after its reply the real handler's post-ping fence queues
without blocking Tokio or Host control. Another signed loopback scan proves SQL/
timer progress and retained cancelled finite Host admission. The metadata mutation
case cancels while its own SQL is waiting, then observes one durable update and
an equal published binding after actual Host/DB drain. Producers are stopped and
drained while the original fixture runtime remains alive.
Old identity, binding, scan and launch placements each fail their expected
contention/watchdog boundary; fixed code passes. Logs:
`target/t748-management-old-{identity,binding,scan,launch}-placement-red.log`,
`target/t748-management-final-restored-green.log` (16 boundaries), registration
policy11 and connection policy13. A zero-match launch-options exploration is not
counted as proof; its real held-summary case is in the 16 boundaries. The first
fixture teardown named an unavailable method and failed compilation; it was
corrected to the existing `shutdown_async`, not counted as a semantic test run.
Exact code `925bce2a405b6d3255887fba88867ab8d23882dc` passed root `cargo check` and
original default-parallel Server **969 passed / 0 failed / 1 existing ignored**,
11 binary tests; library duration **172.25 seconds**. Only three deliberate
executor panics appeared, with no residual test processes. Workdir default153 /
http-client156, fmt/diff/naming558/0/0 passed. Same isolated cache; evidence logs:
`target/t748-management-{root-check,full-suite,workdir-default,workdir-http}.log`.
Docs-only publication `6d8c49b7` changed no tested code. MR seq11 independently
confirmed those fixes and repeated the full validation, but requested changes for
cancelled trust-key revocation; it did not approve the complete snapshot.
## Trust-key revocation must own post-commit subscription termination
Seq11 major `T748-RUNTIME-REVOKE-CANCEL-PUBLICATION` reproduced the authenticated
public DELETE trust-key route waiting for an actual SQLite writer. Cancelling its
HTTP waiter did not cancel accepted SQL: revoke, binding-ID replacement and audit
committed, but waiter-owned expectation removal and broker unregister were lost.
The independent artifact used the normal public Server library's inner router,
not outer Workspace dispatch or live-stream/E2E. New signed requests still fail
the live binding fence; that does not shut down an already connected subscription.
Fix `1a065db0` gives the whole key-revoke outcome one accepted finite Host owner:
intact CAS/audit SQL on the independent DB lane, local expectation removal, broker
unregister/Shutdown, and response observation. Owner/scope/input preflight, typed
trust conflicts and current-binding error responses remain unchanged. Response
reads use the already-owned `_on_host` detail helper, with no nested Host admission.
Admission/unknown-outcome errors retain the normal typed availability mapping;
there is no transaction split, new queue budget or automatic mutation retry.
The adjacent key-mutation caller audit confirms registration and metadata already
own publication and this is the sole production key-revoke caller.
The permanent cancellation regression exercises the **real outer Workspace
dispatch**, owner browser cookie, generated DELETE route, whole store mutation and
broker. Projection producers stop before the write lock is acquired, so the
fixture-local busy observer identifies this actual revoke transaction, not startup
SQL. Timer/control progress before the watchdog releases SQLite. After waiter
cancellation, the real admitted RequestLease keeps deletion Pending. Releasing the
writer and draining actual Host/DB owners persists exactly one revoke audit,
changes binding ID, removes expectations and broker registration, and delivers
`Closed/ServerShutdown` to the downstream. The loopback endpoint holds a WebSocket
handshake; this proves broker termination, not an established upstream socket or
complete product E2E. Existing broker protocol tests cover socket replacement.
A separate full-Host route regression observes 503 before mutation and unchanged
binding, audit and publication. Restoring only the exact old revoke method fails
both permanent tests: the cancelled job leaves broker registration behind, and
under overload the old handler commits revoke before its response helper returns
503. Fixed code passes both without retry or reduced parallelism. Evidence:
`target/t748-revoke-final-old-publication-red.log`,
`target/t748-revoke-fixed-boundaries.log` (18), `target/t748-revoke-policy.log` (3),
`target/t748-revoke-binding-policy.log` (16).
An initial counter probe outside dispatch was invalid because dispatch replaces it
with the real RequestLease; it was corrected to observe actual deletion drain.
A test-only overload channel type-inference compile rejection was corrected with
an explicit unit channel. Neither setup error is counted as semantic evidence.
Exact code `1a065db0fc5d07e2dcc1b9dac2fcfc0607b9a23c` passed root `cargo check` and
the original default-parallel Server **971 passed / 0 failed / 1 existing ignored**,
11 binary tests; library duration **173.05 seconds**. Only three deliberate executor
panic diagnostics appeared, and no retained test/repro processes were observed.
Workdir default153/http-client156, fmt/diff and naming558/0/0 passed. All Cargo
checks/tests use the isolated candidate cache. Logs:
`target/t748-revoke-{root-check,full-suite,workdir-default,workdir-http,fmt,names}.log`.
Docs-only source `ebce7ab7` changed no tested code. MR seq13 independently confirmed
the revoke ownership fix and repeated the full checks, but requested changes for
Ticket cancellation, selector repair and post-restore projection's async callers.
The current uncommitted follow-up and the requested comprehensive caller audit
are tracked in [the caller inventory](2026-10-12-t748-caller-inventory.md).
Successful suites are not evidence that uninspected caller boundaries are safe.
No latency benchmark, production incident measurement, target integration,
Ticket conclusion, or running-environment update is claimed. T743 has now
published its caller inventory/source; its owner will compose the T748 facade and
new callers, then obtain review of that exact combined source. T748 does not copy
those domain APIs or wait on the former unpublished branch.