Skip to content

fix(query-orchestrator): don't report a cancelled query as a query error - #11759

Open
paveltiunov wants to merge 2 commits into
masterfrom
claude/athena-orphaned-query-cancel-mn3jor
Open

fix(query-orchestrator): don't report a cancelled query as a query error#11759
paveltiunov wants to merge 2 commits into
masterfrom
claude/athena-orphaned-query-cancel-mn3jor

Conversation

@paveltiunov

@paveltiunov paveltiunov commented Sep 3, 2026

Copy link
Copy Markdown
Member

Check List

  • Tests have been run in packages where changes have been made if available
  • Linter has been run for changed code
  • Tests for the changes have been added if not covered yet
  • Docs have been added / updated if required

Issue Reference this PR resolves

CORE-861 — follow-up to CUB-4099

Description of Changes Made

When the queue cancels a query — orphaned, stalled, or explicitly cancelled — the queue item is removed and the driver rejects the execution that is still in flight. QueryQueue.executeQuery logged that rejection as Error while querying, which is the event that marks a query as failed in query history. So a cancellation that is deliberately kept out of query history (Removing orphaned query and Orphaned execution result are both treated as cancellations) leaked back in as an error:

Error: Query was cancelled
    at AthenaDriver.waitForSuccess (@cubejs-backend/athena-driver/src/AthenaDriver.ts:628:15)
    at Object.query (@cubejs-backend/query-orchestrator/src/orchestrator/QueryCache.ts:671:26)
    at QueryQueue.executeQuery (@cubejs-backend/query-orchestrator/src/orchestrator/QueryQueue.ts:955:23)

Athena makes it visible because its driver rejects with an explicit message rather than a connection-level failure, but the same applies to any driver that propagates a cancel as a rejection. Nothing is waiting for the result at that point, which is why setResultAndRemoveQuery fails immediately afterwards and logs Orphaned execution result.

The catch now checks whether the queue item is still there and, when it is gone, logs the rejection under a distinct Cancelled query execution event carrying cancellationError instead of Error while querying / error — a cancellation is not a failure, and the error field is what flags one downstream. A timeout is excluded: it cancels a query that is still queued, so it stays an error, and the check is skipped for it entirely. A queue lookup failure resolves to "not cancelled", so a queue storage issue can never hide a genuine query error.

The existing Removing orphaned query / Cancelling query manual / Orphaned execution result events are unchanged, so nothing downstream loses its cancellation signal.

Testing

New unit test in the shared QueryQueue suite (runs for both the in-memory and the Cube Store queue driver): a running query is cancelled mid-execution and the suite asserts the queue logs Cancelled query execution and not Error while querying. It fails against master, which logs ["…", "Cancelling query manual", "Error while querying", "Orphaned execution result", "…"].

yarn unit in packages/cubejs-query-orchestrator: 147 passed / 147. Lint and tsc --noEmit clean.

🤖 Generated with Claude Code

https://claude.ai/code/session_01Fbg1V8t2pGKB91b386YHKi


Generated by Claude Code

When the queue cancels a query - orphaned, stalled or explicitly
cancelled - the queue item is removed and the driver rejects the
execution which is still in flight. `executeQuery` logged that rejection
as `Error while querying`, the event which marks a query as failed in
query history, so a cancellation that is deliberately kept out of query
history leaked back in as an error. Athena makes it visible because its
driver rejects with `Query was cancelled` rather than a connection-level
failure, but it applies to any driver which propagates a cancel as a
rejection.

Nothing is waiting for the result at that point, which is why
`setResultAndRemoveQuery` fails right afterwards and logs
`Orphaned execution result`. Log the rejection under a distinct
`Cancelled query execution` event carrying `cancellationError` instead.
A timeout is excluded: it cancels a query which is still queued, so it
stays an error.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Fbg1V8t2pGKB91b386YHKi
@paveltiunov
paveltiunov requested a review from a team as a code owner September 3, 2026 19:26
@github-actions github-actions Bot added the javascript Pull requests that update Javascript code label Sep 3, 2026
@claude

claude Bot commented Sep 3, 2026

Copy link
Copy Markdown
Contributor

Claude finished @paveltiunov's task in 3m 14s —— View job


Review: sound fix, one blocker — the new event is invisible under the default logger

1 high, 1 medium, 2 low. 4 inline comments posted.

Full review
  • Gather context (PR diff, commit, surrounding code)
  • Review QueryQueue.ts changes
  • Review test changes
  • Trace downstream consumers of the log events
  • Check for stale review threads (none exist)
  • Post review

Summary

The diagnosis is right and the fix is in the right place. executeQuery's catch is genuinely the only thing turning a cancellation-induced driver rejection into an Error while querying, and splitting on "is the queue item still there" is the correct discriminator — it's the same condition setResultAndRemoveQuery uses two lines later to log Orphaned execution result. Excluding TimeoutError is correct: that path cancels a query that is still in the queue, so the lookup would return "not cancelled" anyway, but skipping it saves a round trip and makes the intent explicit. Hoisting the shared payload into logEvent is a clean way to avoid duplicating twelve fields.

