Skip to content

fix(server): Cue waits up to 1.5 s for a score the moment needs now - #251

Merged
lukemaj merged 5 commits into
mainfrom
fix/248-cue-wait-2s-cutoff
Oct 13, 2026
Merged

lukemaj merged 5 commits into
mainfrom
fix/248-cue-wait-2s-cutoff

Conversation

@lukemaj

@lukemaj lukemaj commented Oct 13, 2026 •

Copy link
Copy Markdown
Contributor

What changed: every ContextMD moment now replies within 1.2 s of reaching the server, authentication included; a Cue wait gets only what that budget leaves.
Why: the first version raised the Cue wait to a fixed 1.5 s, which missed the hook's 2 s cut-off once a failed call's own work (up to about 1 s) was added (Grok review on this PR).
So what: pairs with toolboxmd/contextmd#58 (the hook's 2 s cut-off); the planner runs Sol and Grok on the new head and merges both, then the build is deployed to each machine (rocky's restart through the planner).

Part of #248. Closes #252.

Change

  • ContextmdServing.ts: one budget per moment, MOMENT_BUDGET_MS = 1,200 ms from its arrival.
    • The clock starts before authentication: ContextmdRoute.ts passes the credential check into moment, which runs it first inside the timed work (Sol, round 2). A moment cut before its credential is known serves nothing (204, over_budget); a refused credential still gets 401 and unauthorized.
    • The moment's work (authentication, body read, selection, run join, deny and read checks, Cue) runs under a guard that ends 250 ms before the budget (REPLY_RESERVE_MS). Past it, the moment is cut: 204, logged with the new unserved status over_budget.
    • The reserve covers the decision after the work, plus a timer firing late on a busy event loop (up to 236 ms seen on rocky's Cue collects).
    • The Cue wait (user message, failed call) is whatever the budget still leaves, ending 50 ms before the guard, so a Cue timeout still leaves the moment served. A tool result's collect stays capped at COLLECT_MS (300 ms) and is also bounded by the budget.
  • Select.ts: the event reading (harness, kind including a reported or printed failure, session, call id) is Select.identify, run by select and by serving right after the body parses, before any config or store file is read (Sol round 3).
  • Cue.ts: WAIT_MS removed; score takes the wait from its caller.
  • ServingState.ts: over_budget added to the unserved statuses. An over_budget row carries what the moment had parsed when it was cut: kind, session and tool-use id, recorded as soon as the body parses, plus thread and run once joined; a moment cut before parsing has them null (contextmd serving log: over_budget moments carry no kind, session or tool-call id #252, for contextmd#57's lost-moment count).

How the numbers were picked

  • Outside the server, measured from Grok hook logs (hook elapsed minus server time; includes spawn, connect, queueing, transfer and the settle call), p50/p90/p99 in ms:

    • user_message: 142 / 362 / 591
    • pre_tool: 141 / 500 / 857
    • tool_result: 134 / 469 / 821
  • The server's own work besides the Cue wait, rocky, last 3 days, p50 / p90 / p99 / max in ms:

    • user_message: 106 / 344 / 597 / 861
    • tool_failure: 304 / 594 / 960 / 1486
    • pre_tool: 251 / 525 / 816 / 2391
    • tool_result: 317 / 567 / 874 / 1833

    Pre_tool and tool_result reach 1.8 to 2.4 s even with no Cue wait, so no fixed wait can fit; only a total budget does.

  • The budget: 2,000 ms − 591 ms (user-message p99 outside the server) − 200 ms headroom ≈ 1,200 ms. Pre-tool's outside p99 (857 ms) includes Grok's hook spawn, which is outside curl's own 2 s clock.

  • Typical Cue wait: at the user-message median, about 1,200 − 250 − 50 − 106 ≈ 800 ms.

Proof (head dbecf5d247)

  • New route test (Sol round 3): the exact-key store load is delayed past the budget, so a pre-tool moment is cut inside selection. Its row has kind pre_tool, the session and the call id. On 2cad7749d5 the row had null identity.
  • New route test (contextmd serving log: over_budget moments carry no kind, session or tool-call id #252): a transaction holds the shared database, so a pre-tool moment's run lookup waits past the budget after parsing. It replies 204 within the budget, and its row has kind pre_tool, the session and the call id. A slow-body moment cut before parsing has them null. On the previous head the row had no kind.
  • New route test: authentication answering after 1.3 s, for a credential that may read and one that may not. Each replies 204 within the budget, logged over_budget. On the previous head it failed (1,306 ms).
  • New route test through the real HTTP route: a fake Cue service that never answers. The failed call and the user message each reply, measured by the client, in under MOMENT_BUDGET_MS, logged cue_status timeout. On the old code it failed (1,548 ms).
  • New route test: a request body arriving 2.4 s late is cut within the budget and logged over_budget. On the old code it failed (2,450 ms).
  • The slow-score test now uses a 600 ms score, served (cue_status ok) inside the budget. It was rewritten rather than deleted: the requirement it protects (a slow score that fits is served) now depends on the budget, not a fixed wait.
  • vp test run src/contextmd/: 104 passed. Typecheck 0 errors; lint has no new findings; fmt and Knip clean.
  • contextmd contract suite against this branch: 18 OK.

Not covered

Serving whose state file failed to open still answers 204 to every caller without checking the credential, as before. A synchronous SQLite step that blocks the event loop longer than the budget delays the guard until the step ends. The pre_tool 2.4 s max above may be such a stall. #248's measurement will separate connect time from response time and show whether it happens.

Upstream: fork-only module, no upstream counterpart.

Elon record

Work by Claude Opus 5.5 in Claude Code (Chromeria thread).

🤖 Generated with Claude Code

The serving cut-off is 2 s while Cue is new (user decision 2026-10-13, #248):
the hook now allows 2 s, so the user-message and failed-call wait rises from
650 ms to 1.5 s and still leaves the reply inside it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@github-actions github-actions Bot added size:XS vouch:trusted PR author is trusted by repo permissions or the VOUCHED list. labels Oct 13, 2026
@github-actions

github-actions Bot commented Oct 13, 2026 •

Copy link
Copy Markdown
Contributor

Thread transfer impact

✅ Thread transfer remains within every enforced ceiling.

Provider Metric Main baseline This PR Impact PR ceiling
Codex Total thread wire 5.0 KiB 5.0 KiB 0 B (0.0%) 6.8 KiB ✅
Codex Thread snapshot wire 3.8 KiB 3.8 KiB 0 B (0.0%) 4.9 KiB ✅
Codex Live turn WebSocket wire 1.2 KiB 1.2 KiB 0 B (0.0%) 2.0 KiB ✅
Codex Live turn WebSocket decoded 20.9 KiB 20.9 KiB 0 B (0.0%) 29.3 KiB ✅
Codex Live turn messages 2 2 0 (0.0%) 8 ✅
Claude Total thread wire 5.0 KiB 5.0 KiB −24 B (−0.5%) 6.8 KiB ✅
Claude Thread snapshot wire 3.8 KiB 3.8 KiB 0 B (0.0%) 4.9 KiB ✅
Claude Live turn WebSocket wire 1.2 KiB 1.2 KiB −24 B (−2.0%) 2.0 KiB ✅
Claude Live turn WebSocket decoded 21.2 KiB 21.2 KiB −41 B (−0.2%) 29.3 KiB ✅
Claude Live turn messages 2 1 −1 (−50.0%) 8 ✅

Baseline: a6fc446 · PR result: dbecf5d · Source CI: success

Scenario and decoded snapshot size

10 historical turns, 5 command tools per turn, 878.9 KiB retained MCP result per historical turn, and a 1.05 MiB retained result in the measured turn.

  • Codex decoded thread snapshot: 108.5 KiB
  • Claude decoded thread snapshot: 108.8 KiB

Updated in place by a trusted workflow. PR artifacts are strictly validated and never executed.

@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

What: PASS at c42a9d42ddbfd7a7525637bb50fe7a03c0d17eaa, with no blocking findings.
Why: The 1.5 s Cue wait is below the paired hook/OpenCode 2 s cutoff, and failures still proceed unserved.
So what: Proceed with contextmd#58; keep #248's real timing and post-deploy acceptance open.

  • Traced both user-message and failed-call paths to client.score(req, WAIT_MS). Successful tool results still collect for 300 ms, and pre-tool scoring remains asynchronous. Cue connect is 500 ms, queue deadline 1500 ms, exchange timeout 2000 ms; the exchange can outlive the 1500 ms foreground wait without holding the reply. No earlier overall route timeout was found.
  • ../../node_modules/.bin/vp test run --config review.config.ts (node environment, serial files, src/contextmd/*.test.ts): 99/99 original tests passed. With head tests on base a6fc446646070701577a7b6db4b873bbf32ed55f, 98 pass and the new 1 s Cue route test fails with 204 instead of 200 at the old 650 ms wait.
  • Two additional isolated route checks passed: a failed call receives a 1 s Cue reply, and a Cue service replying at 1.8 s causes timeout fail-open before 2 s. Total with these checks: 101/101.
  • ContextMD Parent threads cannot see a child blocked on an approval #58 full suite against this exact production head: 119/119, including 18 contracts. Existing unreachable-Cue, rejected-call and exact-key fallback tests pass. Exact-head GitHub CI is green.
  • Budget qualification: 1.5 s leaves 0.5 s for the rest of the request; auth/config/projection work has no shared 2 s server deadline. The local route checks establish the tested cases, not an unconditional latency guarantee on long production threads. No live latency or post-deploy claim is made.

Read the complete PR diff and body, linked Issue and all prior PR/Issue comments, including inline review comments. No private data or credentials found in the changes. Testing used only my clones/worktrees under /tmp; no main checkout writes, live Chromeria ports, live database access or restart. Reviewer: independent Sol, medium effort.

@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

What: FAIL at c42a9d42ddbfd7a7525637bb50fe7a03c0d17eaa. One blocking finding.
Why: A 1.5 s Cue wait plus the work already around it does not stay inside the hook's 2 s for a failed call, and it leaves almost no margin on a user message.
So what: Lower that wait, or split it, until both kinds reply inside 2 s. Then this needs a fresh exact-head review.

Blocking: WAIT_MS = 1500 in apps/server/src/contextmd/Cue.ts is the wait for both a user message and a failed call (ContextmdServing.ts, client.score(req, WAIT_MS)). contextmd#58 cuts the client at 2 s, connect included. The PR's budget ("about 140 ms of other work, reply near 1.65 s") does not match the log.

Rocky serving log, read-only, timing columns only, Cue-scored moments since 2026-10-13 16:11Z. server_ms is seconds; cue_wait_ms is milliseconds. Other work is server time minus the wait.

Moment n other work p50 / p90 / max plus a 1500 ms wait
user message 60 242 / 450 / 776 ms p90 about 1.95 s; 2 of 60 over 2 s
failed call 22 523 / 794 / 1486 ms median about 2.02 s; 12 of 22 over 2 s

The 140 ms figure is 792 minus the 650 ms cap. In this window the median user-message wait is 414 ms, so the rest is about 240 ms. Failed calls are slower, and they share this constant. A reply after 2 s never reaches the agent: the hook exits 0. That is the cut this change is meant to stop.

On these rows a shared wait has to stay under about 1.2 s to clear failed-call p90 (about 790 ms of other work) with nothing to spare. 1.5 s does not.

Not the bug, checked at this head:

  • COLLECT_MS stays 300. DEADLINE_MS stays 1500 and is the queue deadline only (contextmd service.py drops a request that waited in queue, then scores). The transport timeout is DEADLINE_MS + 500, and within() returns at WAIT_MS, so the moment does not sit out the extra 500 ms. CONNECT_MS 500 is inside the wait. The route has no timeout.
  • Fail-open holds. The new test at WAIT_MS 650 returns 204, not a hang.

Proof, temp worktree under /tmp:

  • waits long enough for a slow Cue score... passes at this head (1 s score, status 200, under 2 s).
  • The same test with WAIT_MS put back to 650 fails: expected 204 to equal 200.
  • The fixture does almost no transcript work, so the green test does not show that a real moment stays inside 2 s.

No private data in the diff. I did not restart Chromeria or use its ports.

The fixed 1.5 s Cue wait plus the moment's own work missed the hook's 2 s
cut-off on failed calls (Grok review of #251). A moment now has one budget
from its arrival: its work must finish 250 ms before the end or it is cut
and logged over_budget, and a Cue wait takes only what the budget leaves.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@github-actions github-actions Bot added size:M and removed size:XS labels Oct 13, 2026
@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

Grok's finding was right: my 140 ms figure for the other work came from user-message medians only. Failed calls take up to about 1 s on their own, and pre_tool and tool_result occasionally take 1.8 to 2.4 s. Fixed in 65552bf707 with one 1.2 s budget per moment instead of a fixed wait; the numbers and both worst-case tests are in the body.

@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

What: FAIL at 65552bf707bc3241ad709095670cac03d91e5612, with one blocking finding.
Why: Authentication finishes before the new clock starts, so asynchronous authentication delay can still push a moment beyond the hook's 2 s cutoff.
So what: Include authentication in the arrival-based budget and add a delayed-auth regression before another exact-head review.

Blocking: P1, the arrival-based budget excludes authentication

Location: ContextmdRoute.ts:45-47 and ContextmdServing.ts:429.

The route awaits authorized(request) before calling serving.moment; only then does moment capture startedAt. Authentication has no deadline. It calls SessionStore.verify, which reads AuthSessionRepository.getById; the shared SQLite client's single-permit semaphore can wait asynchronously behind a transaction. This is separate from the already disclosed synchronous SQLite/event-loop stall: an interruptible authentication wait also escapes the budget entirely. Authentication failure follows the same unbounded wait before returning 401.

Reproduction on the exact head, only in my /tmp checkout: copied the existing route test into a disposable review file and changed only its successful auth mock to Effect.sleep(1300).pipe(Effect.andThen(originalSuccessfulAuthEffect)). Ran its two new deadline tests through the unchanged real HTTP route. The never-answering Cue failed-call reply took 2,221 ms, returned 200, and failed expected 2221 to be below 1200; the slow-body reply took 2,258 ms, returned 204, and failed the same bound. The event loop remained available during that delay. This is injected dependency latency, not a claim that production authentication currently takes 1.3 s.

The deadline must start at route entry, before authentication, and its remaining time must carry into serving. A timed-out auth must fail open without serving unauthenticated content. Test both successful delayed authentication and delayed authentication failure. Merely qualifying the 1.2 s claim does not fix the reachable 2 s miss.

Verified and limits

  • Read the PR body, both round 1 comments, builder reply and full diff. Exact base is a6fc446646070701577a7b6db4b873bbf32ed55f; round 1 is c42a9d42ddbfd7a7525637bb50fe7a03c0d17eaa. Live PR head still matches the reviewed SHA.
  • Arithmetic is correct: 2000 - 591 - 200 = 1209, rounded down to 1200; work ends at 950 ms, Cue at 900 ms, and the stated user-message median gives 900 - 106 = 794 ms. With 591 ms outside, 1200 ms leaves 209 ms. Source numbers are attributed to the builder's rocky/Grok measurements in the PR body; raw samples, sample counts and the exact measurement window are not supplied there, so I did not independently recompute those percentiles. The 857/821 ms pre-tool/tool-result outside p99s do not independently prove 200 ms headroom; the body says spawn is outside curl's clock. contextmd#58 is merged and establishes 2 s total including connect, with connect capped at 1 s, Grok 4 s, and settle separate.
  • node_modules/.bin/vp test run apps/server/src/contextmd/ --fileParallelism=false: 101/101 passed on the unmodified candidate. Existing deny/serve, three-deny cap, evidence, lifting, holdout, replay and exact-key fallback cases pass. The decision logic itself is unchanged.
  • Holding head route tests constant against round 1 production files, with the missing new budget export supplied as the literal test oracle 1200, both new regressions fail for the intended reason: 1,526 ms for the never-answering failed call and 2,408 ms for the slow body. Restored the exact candidate and reran both: 2/2 passed. The combined Cue test also exercises user-message timeout on the candidate.
  • over_budget returns 204, logs a moments row with that status, harness, delivery and elapsed serving time, and skips state.decide, so it reserves no reply or serve budget. Slow-body coverage confirms the logged status. Normal malformed/config/Cue error paths remain fail-open. The synchronous SQLite steps before/after the timed preparation, final decision/logging and event-loop stalls still prevent an unconditional hard bound, as disclosed. contextmd#60 tracks health ownership separately.
  • Exact-head CI checks are green. No private data or credentials found in the changes. No production latency or deployment verification claimed. All tests and disposable edits were under /tmp; no checkout changes, writes, live ports or restart in the user's Chromeria checkout.

Elon record for this review:

  • Requirements and who asked: exact-head independent round 2 review, including all-path deadlines and regressions, requested by the planner.
  • Deleted: no implementation changes or additional delivery work.
  • Bottleneck: authentication precedes the shared deadline.
  • Checked myself: full diff and caller chain, 101 candidate tests, both old-code failures, and delayed-auth HTTP reproduction.

Reviewer: independent Sol, medium effort.

The route authenticated before the moment's clock started, so a slow
authentication could still push the reply past the hook's 2 s (Sol review
of #251). The moment now starts its clock first and checks the credential
inside the same timed work; a cut moment serves nothing.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

Sol's round 2 finding is fixed in 13dc912855: the moment's clock now starts before authentication, which runs inside the same timed work. A new test with authentication taking 1.3 s (one credential that may read, one that may not) replies within the budget and logs over_budget; it failed on 65552bf707 at 1,306 ms. Grok's round 2 had not posted when I pushed.

@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

What: FAIL at 65552bf707bc3241ad709095670cac03d91e5612. One blocking finding.
Why: Authentication finishes before the new clock starts, so a delayed session lookup is added on top of the full 1.2 s budget and can miss the hook's 2 s cutoff.
So what: Start the budget when the request arrives, before authentication, and fail open if that wait uses the budget up. Then this needs another exact-head review.

Blocking: the arrival budget does not include authentication

ContextmdRoute.ts awaits authorized(request) and only then calls serving.moment. startedAt is the first line of moment, so MOMENT_BUDGET_MS does not cover authentication. authenticateHttpRequest calls SessionStore.verify, which reads AuthSessionRepository.getById on the shared SQLite client. That client takes a one-permit semaphore (packages/shared/src/nodeSqliteClient.ts), and a transaction holds the permit until it ends. The same client sets busy_timeout to 5,000 ms so a CLI writer does not fail the server with SQLITE_BUSY (apps/server/src/persistence/Sqlite.ts). Neither wait has a deadline, and both happen before the budget is armed. A failed authentication takes the same unbounded wait and only then returns 401.

This is not the disclosed synchronous stall inside the moment. The event loop can stay free while authentication waits on the semaphore, and the budget cannot shrink to pay for time it has not started counting. After that wait the handler may still use the whole 1.2 s, so the hook (curl -m 2, connect included, merged in contextmd#58) can already be gone when a 200 arrives.

Reproduction, only in a /tmp worktree at this head: the route test's auth mock slept 1,300 ms, then the existing never-answering Cue test ran otherwise unchanged. The failed call came back HTTP 200 at 2,207 ms (client clock 2,222 ms), which is past both 1,200 ms and the hook's 2 s. The 1,300 ms is injected delay, not a measured production authentication time. The production wait with no cutoff is that semaphore, plus up to 5 s of busy_timeout.

Checked, not blocking

  • Budget arithmetic matches the stated inputs. The merged hook is deadline=2 and --connect-timeout 1 (Grok stays at 4). 2,000 − 591 − 200 = 1,209, and the constant is 1,200. A typical Cue wait is 1,200 − 250 − 50 − 106 = 794 ms, about 800. I did not recompute the 591, 106, or 236 log percentiles.
  • Inside the clock, a Cue wait ends 50 ms before the guard, so a Cue timeout is still served. Past the guard the handler logs over_budget and returns 204 without decide, so it reserves nothing. The hook prints a body only for HTTP 200 and otherwise exits 0, so 204 fails open. moments.status is plain text, so the new status is stored. At this head the slow-body test returned 204 in 951 ms and logged over_budget.
  • The synchronous SQLite step that blocks the event loop, and contextmd#60 (health.py STATUSES omits over_budget, so owner() files it to contextmd), match the gaps the PR already names.
  • Parent c42a9d42 with only MOMENT_BUDGET_MS = 1200 added so the new tests can import it: the never-answering failed call took 1,529 ms and returned 200; the slow body took 2,410 ms. Both fail the new bound. Restored this head and ran ContextmdRoute, Cue, and ServingState: 80 passed, including the three-deny cap and the lift cases. DENY_CAP is still 3. Serve and deny budgets are unchanged. COLLECT_MS stays 300 and is also capped by the time left.
  • No private data in the diff. Tests ran only under /tmp. I did not write the Chromeria checkout, restart it, or use its ports.

Reviewer: independent Grok, medium effort.

… parsed

A moment cut by its budget was logged with only harness, delivery and
timing, so a measurement joining calls to the serving log could not tell a
budget cut from a call that never arrived (#252). Its row now carries what
it had parsed: kind, session, tool-use id, and the run once joined.

Closes #252.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

Grok's round 2 blocker is the same one Sol found; it's fixed in 13dc912855. Also folded in #252 at 2cad7749d5: over_budget rows now carry the kind, session and call id the moment had parsed, plus the run once joined. The new test cuts a pre-tool moment by holding the shared database in a transaction, which is the semaphore wait Grok named. This PR now closes #252.

@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

What: FAIL at 2cad7749d59e2d917a40547087f03c60ebafcbc4, with one blocking P2 finding in #252's identity coverage.
Why: A moment cut during selection still loses already parsed identity, so the measurement can count it as a call that never arrived.
So what: Preserve validated moment identity before selection's asynchronous file work, add that timeout regression, and request a fresh exact-head review.

Blocking: P2, identity is saved only after all selection work finishes

Location: ContextmdServing.ts:482-504, with Select.ts:194-296.

known remains empty until Select.select returns. That function validates the event and session and determines the moment kind before awaiting read/path checks, session-start files, or exact-key store loading. Thus a valid, authenticated pre-tool body can be fully received and parsed, then time out while loading its store, yet its over_budget row has null kind, session and tool-use id. The new test only blocks the later run lookup, after known has been assigned, so it misses this path. This violates #252's outcome and acceptance criterion and preserves the false "no pre-tool row" classification for contextmd#61's measurement.

Independent reproduction on the exact production head, in a disposable copy of the route test under /tmp: vi.spyOn(Store, "load") returns Effect.sleep(1300).pipe(Effect.andThen(original(...args))); send the existing valid Claude PreToolUse fixture (echo a, session S1, call toolu-echo a) through the real HTTP route. The HTTP response is empty 204 at about 956 ms, within the budget, but the database contains:

{"kind":null,"status":"over_budget","session":null,"tool_use_id":null}

The identity assertion fails. Repeated the probe: same failure. This is injected asynchronous store latency, not a claim that production stores currently take 1.3 s. No production implementation was modified for this probe. Retain the parsed identity before those waits, using the same validated/normalized harness interpretation as normal selection; retain nulls when authentication or actual event parsing has not completed.

Cleared concerns and proof

  • Both round 2 blockers are the same authentication defect and are closed. The clock starts before the credential effect executes; accepted delayed authentication and refused delayed authentication both time out without serving content. Replay also follows authorization. The candidate's delayed-auth test passes; holding head tests constant against round 2 ContextmdRoute.ts and ContextmdServing.ts fails at 1,311 ms versus the 1,200 ms oracle. The contextmd serving log: over_budget moments carry no kind, session or tool-call id #252 lookup test also fails on those old production files because identity is null.
  • Authentication, body read, config/selection I/O, run lookup, deny/read queries, transcript work and Cue waits are inside timeoutOption. The shared-database semaphore wait is interruptible and the new lookup test passes. Cue ends 50 ms before the 950 ms work guard; tool-result collection remains capped at 300 ms and the remaining budget. I found no additional asynchronous foreground wait outside that guard in the moment path. The outer error handler logs and returns empty 204; it adds no authentication or database lookup.
  • This remains a best-effort deadline, not an unconditional hard bound: synchronous shared SQLite operations can block the event loop (its configured busy timeout is 5 s), and state.decide, timeout logging and the error logger are outside the timed preparation. The private serving database has a 100 ms busy timeout. These are the disclosed synchronous limitations, not a newly discovered asynchronous escape or a production latency verification.
  • contextmd serving log: over_budget moments carry no kind, session or tool-call id #252's fields are otherwise correct and safe: the normal selected moment supplies kind/session/call id, a unique joined running attempt supplies thread/run, and parameterized insertion preserves nulls where unknown. An additional route probe delaying Store.loadCue after the run join passes and verifies thread_id = thread-of-run-1 and run_id = run-1. The remaining defect is when identity becomes available, not SQL injection or a wrong join.
  • Disabled serving whose state file cannot open is acceptable for this fail-open route: an additional test sends unknown, weak and delayed-unknown credentials and receives exactly {status: 204, body: ""} for each. The disabled service never reads the body, calls selection, replays content or reaches state.decide. No unauthenticated knowledge is served.
  • Exact candidate: node_modules/.bin/vp test run apps/server/src/contextmd/ --fileParallelism=false: 103/103 passed. Existing deny/serve budgets, three-deny cap, evidence/lifting, holdout, replay, malformed/config failures and exact-key fallback coverage remain green. Additional review probes: two pass (joined IDs and disabled serving), one fails (selection-time identity loss).
  • Holding head tests constant against round 1 production route/serving/Cue files, with only the literal MOMENT_BUDGET_MS = 1200 test oracle added, the never-answering Cue test fails at 1,525 ms, and the slow-body test fails at 2,408 ms. Both pass on the exact candidate. The round 2 baseline comparison above separately establishes the authentication and new lookup-identity regressions.
  • Read the PR body and all prior comments in full, plus the complete gh pr diff, git show, contextmd serving log: over_budget moments carry no kind, session or tool-call id #252 and surrounding callers. Inline comments and review API lists are empty. GitHub build/typecheck/lint and test checks are green on this head. No other regression or private data/credential exposure found in the inspected scope. No deployment or live latency claim.

All test runs and disposable changes were in /tmp/chromeria-review-r3.45Nmdv/repo. Production files there were restored to the exact reviewed head after baseline comparisons. No writes in ~/dev/toolboxmd/chromeria, no live Chromeria ports, no live database access and no restart.

Elon record:

Reviewer: independent Sol, medium effort, round 3.

… any file

An over-budget moment cut while selection loaded its config or store still
logged no identity, because it was taken only after selection finished
(Sol round 3 on #251). Selection's event reading is now `Select.identify`,
which serving runs as soon as the body parses, before any file work.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

Sol's round 3 finding is fixed in dbecf5d247. The moment's kind, session and call id are now taken by Select.identify as soon as the body parses, before the config and store reads, so a cut at any later point logs them; thread and run follow once joined. The new test delays the exact-key store past the budget, as in Sol's reproduction; it failed on 2cad7749d5 with null identity.

@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

What: PASS at 2cad7749d59e2d917a40547087f03c60ebafcbc4. No blocking findings.
Why: The moment clock now starts before authentication, and a cut serves nothing. An over_budget row carries the kind, session and tool-use id contextmd#61 joins on, or null when the cut came first.
So what: Nothing from this review goes back to the branch.

Round 2 blockers, closed

Authentication is inside the timed work. ContextmdRoute.ts passes the credential effect into moment, and moment yields it only after startedAt and under Effect.timeoutOption. On this head a 1.3 s credential, one that may read and one that may not, each returned 204 in 951 ms and 953 ms (http.span), logged over_budget. On 65552bf707 the same test returned 200 at 1,305 ms server time (client 1,308 ms) and failed expected 1308 to be below 1200. That was a served reply, not only a late empty one.

The shared-database lock is inside the same clock. A transaction held on the server SqlClient makes the pre-tool run lookup wait; the reply was 204 at 953 ms with kind pre_tool, the session, and toolu-echo a. A body held for twice the budget, cut before parsing, was 204 at 952 ms with kind, session and tool-use id null. On 65552bf707 the parsed row had all three null, which is the #252 failure. contextmd#61 counts a server cut only when the sole pre_tool status for (harness, session, tool_use_id) is over_budget, and counts tool_use_id IS NULL as idless, not lost. These rows match that. Thread and run are added only after resolveRun returns a run, from the same query a served row uses, and they are not the join key. A cut before the credential is known cannot write a forged id, because parsing is after authentication. The bearer token is not logged.

Other paths

  • Body read. The body effect is yielded inside the timeout. The slow-body test above was cut at 953 ms, 204, over_budget.
  • Run lookup. Same lock test. orElseSucceed does not swallow the timeout: a probe of Effect 4.0.1 returned None in 152 ms around a 5 s sleep wrapped in orElseSucceed.
  • Database locks. The in-process semaphore wait is that same test. checkDenies and checkReads use catchCause, which does not keep the reply open: the same probe returned None in 153 ms when catchCause was followed by another 5 s sleep. A synchronous busy_timeout of 5,000 ms on the shared client can still block the event loop until the step ends. That is the limit the PR already names, not an async wait outside the clock. The serving-state connection uses 100 ms.
  • Error handler. The outer catchCause returns 204 and does not replace a timeout. The probe's timeout result was "cut" in 153 ms, not the handler value. A 204 has no body (HttpServerResponse.empty).
  • 204 without a credential check. If the state file cannot be opened, moment is a constant 204 and the credential effect is never run. The existing test still expects 204. Nothing is served. Acceptable.

decide stays after the guard, so a cut does not reserve a reply. A fast refusal is still 401 (unknown and weak in the existing route test). Cue's own wait still ends 50 ms before the guard.

Proof

/tmp clone only, at this head: vp test run src/contextmd --fileParallelism=false gave 103 passed (route 23, serving state 48, select 21, cue 11), including deny, replay, exact key, and the state-file 204. The same new route tests against 65552bf707 failed the two cases above and passed the slow score, the never-answering Cue, and the slow body. Effect 4.0.1 as installed in that clone.

No private data in the diff. I did not write ~/dev/toolboxmd/chromeria, restart Chromeria, or use its ports.

Elon record

Reviewer: independent Grok, medium effort, round 3.

@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

What: PASS at dbecf5d2475bd130f3ab7d88dd56da90bfc4263e, with no blocking findings.
Why: Validated identity is retained before selection I/O, closing round 3's #252 failure; the authentication and asynchronous work budget fixes still hold.
So what: No branch changes are required by this review; the planner retains merge and deployment ownership.

Round 3 finding closed

ContextmdServing.ts:482-487 calls Select.identify immediately after JSON decoding and assigns kind, session and tool-use id before Select.loadConfig, read/path checks, session-start reads or exact-key store loading. Select.select uses that same identity function, including harness fields and reported/printed failure normalization. Identity is not subsequently cleared. Once resolveRun returns a unique running attempt, thread and run are added before deny/read queries, Cue-store loading or transcript work. Invalid events remain unrecognized; cuts before authentication or body parsing retain null identity.

I found no remaining asynchronous cut point after valid identity extraction that loses these fields. The new store-delay route test genuinely reaches Store.load, returns 204 and asserts all three IDs. Keeping the candidate test fixed against round 3 production ContextmdServing.ts and Select.ts at 2cad7749d59e2d917a40547087f03c60ebafcbc4 fails exactly as reported: HTTP 204 at 955 ms, over_budget, but null kind/session/tool-use id. It passes on the requested head.

Additional disposable real-route probes pass:

  • Delay config loading beyond the guard for Claude pre-tool, Codex printed failure, Grok reported failure and OpenCode pre-tool: each returns 204 within 1,200 ms and logs its normalized kind, session and call ID.
  • Delay Store.loadCue after the run join: the cut logs run_id = run-1 and thread_id = thread-of-run-1.

These fields satisfy #252 and contextmd#61's identity join. No credential is logged.

Earlier fixes and regressions

The first operation in moment captures the clock. The route passes authentication as an effect, which executes first inside the timed preparation, before body reading or replay. A fast refusal remains 401; a credential still unknown at the cut serves nothing. Body reading, config/selection I/O, run lookup, deny/read checks, transcript queries and foreground Cue waits remain inside the 950 ms guard. Cue's wait ends 50 ms earlier; tool-result collection remains capped at 300 ms and the time left. A cut skips state.decide, logs over_budget, and returns empty 204. I found no new asynchronous foreground wait outside that guard.

The 2 s deadline remains qualified by the same disclosed synchronous limitations: shared SQLite can block the event loop with a 5 s busy timeout; synchronous final decision/logging runs after preparation, and the serving-state connection uses a 100 ms busy timeout. The guard cannot enforce an unconditional wall-clock deadline against an event-loop stall. This head neither introduces nor closes that limitation. No production latency or deployment verification is claimed.

Proof, only in my /tmp/chromeria-review4.U0nI0E/isolated clone:

  • Exact candidate: node_modules/.bin/vp test run apps/server/src/contextmd/ --fileParallelism=false: 104/104 passed. Existing denial/serving budgets, three-deny cap, evidence/lifting, holdout, replay, malformed/config failures and exact-key fallback remain green.
  • Additional route probes: 2/2 passed, including the four harness/config cuts and joined IDs above.
  • Candidate delayed-auth test against round 2 production route/serving at 65552bf707bc3241ad709095670cac03d91e5612: fails at 1,327 ms against the 1,200 ms oracle.
  • Candidate deadline tests against round 1 production route/serving/Cue at c42a9d42ddbfd7a7525637bb50fe7a03c0d17eaa, adding only the literal missing MOMENT_BUDGET_MS = 1200 test export: fail at 1,528 ms for never-answering Cue and 2,408 ms for slow body.
  • Restored all production files to the exact candidate. ContextMD contract suite from my separate /tmp clone at 5ae62ffc63c4d0a28a908b8139efbbc684b16548: CONTEXTMD_CHROMERIA=/tmp/chromeria-review4.U0nI0E/isolated python3 -m unittest tests.test_contract: 18 tests OK, no skips. This run began after exact-head restoration.
  • Exact-head GitHub build, typecheck, lint and test checks pass. I inspected their SHA binding; I did not rerun repository-wide checks locally. No separate local Knip result is claimed.

Read the PR body and all prior comments in full, complete gh pr diff, git show, #252 and the relevant callers. Review and inline-comment lists are empty. No other regression or private-data exposure found in the inspected scope. Production files are restored and the clone is clean; disposable probes were removed. No writes in ~/dev/toolboxmd/chromeria, no live Chromeria ports or databases, and no restart.

Elon record:

  • Requirements and who asked: round 4 exact-head independent review, parsed IDs, previous budget fixes, old-code failures and regressions, requested by the planner.
  • Deleted: implementation and unrelated delivery work; review only.
  • Bottleneck: preserving identity before asynchronous selection work, now closed.
  • Checked myself: full diff and caller inspection, 104 candidate tests, old-code failures, four-harness config-cut and joined-ID probes, 18 exact-candidate contract tests and SHA-bound CI.

Reviewer: independent Sol, medium effort, round 4.

@lukemaj

lukemaj commented Oct 13, 2026

Copy link
Copy Markdown
Contributor Author

What: PASS at dbecf5d2475bd130f3ab7d88dd56da90bfc4263e. No blocking findings.
Why: A budget cut after the body parses now logs kind, session and tool-use id, including a cut while selection reads its config or store. The clock still starts before authentication, and every moment path still answers inside the 1.2 s budget.
So what: Nothing from this review goes back to the branch. contextmd#61 can join these rows.

Round 3 finding, closed

Sol's cut during selection lost parsed ids because known was assigned only after Select.select returned. Select.identify now reads kind, session and tool-use id as soon as JSON parses, and moment stores them before Select.loadConfig or Select.select. Config load, path checks, the exact-key store, run lookup, deny and read checks, and Cue are all yields after that assignment. known gains thread and run only after resolveRun returns one run, and it is never cleared.

Effect.option around identify uses Effect 4.0.1 match, which re-fails an interruption instead of turning it into None. identify itself does no file or database yield, so a timer cannot land between a successful identify and the assignment. A body that fails identify (unknown event, no session) still logs nulls. A cut before the body parses still logs nulls. Thread and run stay null until the run lookup returns.

contextmd#61 counts a server cut only when the sole pre_tool status for (harness, session, tool_use_id) is over_budget, and counts tool_use_id IS NULL as idless. The new row matches that. The bearer token is not logged.

Earlier fixes, still holding

  • The clock is the first line of moment, and ContextmdRoute passes the credential effect in. A 1.3 s credential that may read, and one that may not, each returned 204 inside the budget, logged over_budget.
  • The shared-database lock, the slow body, and a Cue service that never answers still reply inside MOMENT_BUDGET_MS. A 600 ms score is still served.
  • decide stays after the guard. A synchronous SQLite step can still block the event loop until it ends. That is the limit the PR already names. Disabled serving whose state file cannot open still answers 204 and reads nothing.

Proof

/tmp clone only, at this head: vp test run apps/server/src/contextmd/ --fileParallelism=false gave 104 passed (route 24, serving state 48, select 21, cue 11). The new store-delay test was one of them (992 ms, 204, kind pre_tool, session S1, toolu-echo a).

The same test with ContextmdServing.ts and Select.ts restored to 2cad7749d5, and the new test left in place, failed: 204 at 955 ms, row {kind: null, status: over_budget, session: null, tool_use_id: null}. Those two files were restored to dbecf5d247 afterward.

GitHub Lint, Typecheck, and Test are green on this SHA. I did not re-run Knip or the contextmd contract suite. This commit does not change the HTTP reply. No private data in the diff. I did not write ~/dev/toolboxmd/chromeria, restart Chromeria, or use its ports.

Elon record

  • Requirements and who asked: exact-head round 4 review of fix(server): Cue waits up to 1.5 s for a score the moment needs now #251: close Sol's selection-time identity loss, keep the budget and authentication fixes, and show the new test fails on 2cad774 (planner).
  • Deleted: no implementation changes.
  • Bottleneck: parsed ids were stored only after selection's file reads.
  • Checked myself: the moment path and Effect 4.0.1 match, 104 tests at this head, and the null-identity failure on 2cad7749d5.

Reviewer: independent Grok, medium effort, round 4.

@lukemaj
lukemaj merged commit 916b0fe into main Oct 13, 2026
28 of 29 checks passed
@lukemaj
lukemaj deleted the fix/248-cue-wait-2s-cutoff branch October 13, 2026 19:34
lukemaj added a commit that referenced this pull request Oct 14, 2026
…251)

* fix(server): Cue waits up to 1.5 s for a score the moment needs now

The serving cut-off is 2 s while Cue is new (user decision 2026-10-13, #248):
the hook now allows 2 s, so the user-message and failed-call wait rises from
650 ms to 1.5 s and still leaves the reply inside it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix(server): every ContextMD moment replies within a 1.2 s budget

The fixed 1.5 s Cue wait plus the moment's own work missed the hook's 2 s
cut-off on failed calls (Grok review of #251). A moment now has one budget
from its arrival: its work must finish 250 ms before the end or it is cut
and logged over_budget, and a Cue wait takes only what the budget leaves.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix(server): a moment's budget includes its authentication

The route authenticated before the moment's clock started, so a slow
authentication could still push the reply past the hook's 2 s (Sol review
of #251). The moment now starts its clock first and checks the credential
inside the same timed work; a cut moment serves nothing.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix(server): an over-budget moment logs the kind, session and call it parsed

A moment cut by its budget was logged with only harness, delivery and
timing, so a measurement joining calls to the serving log could not tell a
budget cut from a call that never arrived (#252). Its row now carries what
it had parsed: kind, session, tool-use id, and the run once joined.

Closes #252.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix(server): a moment knows its kind, session and call before reading any file

An over-budget moment cut while selection loaded its config or store still
logged no identity, because it was taken only after selection finished
(Sol round 3 on #251). Selection's event reading is now `Select.identify`,
which serving runs as soon as the body parses, before any file work.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
lukemaj added a commit that referenced this pull request Oct 29, 2026
…251)

* fix(server): Cue waits up to 1.5 s for a score the moment needs now

The serving cut-off is 2 s while Cue is new (user decision 2026-10-13, #248):
the hook now allows 2 s, so the user-message and failed-call wait rises from
650 ms to 1.5 s and still leaves the reply inside it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix(server): every ContextMD moment replies within a 1.2 s budget

The fixed 1.5 s Cue wait plus the moment's own work missed the hook's 2 s
cut-off on failed calls (Grok review of #251). A moment now has one budget
from its arrival: its work must finish 250 ms before the end or it is cut
and logged over_budget, and a Cue wait takes only what the budget leaves.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix(server): a moment's budget includes its authentication

The route authenticated before the moment's clock started, so a slow
authentication could still push the reply past the hook's 2 s (Sol review
of #251). The moment now starts its clock first and checks the credential
inside the same timed work; a cut moment serves nothing.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix(server): an over-budget moment logs the kind, session and call it parsed

A moment cut by its budget was logged with only harness, delivery and
timing, so a measurement joining calls to the serving log could not tell a
budget cut from a call that never arrived (#252). Its row now carries what
it had parsed: kind, session, tool-use id, and the run once joined.

Closes #252.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

* fix(server): a moment knows its kind, session and call before reading any file

An over-budget moment cut while selection loaded its config or store still
logged no identity, because it was taken only after selection finished
(Sol round 3 on #251). Selection's event reading is now `Select.identify`,
which serving runs as soon as the body parses, before any file work.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

size:L vouch:trusted PR author is trusted by repo permissions or the VOUCHED list.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

contextmd serving log: over_budget moments carry no kind, session or tool-call id

1 participant