test(session-net): investigate protected transition exceeding 100 ms budget

[VerifiedOrganic]

Current scope: independent performance qualification

The separation was merged in #836 at e14650bee4115a3e3fa50dcbd84b280a2e544b63. All 45 hosted functional checks passed on their first attempts, and the merged tree is identical to the tested tree. 54 current-head local gate commands passed, including all five explicit latency profiles. The three 100 ms observations were 6,495 us (core), 6,245 us (native), and 7,317 us (i686); the one-second observations were 670,396 us (core) and 205,253 us (forced-unsupported cfg). The performance workflow is now available on main, using GitHub-hosted ubuntu-latest by default. Performance qualification remains independent of required functional CI. These local observations do not close this issue.

The maintainer approved separating hard latency qualification from required functional CI so runner performance does not block the dependency cleanup. GitHub-hosted ubuntu-latest remains the default; a repository variable can select a different Linux x64 runner when available.

PR #836 keeps the complete real-disk scenario in required functional CI with a ten-second hang guard. A separate explicit performance test preserves the original 100 ms timeout and late-completion assertion, exact-voter prewarm, single physical proposal, capability/quorum counts, durable receipt checks, and cleanup. The one-second selector limit is likewise retained as an independent performance test. Production deadlines and durability are unchanged.

This issue remains open for hosted latency qualification. Splitting the gates resolves CI coupling; it does not establish that current hosted runners consistently meet the limit. The performance workflow runs manually, or on main pushes with OPC_PERFORMANCE_GATES=true, and reports failures normally. OPC_PERFORMANCE_RUNNER can select another runner. Do not infer production latency certification from an individual pass.

The last ungated head 5720f4de1797 finished 43 successful checks, the protected 100 ms timeout, and its dependent Rust aggregate failure. The request took 101,122 us, with all three voters at log index 3 / applied index 2 and no completed handler. Original first-attempt failure; raw log SHA-256 c19a86a681caa4430dd30134d18afbfb74fca826c6d9fa41ff735757bef2d3f9. That historical head is not being merged; the new candidate still requires all functional checks.

Original failures and bounded controls

The existing i686 protected-transition contract exceeded its original 100 ms caller budget in job 104408632655.

• Candidate: 049919c1fe129e2a251faab866235cb41c49de29; base: 987246c8be773b19304f059231c39baa8d54d123.
• Actual checkout: 6504374ce7548e303b6c103e64481e60fdad1e4c.
• Test: stateless_quorum_consumer::protected_consumer_chain_after_activation_elides_outer_capability_wire_calls in crates/opc-session-net/tests/stateless_quorum_consumer.rs.
• Observed elapsed: 119,919 microseconds; the outer timeout returned a completed operation, so the separate wall-clock assertion correctly rejected the late result. Original budget: 100,000 microseconds.
• Diagnostics recorded one physical transition, exactly one prewarm capability call per voter, zero extra read barriers, and all three voters at the next applied proposal. These counters do not attribute the extra elapsed time to a particular operation, resource or scheduler event.
• Raw hosted log SHA-256: 7d40bb20560ca854bfd522827c513cebfc19264e3127f0dd74a1f9c01e52303e.

This lane already gives each timing contract a fresh i686 process, using its original assertions and budget. The test, concrete consumer adapter, protected backend and CI workflow are byte-identical between base and candidate. PR #835 changes the separate snapshot-directory handoff. At initial triage, no test defect or causal implementation regression had been established; the bounded runtime diagnosis below was completed subsequently. A passing unchanged retry would supply current qualification only, not prove a repair.

Required resolution:

• Preserve the original failure and establish a bounded, repeatable cause or explicitly retain the unresolved attribution.
• Keep the original 100 ms budget, explicit late-completion assertion, exact-voter prewarm, single physical transition, no extra capability/read quorum, retained receipt checks and cleanup.
• Any proposed correction needs an intended runtime detector, fix-removal and adversarial controls, then current local and hosted qualification. Do not relax the budget or remove the wall-clock check to obtain a pass.
• Keep this synthetic SDK contract separate from production latency, transport-security or deployment claims.

This is distinct from #821's one-second selector request and #741's two-snapshot throughput qualification. Refs #835.

Native conformance recurrence

The same contract failed on x86_64 in the first IPsec LB conformance job for dependency candidate b6dbabcf1ba670fe6188e7ba0ac86b2876423bd5 (tested merge c722eb0d79b459d84c1356125773b02dcd805d3b, tree 28a53822eab06a75721ffb3e0094ec134f15f555).

• Complete request: 125,621 microseconds; original budget: 100,000 microseconds. The timeout returned success, and the explicit late-completion assertion rejected it.
• One physical transition, exactly one capability call per voter, zero read barriers, and all three voters at applied proposal 3 after proposal 2.
• Raw job-log SHA-256: 5de7f4e9db5cbd77ce870109e86736dcd84f930e0a443d6147017e2cea36972c. No unchanged retry was requested.
• The IPsec workflow omits this case from its isolated timing-contract list, although the core planner and i686 lane isolate it. That mismatch is established; it does not by itself explain the earlier isolated i686 failures.
• This recurrence prompted the fixture-runtime investigation below: the original fixture put the client and all three voters on one current-thread Tokio runtime, where admitted SQLite writes retain inline behavior.

This recurrence prompted the runtime and performance qualification changes in #836. The original deadline, authority, receipt and cleanup requirements above remain in force.

Bounded runtime controls and proposed correction

The test places the caller and all three durable voters in one current-thread Tokio runtime. In that runtime, run_admitted_sqlite_write must execute inline. The SDK runtime uses a multi-thread scheduler, where the existing bounded handoff lets other voters and the caller progress while the original thread retains its SQLite connection, transaction and ownership guards.

A private native diagnostic build on main 62e087536a09260b0e74d4ec056ec84124f5152d retained every real fsync/fdatasync and injected bounded delay only during the original measured request:

Runtime / control	Added delay per sync	Complete request	Result
Original current-thread baseline	0 ms	47,051 us	Passed
Original current-thread	5 ms	88,658 us	Passed
Original current-thread detector	10 ms	130,405 us	Late completion correctly rejected
Multi-thread, one async worker	10 ms	62,475 us	Passed
Runtime correction removed	10 ms	128,433 us	Late completion correctly rejected
Runtime correction restored	10 ms	65,053 us	Passed
Corrected runtime, adversarial delay	50 ms	101,038 us	Original timeout correctly fired

The trace shows the original voters' syncs serialized on one OS thread. The corrected runtime permits independent voter syncs to overlap through the existing bounded handoff. The positive controls retain the physical-call/proposal, capability, quorum, receipt and cleanup assertions. The adversarial timeout does not imply a durable outcome for the interrupted request.

The proposed two-file correction uses multi_thread with one async worker for this fixture, records runtime/completed server duration for future failures, and adds the missing IPsec isolation entry. The private delay/trace hooks are absent from the committed source. The 100 ms timeout and separate late-completion assertion are unchanged.

This demonstrates a bounded causal amplification mechanism. Historical hosted runs did not capture disk/scheduler stages, so the exact attribution of those original elapsed times remains unavailable. This is synthetic SDK contract evidence, not a production deployment latency certification.

Recurrence and follow-up qualification

The first hosted i686 contract run on 4075726034d318c414cb39fff6c7a58deadc2b34 timed out at 101,449 us / 100,000 us, despite the multi-thread runtime. The runtime correction above was insufficient. Original log SHA-256: bbf37b35a64a9e3ab4b77e1b5691dd0e043200d295f9cbf0db2f9d749b1dc01e.

At timeout it recorded one physical call, exactly three capability calls, zero read barriers and no completed server transition. Two voters reported log index 3; all three reported applied index 2. This snapshot does not prove the exact cause or the cancelled request's durable outcome. The workflow was not retried unchanged.

A fresh private i686 build with CI's CARGO_INCREMENTAL=0 started with all voters fully applied. Its ordinary local request took 26,621 us; all nine voter syncs completed with about 1.6 ms combined sync time. CPU plus transport work remained in the unoptimized build. With a bounded 2,500 us CPU quota per 10,000 us period and real disk flushes plus injected delay, the same assertion source produced:

Profile/control	Added delay per voter sync	Complete request	Result
O0, corrected runtime	10 ms	100,601 us	Original timeout
O1, same source	10 ms	67,781 us	Pass
O1 removed	10 ms	101,711 us	Original timeout
O1 restored	10 ms	59,974 us	Pass
O1, adverse disk delay	50 ms	101,101 us	Original timeout

The optimized compiler profile retains debug assertions and overflow checks. Real fsync/fdatasync calls are never bypassed. Every control has its source patch, binary hash, raw log and sync trace retained. Test-only CPU cgroups were removed after exit. The quota is a synthetic resource condition, not a claim about GitHub's CPU allocation; hosted stage timings remain unavailable.

Follow-up 5720f4de1797df1ff274d4b30af04008a6dee145 runs this one contract with the existing O1 profile in core, native IPsec and i686, and keeps the 100 ms timeout and separate late assertion. The one-second selector keeps its ordinary profile. All Rust source is identical to 40757260; private diagnostic hooks are removed. Native/i686/egress local runners also now disable incremental compilation, matching the value hosted caching supplies.

Bounded storage observation

A native workspace-O1 control retained all real disk syncs and every original assertion. With no added delay the request took 6,255 us. Adding 20 ms per voter sync completed at 86,972 us; adding 25 ms hit the original timeout at 100,369 us, with all three log indices at 3, applied indices at 2, and no handler completion. The trace shows four successive sync stages on the critical path. This reproduces the boundary snapshot, but does not establish the unrecorded hosted sync timings.

Diagnostic workflow on separate branch debug/838-hosted-sync-trace-20260916 measures real hosted sync calls with no injected delay. It has three predeclared fresh-fixture observations: immediately after compilation, after draining compiler-filesystem writes, and a second drained observation. Every result is retained and any failure keeps the diagnostic job failed. This is not qualification or a repair, and that branch will not be merged.

The observer passed local workflow lint, planner tests/coverage, Python checks, successful/error syscall controls, and its complete observed workflow. Local observed requests were 6,948, 6,540, and 6,408 us. The product Rust source is unchanged; the measurement-only patch is applied inside the diagnostic job, and all original disk syncs, the 100 ms timeout, late assertion, receipt checks and cleanup remain in place.

The first diagnostic dispatch stopped before building or running tests because shallow checkout omitted the baseline commit needed for exact-source verification. Its raw log is retained (SHA-256 2944bd052719375ffc462b044a118b27777ddc0eee87c5786bc31357f200299c). The corrected diagnostic head f0e64e29 fetches history; the observation script and product source are unchanged. This setup failure contains no latency result.

Hosted storage observation completed

The separate first-attempt diagnostic job completed all three predeclared fresh-fixture samples with the original 100 ms limit and every real sync retained:

Sample	Complete request	Longest sync overlapping the request
Immediately after compilation	45,654 us	38,032 us
After compiler-filesystem drain	96,731 us	50,920 us
Second drained observation	12,944 us	18,060 us (this follower sync finished after the request)

The 96,731 us sample includes a 50,920 us initial voter sync and a later approximately 37,300 us apply-sync wave. Draining compiler writes did not eliminate this observed latency variability. These three passes are diagnostic observations, not a repair or qualification of the earlier failed run. The historical timeout did not record syscall timings, so its exact cause remains unproven. The diagnostic branch will not be merged.

Raw diagnostic job-log SHA-256: aa9afda1e4b1fd7997e7fe00bbaa0dce504c6189e80d2d961a6cfddc8bf59a46. The downloadable workflow artifact retains each sample log, full sync trace, host details, commands, and hashes.

[VerifiedOrganic]

One unchanged confirmation passed in job 104426041830, using the same candidate 049919c1fe129e2a251faab866235cb41c49de29 and tested checkout 6504374ce7548e303b6c103e64481e60fdad1e4c (tree 314b11343bc616cfbd2be5eb1747b91b0c10d66d). All ten exact i686 contract cases passed, including the protected transition with its original 100 ms assertion. No source, test, workflow or deadline changed for the confirmation.

The original 119,919-microsecond failure remains preserved and unexplained. This confirmation provides current qualification only; it does not establish a causal repair or a production latency result. This issue remains open.