Findings

# Severity Location Issue
1 High QueryQueue.ts:1029-1036 cancellationError with no error/warning field means the default OSS logger drops the event entirely at the default info level — the stack trace the PR sets out to preserve never reaches stdout
2 Medium QueryQueue.ts:1005-1012 The getQueryDef fallback is a post-hoc heuristic, not an exact test: a genuinely failing query whose item was concurrently orphaned loses its error field. Also a 6-line comment for one boolean
3 Low QueryQueue.ts:1111 queryKey is the hash here; every other logger call in the class passes the unhashed key
4 Low QueryQueue.abstract.ts:218-224 1s poll deadline against a 2s executionTimeout is a thin margin for the CubeStore variant on loaded CI

On #1 — this is the one worth acting on before merge. createLogger defaults to filterByLevel: 'info' (cubejs-server-core/src/core/logger.ts:168), and both devLogger and prodLogger route on the presence of error / warning alone. An event with neither, and not on the small info allowlist, matches no branch and is logged only at trace. So for OSS users the net effect of this PR is not "reclassified" but "disappeared" — strictly less information than master. 'Orphaned execution result' right below solves this by setting warning; doing the same keeps the event visible at default level without carrying the error field that flags a failure downstream.

What's good

  • Failing the queue lookup closed (isQueryRemovedFromQueue returns false on error) is the right default — a queue storage problem can't mask a real query error.
  • queryCancelled || short-circuits the extra getQueryDef, so the common external-cancellation path costs nothing extra.
  • The test exercises the real path rather than stubbing the classification: a running handler is rejected the way a driver rejects a stopped query, and it runs for both the in-memory and CubeStore queue drivers. logger.mockClear() in beforeEach means the not.toContain assertion is scoped correctly.
  • No security or authz surface touched; no new resource retained (the cancelable handler's timer is cleared on reject).

Verification

I read the code and traced the log-event consumers; I did not run the test suite or the linter in this environment.

• Branch: `claude/athena-orphaned-query-cancel-mn3jor`

Comment thread packages/cubejs-query-orchestrator/src/orchestrator/QueryQueue.ts
Comment thread packages/cubejs-query-orchestrator/src/orchestrator/QueryQueue.ts Outdated
Comment thread packages/cubejs-query-orchestrator/src/orchestrator/QueryQueue.ts Outdated
Comment thread packages/cubejs-query-orchestrator/test/unit/QueryQueue.abstract.ts
@codecov

codecov Bot commented Sep 3, 2026

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 57.14286% with 6 lines in your changes missing coverage. Please review.
✅ Project coverage is 59.95%. Comparing base (4335ea5) to head (d1328ba).
⚠️ Report is 4 commits behind head on master.

Files with missing lines Patch % Lines
...-query-orchestrator/src/orchestrator/QueryQueue.ts 57.14% 4 Missing and 2 partials ⚠️

❗ There is a different number of reports uploaded between BASE (4335ea5) and HEAD (d1328ba). Click for more details.

HEAD has 1 upload less than BASE
Flag BASE (4335ea5) HEAD (d1328ba)
cubesql 1 0
Additional details and impacted files
@@             Coverage Diff             @@
##           master   #11759       +/-   ##
===========================================
- Coverage   80.15%   59.95%   -20.20%     
===========================================
  Files         500      240      -260     
  Lines      105493    19190    -86303     
  Branches     3851     3887       +36     
===========================================
- Hits        84554    11505    -73049     
+ Misses      20391     7135    -13256     
- Partials      548      550        +2     
Flag Coverage Δ
cube-backend 59.95% <57.14%> (+0.34%) ⬆️
cubesql ?

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

Address review on #11759.

The default logger routes purely on `error` / `warning`, so an event
carrying neither is dropped at the default `info` level: the new
`Cancelled query execution` event would have removed the rejection from
OSS logs entirely rather than reclassifying it. Set `warning`, which
keeps the event at the default level without the `error` field that
flags a query as failed downstream.

Also note in the comment that the queue lookup runs after the rejection,
so a query which genuinely fails as its item is orphaned is reclassified
too, log the unhashed query key and the request id from the lookup's own
error path like every other event in the class, and tighten the test's
poll so a worker which never picks the query up fails on the poll rather
than on the log assertions.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Fbg1V8t2pGKB91b386YHKi
@claude

claude Bot commented Sep 3, 2026

Copy link
Copy Markdown
Contributor

Claude finished @paveltiunov's task in 1m 47s —— View job


Re-review of 1d87e98: blocker resolved, nothing new blocking

0 high, 0 medium, 3 low. All four prior threads are resolved and the concerns they raised are addressed in the follow-up commit. No new inline comments posted.

Full review
  • Fetch the follow-up commit and re-diff against the base
  • Check prior review threads (all 4 resolved — deduplicated, none re-posted)
  • Verify the warning field actually makes the event visible in both loggers
  • Re-check the isQueryRemovedFromQueue signature change and test tightening
  • Post review

The blocker is genuinely fixed

I traced the routing rather than taking the commit message for it. warning set with no error hits the warn branch in both loggers (cubejs-server-core/src/core/logger.ts:93-98 for devLogger, :148-153 for prodLogger), which is reachable at the default info level through the fall-through chain. devLogger's logWarning passes showRestParams: true, so cancellationError — the stack trace this PR exists to preserve — is printed, not just the message. prodLogger spreads all params into the JSON line. The event is visible at default level and carries no error field, which was the point.

One correction to my earlier comment: I cited 'Orphaned execution result' as the precedent that "solves exactly this by setting warning". It sets warn (line 1071), not warning — a field the logger doesn't route on. So that neighbouring event is itself dropped at the default level today. The fix here is right; the precedent I pointed at is the broken one. Worth a separate one-character follow-up (warn:warning: at QueryQueue.ts:1071), out of scope for this PR. Fix this →

Other follow-up items, all addressed

  • Heuristic disclosure — the comment now states that the lookup runs after the rejection and that a query which genuinely fails while its item is orphaned is reclassified too. That's the honest framing; a future reader won't mistake it for an exact test.
  • queryKey shapeisQueryRemovedFromQueue now takes query and logs the unhashed query.queryKey plus requestId, matching every other this.logger call in the class. Passing both query and queryKeyHashed when the former is only for logging is a little redundant, but the alternative (hashing at the log site or logging the hash) is worse.
  • Test timing — deadline is 750ms against a 2s executionTimeout with a 10ms pausePromise step, and a miss now fails on expect(cancelableRejects.length).toEqual(1). Adequate margin; the failure mode is unambiguous.

Remaining low-severity notes (non-blocking)

# Location Note
1 QueryQueue.ts:1004-1009 Still a 6-line comment for one boolean. The load-bearing halves are "a missing queue item means the queue cancelled it" and "the lookup is after the fact, so a concurrent orphan reclassifies a real failure". The history/timeout sentences could go. Raising it once more only because the repo guideline is 3 lines; not worth another round on its own.
2 QueryQueue.ts:1010 Every non-timeout query error now costs an extra getQueryDef round trip when queryCancelled is false — a network call for the CubeStore queue driver. Errors are rare enough that this is fine, but it is a new call on the failure path.
3 QueryQueue.ts:1032 The warning string restates the event name. Harmless; it's what makes the event routable.

Verification

I read the code and traced the logger routing end to end in this checkout. I did not run the test suite or the linter here — the CubeStore variant of the queue suite needs Docker, and the packages aren't built in this environment. The author reports 147/147 on yarn unit plus clean lint and tsc --noEmit.

• Branch: `claude/athena-orphaned-query-cancel-mn3jor`

Copy link
Copy Markdown
Member Author

CI on 1d87e98: two red driver jobs, neither caused by this diff

Both are external-service auth failures in drivers this PR does not touch. The diff is confined to QueryQueue's log routing on the error path plus a unit test — it cannot produce either failure.

Check Failure Why it isn't this PR's
tests (mssql, false) ConnectionError: Login failed for user 'sa' — every suite fails to run The MSSQL container never accepted a login. No test body executed. Green on master's last run (bb15ec5).
integration (24.x, firebolt, true) Authenticator.authenticateServiceAccountmakeRequest fails in FireboltDriver.initConnection; the dependent "query should fail on timeout" assertion then fails too Firebolt's service-account auth endpoint rejected the request. Green on master's last run (bb15ec5).

Neither is red on the base branch, so there is no fix to port. Re-running the failed jobs once to confirm; a second failure would be treated as real.

Everything the diff can actually affect is green on this head: lint, build, unit (24.x, 3.13), unit-core, integration-cubestore (24.x). Locally, yarn unit in packages/cubejs-query-orchestrator is 147/147 with clean lint and tsc --noEmit.


Generated by Claude Code

Copy link
Copy Markdown
Member Author

Both re-runs passed — the two failures were transient, as expected

One check is still red and it is mine, not the code's: Upload merged coverage to Codecov on attempt 2 of the Build run, failing with Unable to download artifact(s). rerun_failed_jobs re-ran only the failed job, so the coverage merge had no artifacts from the 29 jobs that weren't re-run. It was green on attempt 1 of the same run, on this exact commit, and Codecov has already reported on the PR. Repainting it would mean re-running all 30 jobs, which isn't worth the CI, so I'm leaving it — it's why mergeable_state reads unstable rather than clean; required checks all pass.

Everything else on 1d87e98 is green, all four review threads are resolved, and there's nothing outstanding. Unsubscribing from PR activity; ping me here if you want changes and I'll pick it back up.


Generated by Claude Code

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

Labels

javascript Pull requests that update Javascript code

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants