fix(querylog): correct the ExceptionBeforeStart boundary, classify CALL - #1014
Merged
Conversation
Both findings come from reading the query log on prod tenants after the rollout. ExceptionBeforeStart was documented as "failed before any engine saw it". That is wrong, and not marginally: every one of the ~92/day ExceptionBeforeStart events on the tenant I sampled is an extended-protocol Describe whose prepare the worker rejected with a binder error. Describe hands the statement to a worker to learn its result schema, so the engine does see it — it just never runs. The boundary the code actually implements is "execution began" (execStarted, set at queryContextInner), which is both correct and the same line ClickHouse draws: analysis-time failures are ExceptionBeforeStart. Since this is the LARGEST source of the class, "never reached a worker" would have sent triage the wrong way. No behaviour change — the classification was right, the words around it were not. Verified against prod: 0 of 92 have a paired QueryStart, so the "no start event" invariant holds. querymeta had no case for CALL, so it fell to the default branch and came back access_kinds=unknown WITH metadata_complete=false. Unknown was right; incomplete was not. A procedure body is invisible to any parser, so "parsed, but its access is opaque" is a different fact from "we could not parse it" — both deny, but only the second is fixable by a better parser, and conflating them turns an allowlistable procedure call into a parser bug report. CALL is now handled explicitly: unknown access, complete extraction, and the procedure name recorded so a policy can allowlist specific procedures instead of refusing CALL wholesale. Verified the whole chain before asserting on it: pg_query parses CALL as CallStmt, the transpiler passes it through unchanged, and DuckDB executes it — so the e2e assertion is a hard one, not a tolerant skip. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FQWUvX5Hkvx2mRhCg8JECv
Test Impact PlanDeterministic summary of how this PR changes tests, CI runners, and coverage-risk signals. Summary
Signals
Coverage risk: neutral or increased No coverage-reduction warnings detected. |
benben
approved these changes
Jul 30, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Two fixes, both found by reading
query_logon prod tenants after #1002 rolled out. No behaviour change to the event model itself; one doc correction and one extraction gap.1.
ExceptionBeforeStartwas documented wrong#1002 described the class as "failed before any engine saw it". That's inaccurate, and not marginally — it's wrong for the largest population of the class.
Sampling one prod tenant over 24h: all 92
ExceptionBeforeStartevents areprotocol=extendedcarryingflight execute: rpc error … failed to prepare query: Binder Error. That's the extended-protocolDescribepath, which hands the statement to a worker to learn its result schema. The engine does see the SQL — it just never runs it.The boundary the code actually implements is "execution began" (
execStarted, set atqueryContextInner), which is correct and is the same line ClickHouse draws: analysis-time failures areExceptionBeforeStart. So the classification was right; only the words around it were wrong. Left as-is, "never reached a worker" would send triage looking in the wrong place for the most common case.Corrected in
query_event.go,query_metrics.go,querylog.go,README.md, and the design doc, each stating the boundary and naming the Describe case explicitly.Prod also confirms the paired invariant holds: 0 of 92
ExceptionBeforeStartrows have aQueryStart.2.
CALLwas classified as an incomplete extractionquerymetahad no case forCallStmt, so it fell to the default branch:access_kinds=unknownwithmetadata_complete=false. Four occurrences over 7 days on the sampled tenant.unknownwas right.incompletewas not. A procedure body is invisible to any parser, so:Both deny under a future gate, but only the second is fixable by a better parser — and conflating them turns an allowlistable procedure call into what looks like a parser bug.
CALLis now handled explicitly, and the procedure name is recorded so a policy can allowlist specific procedures rather than refusingCALLwholesale.Verification
Verified the chain before writing a hard e2e assertion around it:
pg_queryparsesCALL pragma_version()asCallStmt,querymetareturnskinds=[unknown] complete=true funcs=[pragma_version], the transpiler passes it through unchanged, and DuckDB executes it. So the harness gets a real assertion, not a tolerant skip.TestExtractCallStatement,TestUnknownAccessDistinguishesOpaqueFromUnparseable(pins opaque-vs-unparseable as distinct facts).query_log_access_metadata): aCALLmust logaccess_kinds=unknownwithmetadata_complete=true../server/...suite green; golangci-lint v2.11.4 clean on./server/....Prod observation, not addressed here
Those binder errors are pre-existing, not a regression: the 24h window before the #1002 rollout has 94 identical
XX000errors (labelledExceptionWhileProcessingunder the old blanket rule); after, 92 labelledExceptionBeforeStart. Same volume — the new classification just made them legible. Some extended-protocol client with noapplication_nameis sending SQL DuckDB can't bind, ~92×/day on one tenant. Worth tracing separately.🤖 Generated with Claude Code
https://claude.ai/code/session_01FQWUvX5Hkvx2mRhCg8JECv