test(query-orchestrator): make the orphaned queue test deterministic - #11610
test(query-orchestrator): make the orphaned queue test deterministic#11610ovr wants to merge 2 commits into
Conversation
`QueryQueue.abstract.ts`'s `orphaned` test needed two hostile things from one 800ms delay value. With `continueWaitTimeout: 1s`, `executionTimeout: 2s`, `orphanedTimeout: 2s` and `concurrency: 1`, each awaited `executeInQueue` had to return inside its own 1s window or throw `ContinueWaitError` (so `delay < 1000`), while `114` had to stay queued past the 2s orphaned timeout behind three sequential queries (so `3 * delay > 2000`). That leaves `delay` in (667, 1000) — about 200ms of slack per step, minus several Cube Store round trips. Its numbers had already been nudged in #6090, #6094, #6125, #6189 and #9705, and it spent a while disabled for Cube Store. Timing now comes from explicit per-query orphaned timeouts and an explicit reconciliation poll instead of the ratio between query duration and `continueWaitTimeout`: two blockers hold the single worker for ~2.4s carrying `orphanedTimeout: 60` so they are never orphan-eligible themselves, the orphan candidate carries `orphanedTimeout: 1`, and the test polls `reconcileQueue()` rather than hoping one fires. The orphan candidate can now be added ~1.4s late and the test still holds, and stalls widen that window instead of closing it. `expect(delayCount).toBe(2)` additionally proves the orphaned query never executed, which the old version never checked. Fresh keys `121`-`123` drop the coupling to `sequence`'s `111`-`114`, so the recovery loop goes away; ordering stays covered by `sequence` and `negative priority`. Verified against docker `cubejs/cubestore:v1.7.23`, with 12 busy-loops saturating the box to reproduce the CI conditions: | run | before | after | | --- | --- | --- | | Cube Store suite, idle, 5x | pass | pass | | Cube Store `orphaned`, under load | 5/8 passed | 8/8 passed | | memory driver suite, under load | — | 4/4 passed | Under load the old test reproduced both CI signatures: `Continue wait` at `QueryQueue.abstract.ts:270` and `Expected "114", Received "113"`. Runtime drops from 3675ms to ~2.5s. `yarn unit` 68/68, `yarn tsc` and `eslint` clean. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
Claude finished @ovr's task in 5m 31s —— View job Review: sound direction, 3 comments (0 blocking, 1 medium, 2 low)Full review — click to expand
VerdictThe core idea is right and this is a real improvement over what it replaces. Decoupling the orphan trigger from the I verified the mechanics hold:
Two things I'd like tightened, both left as inline comments:
What I liked
|
| expect(result).toBe('32'); | ||
| // every client gave up on ContinueWaitError long before this point | ||
| await Promise.all(pending); | ||
| await awaitProcessing(); |
There was a problem hiding this comment.
There is a narrow window where expect(delayCount).toBe(2) can miss 122 — worth hardening, since removing residual flake is the whole point of the PR.
reconcileQueueImpl still dispatches one process message per call even when the slot is saturated (toProcessLimit = active.length >= this.concurrency ? 1 : ..., QueryQueue.ts:576). So each of the ~10 poll iterations above fires a speculative processQuery('122'). Those take the processing lock, fall into the "Skip processing" branch and free it — and that branch, unlike the success path, does not call reconcileQueue() (QueryQueue.ts:971 vs :974).
If one of those speculative attempts holds the lock at the moment 121 finishes and runs its completion reconcile, the real dispatch of 122 gets retrieveForProcessing → null (LocalQueueDriverConnection.ts:286-290) and returns without re-dispatching. Nothing then picks 122 up: the poll loop has already exited (it stops as soon as cancelledQuery === '123', ~1.1 s — right on top of 121 finishing at ~1.2 s), and awaitProcessing() only drains promises that already exist. Result is either delayCount === 1 here, or 122 gets dispatched by the final executeInQueue('123')'s own reconcile and that call throws Continue wait — the exact CI signature this PR is retiring.
Probability is low on the memory driver (the lock is held across a couple of microtasks) but wider on Cube Store, where getQueryDef in that branch is a network round trip. Cheap fix — reconcile until the queue is actually drained rather than once:
| await awaitProcessing(); | |
| // 121 may still be executing; keep reconciling so 122 is re-dispatched even if a | |
| // speculative processQuery from the poll loop above briefly held its processing lock. | |
| const drainDeadline = Date.now() + 3000; | |
| do { | |
| await queue.reconcileQueue(); | |
| await awaitProcessing(); | |
| if (delayCount < 2) { | |
| await delayFn(null, 100); | |
| } | |
| } while (delayCount < 2 && Date.now() < drainDeadline); |
| await queue.executeInQueue('delay', `11${i}`, { delay: 50, result: `${i}` }, 0); | ||
| } | ||
|
|
||
| cancelledQuery = null; |
There was a problem hiding this comment.
Nit: delayCount and streamCount are reset in beforeEach (lines 102-106) but cancelledQuery is reset here, inside the one test that reads it. Moving it to beforeEach keeps the shared mutable state in one place and stops a stray cancel from a preceding test (e.g. the timeout test's Cancelling query due to timeout path, which also runs cancelHandlers.delay) from leaking into whichever test looks at it next.
Codecov Report✅ All modified and coverable lines are covered by tests.
Additional details and impacted files@@ Coverage Diff @@
## master #11610 +/- ##
===========================================
- Coverage 84.10% 59.33% -24.77%
===========================================
Files 257 228 -29
Lines 81789 18222 -63567
Branches 0 3675 +3675
===========================================
- Hits 68785 10812 -57973
+ Misses 13004 6863 -6141
- Partials 0 547 +547
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
Co-authored-by: claude[bot] <209825114+claude[bot]@users.noreply.github.com>
|
Claude finished @ovr's task in 2m 21s —— View job Re-review of
|
| # | Severity | Where | Status |
|---|---|---|---|
| 1 | Medium | line 281 | Still applies. awaitProcessing() only drains promises that already exist — shutdown() awaits reconcilePromise and returns, it never re-dispatches (QueryQueue.ts:431-439). So if a speculative processQuery('122') from the poll loop holds the processing lock when 121's completion reconcile fires, 122 can be stranded in toProcess and expect(delayCount).toBe(2) fails — or the final executeInQueue('123') picks it up and throws Continue wait, the signature this PR retires. Reconcile-until-drained fix is in the thread. |
| 2 | Low | line 253 | Still applies. cancelledQuery = null belongs in beforeEach next to delayCount / streamCount (lines 102-106). |
Notes
- Nothing else changed in the incremental commit; no new correctness, security, performance or docs concerns. Test-only diff, single file.
- Minor stylistic thought, not worth a thread:
outcomes.forEach((e) => expect(e).toBeInstanceOf(...))won't tell you which of the three failed.expect(outcomes).toEqual([...])withexpect.any(ContinueWaitError)would, but the three keys are easy enough to identify from the surrounding output.
Check List
Description of Changes Made
QueryQueue.abstract.ts'sorphanedtest is a long-standing flake — most recently it failed #11608'sintegration-cubestorejob withContinue waitatQueryQueue.abstract.ts:270, and its magic numbers had already been nudged in #6090, #6094, #6125, #6189 and #9705. The cause is that one 800ms delay value had to satisfy two hostile constraints: withcontinueWaitTimeout: 1s/executionTimeout: 2s/orphanedTimeout: 2s/concurrency: 1, each awaitedexecuteInQueuemust return inside its own 1s window (delay < 1000) while114must stay queued past the 2s orphaned timeout behind three sequential queries (3 * delay > 2000), leaving ~200ms of slack per step minus several Cube Store round trips. Timing now comes from explicit per-query orphaned timeouts and an explicitreconcileQueue()poll instead of that ratio — two blockers hold the single worker for ~2.4s withorphanedTimeout: 60so they are never orphan-eligible themselves, and the orphan candidate carriesorphanedTimeout: 1, so it can be added ~1.4s late and the test still holds.expect(delayCount).toBe(2)also proves the orphaned query never executed, which the old version never checked, and fresh keys121-123drop the coupling tosequence's111-114(ordering stays covered bysequenceandnegative priority).Verification
Run against docker
cubejs/cubestore:v1.7.23, with 12 busy-loops saturating the box to reproduce CI conditions — under that load the old test reproduced both signatures (Continue waitat line 270, andExpected "114", Received "113").orphaned, under loadyarn unit68/68 inquery-orchestrator,yarn tscandeslintclean. Test runtime drops from 3675ms to ~2.5s.Note one thing left untouched:
LocalQueueDriverConnectionreports actively executing queries as orphaned (state.recentsurvivesretrieveForProcessing), so on the memory driver a reconcile can cancel a query mid-flight, while Cube Store only cancels active queries on heartbeat timeout. That divergence is why the blockers here needorphanedTimeout: 60; changing dev-mode driver behaviour doesn't belong in a test fix.🤖 Generated with Claude Code