Skip to content

test(flow-scheduled): the SLA backlog block waits for its sweep's notification deliveries before its no-op test runs - #2176

Merged
objectstack-fleet[bot] merged 2 commits into
mainfrom
claude/issue-2157-sla-sweep-test-timeout
Oct 19, 2026
Merged

objectstack-fleet[bot] merged 2 commits into
mainfrom
claude/issue-2157-sla-sweep-test-timeout

Conversation

@objectstack-fleet

Copy link
Copy Markdown
Contributor

Fixes #2157
Clause-②: no

The case_sla_monitor block of test/flow-scheduled.test.ts now waits, in its own beforeAll, for the notification deliveries its backlog sweep enqueues. Its no-op test (line 195 on main) no longer spends ~2.2 s of its 5 s budget waiting for them. That wait is what timed it out on slower CI runners (PR #2151, PR #2155, main a3653187, PR #2173).

Where the time went (measured on 0a8f73d, before any edit)

The instrumentation ran in the worktree only and is not in this diff. Six runs, through the shared lock, on a quiet 4-core box:

step of the no-op test time
openCase: the account seed 14 ms
openCase: verify.hooks.run('crm_case', 'insert', …, { as: agent.token }) 2109 ms
openCase: the system update 14 ms
sweep('case_sla_monitor') (selected=0) 2–4 ms
the two reads 4 ms
whole test 1911–2550 ms across the six runs

Inside that insert, contextFor's auth.api.getSession took 1792–2452 ms; the rest of contextFor took 14 ms. The call issued its first engine operation (the sys_session read) only about 2.08 s after it started. Over the same window the engine received 782 operations that the test did not make. All came from the messaging outbox dispatcher, which was working off the backlog sweep's deliveries: 46 sys_email inserts, 30 sys_inbox_message inserts, 92 sys_notification_delivery updates, 152 delivery reads, and others.

The mechanism, measured step by step:

  • The block's backlog sweep processes every match, seed rows included (selected=34 acted=17). It notifies 30 times: 17 case_sla_breach and 13 urgent_task, each on two channels (inbox and email), so 60 sys_notification_delivery rows. notify only enqueues them; the dispatcher delivers them after the sweep has returned.
  • On the boot's synchronous SQLite driver (driver-sqlite-wasm), that drain is one long run of promise continuations. A 5 ms setInterval pinger fired 9 times in 2.5 s, with gaps of 1673, 604 and 132 ms. The pinger cannot fire during the drain, and neither can getSession resume while it waits on a macrotask. This is not a connection lock: no driver transaction was opened in the window (0 beginTransaction).
  • Every email attempt fails on this boot with VALIDATION_FAILED: from address required (set options.defaultFrom or pass input.from), because the harness's EmailServicePlugin has no from address. The outbox retries a failed delivery about 1 s later, then about 10 s later (its schedule is 1 s, 10 s, 60 s, 10 min, 1 h, with ±20% jitter). Each attempt writes one failed sys_email row.

PM hypothesis 1 holds: the time is the backlog sweep's async aftermath. The aftermath is specifically the outbox drain, plus the email channel's first retry wave.

The change

  • settleNotificationDeliveries(stack, fn), new in test/helpers/verify-stack.ts next to notificationsTo. It runs fn inside the handle's own door, verify.observeWrites. It then waits on observation.settled(…) for the dispatcher's acknowledging update of every delivery inserted while the observation is open. It keeps waiting until each delivery is finished (success, suppressed, dead) or parked for a retry more than one test's budget (5 s) away. An attempt is the acknowledgement update addressed to the row's id; it is the one write that stamps last_attempted_at. The wait is on the work, not on the clock. Each settled call has a 60 s bound, which is a failure bound and not a wait: it fails loudly, naming every observed write, well inside the hook's unchanged 120 s budget.
  • The block's beforeAll runs its backlog sweep through it. No other block uses it.
  • No timeout raised, no skip, no retry wrapper, no sleep. Every it keeps exactly what it asserts.
  • An empty-frontmatter changeset declares the PR tests-only, as AGENTS.md allows and as test: run every remaining driver-memory test on the SQL driver #2104 did.

Waiting only for each delivery's first attempt is not enough. A prototype that did so left the no-op test at 630 ms: the 1 s retry wave landed in its window, and getSession took 503 ms of it. That is why the wait also covers retries due soon.

Before and after

run no-op test
0a8f73d, quiet, whole file 2327 ms (instrumented runs 1911–2550 ms)
this branch, quiet, whole file 81 ms (78 ms in an instrumented run: getSession 12.6 ms, no macrotask gap over 50 ms)
0a8f73d under load (vitest pinned to one core with taskset -c 0, beside two busy-loop processes on the same core, --maxWorkers=1, this block only) × 7600 ms, Error: Test timed out in 5000ms, the CI failure shape
this branch, same load ✓ 312 ms

The block's beforeAll now spends 747 ms on the sweep and 3373 ms in the wait, inside its own budget. On return all 30 inbox deliveries are success and all 30 email deliveries are parked about 10 s out. The whole file passes 54 of 54 in 65.6 s, against 61.1 s on 0a8f73d. The probe and load runs were on 249abb7; 03f3df4 adds only the changeset.

Verification (pnpm verify on 03f3df4, through the shared lock)

  • The build half (pnpm validate && pnpm typecheck && pnpm lint && pnpm lint:i18n-gate && pnpm hygiene && pnpm hygiene:tokens && pnpm build) printed VERDICT command-exit 0. tsc covers test/**.
  • pnpm exec vitest run --shard=1/3: 66 files, 1102 passed, VERDICT command-exit 0.
  • --shard=2/3: 65 files, 1223 passed and 1 skipped, VERDICT command-exit 0.
  • --shard=3/3: 65 files, 1579 passed, VERDICT command-exit 0.

CI runs the rest.

Acceptance notes

These were observed during measurement. None was filed, and none is changed here.

  • For hotcrm#2175, which is not addressed here: the same mechanism. The dispatcher's email channel inserts sys_email rows asynchronously, long after the run that notified: 46 of them landed inside this test's 2.1 s window. Because every notification email fails on this boot and is retried about 1 s, 10 s and 60 s later, any test that reads "the first sys_email insert" off an engine recorder can catch another notification's attempt. test/script-bodies.test.ts:366 does exactly that. settleNotificationDeliveries waits only for deliveries enqueued while it is open, and only for retries due within 5 s, so it does not cover an earlier test's 10 s or 60 s wave. Two candidates for that dispatch:
    • give the harness's EmailServicePlugin a from address, so each notification email is one attempt and the retry tail disappears suite-wide (a boot change for every suite);
    • make the pin read its own row.
  • Platform observation, with no public-door reach measured: the email channel classifies VALIDATION_FAILED: from address required, a configuration error that no retry can cure, as retryable. Each notification email is therefore attempted five times over about 71 minutes, and each attempt writes a failed sys_email row. Carrier: none.
  • Platform observation, with no public-door reach measured: on driver-sqlite-wasm, the dispatcher's drain of 60 deliveries held the event loop's macrotask phase for about 2.2 s, measured in-process. A server on that driver would not answer requests during such a burst. The HTTP door was not measured. Carrier: none.
  • @objectstack/verify already offers the path this needed (observeWrites with settled), so no platform gap is reported. The helper does rely on the outbox's acknowledgement stamping last_attempted_at, a declared field of sys_notification_delivery.

Generated by Claude Code

…ification deliveries before its no-op test runs

The no-op test of the `case_sla_monitor` block spent ~2.2 s of its 5 s budget
outside its own ~3 ms sweep, and timed out on slower CI runners (four times).
Measured: the block's backlog sweep enqueues 60 notification deliveries (30
notifications, inbox and email), the messaging dispatcher works them off after
the sweep returns, and on the synchronous SQLite driver that drain starves every
macrotask until it ends, so the next test's session lookup waited it out. The
email channel fails every attempt on this boot and the outbox retries it about
1 s later, which landed in the same window.

`settleNotificationDeliveries` (test/helpers/verify-stack.ts) runs a function
inside `observeWrites` and waits, on the dispatcher's acknowledging writes, for
every delivery enqueued meanwhile to be finished or parked beyond one test's
budget. The block's beforeAll runs its sweep through it.

Co-Authored-By: Claude <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01BDgipbNowaGa139em8Fhoq
@vercel

vercel Bot commented Oct 19, 2026

Copy link
Copy Markdown

The latest updates on your projects. Learn more about Vercel for GitHub.

1 Skipped Deployment
Project Deployment Actions Updated
hotcrm Ignored Ignored Oct 19, 2026 8:18am UTC

Request Review

@objectstack-fleet

Copy link
Copy Markdown
Contributor Author

席位核对

ACCEPT (#2157, maintainer direct dispatch 「同意你的建议」, CI health) · PR #2176 at 03f3df4e0f · repo:hotcrm seat · os-project-manager · session session_01BDgipbNowaGa139em8Fhoq · 2026-10-19T08:23Z · report on hotcrm#2157 (6262864028)

  1. Shape:
    • Draft, opening with Fixes #2157 and Clause-②: no. Assignee os-project-manager.
    • 3 files, +111 / −3: test/helpers/verify-stack.ts (a new helper), test/flow-scheduled.test.ts (one beforeAll line plus its comment, and the import), and an empty-frontmatter changeset. No governed path, no product file.
    • Both commits carry only the Co-Authored-By: Claude / Claude-Session: pair, so there are 0 model-identifier lines.
    • The head contains main 0a8f73d, which is main's tip.
  2. Premise, re-read on main 0a8f73d: the timed-out test is test/flow-scheduled.test.ts:195, "is a clean no-op when nothing has breached", under the block whose beforeAll runs the backlog sweep. Four CI occurrences are on the card, the third and fourth read by the seat (main a3653187 run 39190739355; PR feat(nav): a Reports group with an entry for every shipped report (#2073 item 1) #2173 run 39204202466).
  3. The diff, read:
    • settleNotificationDeliveries(stack, fn) runs fn inside observeWrites. It then waits for the dispatcher's acknowledging update of every sys_notification_delivery row inserted while the observation is open. A delivery counts as worked off when it is finished, or when it is parked for a retry at least 5 s after the attempt. Deliveries inserted during the wait are picked up too.
    • Only the case_sla_monitor block's beforeAll uses it. No it changes, no assertion changes, and both timeouts stay as they were: vitest's default 5 s and the hook's 120 s.
    • The seat checked the two platform behaviours the helper rests on, in the objectstack source.
      • WriteObservation.settled (packages/verify/src/handle.ts:244-260, :931-975) resolves with the first matching write, already observed or later, once the engine has answered it. The helper's answered set is what moves it past an attempt it has already read.
      • next_attempt_at and last_attempted_at are Field.number epoch ms (packages/services/service-messaging/src/objects/notification-delivery.object.ts:18, :169), so the Number(…) − Number(…) ≥ 5000 park test is arithmetic on numbers, not on dates.
  4. Accepted deviation: the helper's 60 s settled bound is a failure bound, not a test timeout. It fails loudly, naming every observed write, inside the hook's unchanged 120 s budget. The ruling "⛔ No timeout raised" is about the test's budget, and that budget is unchanged at 5 s.
  5. Gates:
    • The dev's pnpm verify on 03f3df4 passes through the lock: the build half exits 0, and the three shards (66 + 65 + 65 files) each exit 0.
    • Where the time went, measured on 0a8f73d: the no-op test spent 2109 ms in openCase's hooks.run(…, { as }), inside which getSession took 1792–2452 ms. The sweep took 2–4 ms. Over the same window, 782 engine operations came from the outbox dispatcher's drain, which held the macrotask phase for gaps of up to 1673 ms.
    • Before and after: 2327 ms → 81 ms on a quiet box. Under one-core load, the base fails at 7600 ms with "Test timed out in 5000ms" (the CI shape) and the head passes at 312 ms. Both legs ran through the lock, and blob equality was proven after each.
    • CI on 03f3df4: 8 of 9 checks success. Build and Test (22.x) was running at review time.
  6. Changeset, read: the frontmatter is empty, as the hotcrm AGENTS.md changeset rule allows for a PR that ships nothing to users. Its one sentence ("waits for its backlog sweep's notification deliveries … no longer times out on slower CI runners") matches the diff and the load measurement. Check Changeset is success.
  7. Out of scope, one line each:
  8. Landing: ready plus auto-merge once every check on this head reads success and the head still contains main's tip. Afterwards: bring PR feat(nav): a Reports group with an entry for every shipped report (#2073 item 1) #2173 up to date with main so its CI runs with this fix, and dispatch test/script-bodies.test.ts:367 "send_email writes the email and its timeline pointer" fails with 'failed' for 'queued' in CI (second occurrence): the pin reads the first sys_email insert in its window, which may be another writer's #2175.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

ci/cd CI plumbing and the verification pipeline

Projects

None yet

2 participants