From 4d9ce9e2e4bfa8c6f30ca2bf7af0e151ee89f953 Mon Sep 17 00:00:00 2001 From: James Greenhill Date: Thu, 30 Jul 2026 09:20:20 +0000 Subject: [PATCH] fix(querylog): correct the ExceptionBeforeStart boundary, classify CALL MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) Claude-Session: https://claude.ai/code/session_01FQWUvX5Hkvx2mRhCg8JECv --- README.md | 15 ++++++++-- docs/design/query-log-metadata.md | 23 +++++++++----- server/query_event.go | 15 ++++++---- server/query_event_test.go | 4 +-- server/query_metrics.go | 10 +++++-- server/querylog.go | 2 +- server/querymeta/querymeta.go | 22 ++++++++++++++ server/querymeta/querymeta_test.go | 48 ++++++++++++++++++++++++++++++ tests/mw-dev/README.md | 6 ++-- tests/mw-dev/e2e/harness.sh | 20 ++++++++++++- 10 files changed, 142 insertions(+), 23 deletions(-) diff --git a/README.md b/README.md index aac942e5..b6cdf54b 100644 --- a/README.md +++ b/README.md @@ -131,9 +131,18 @@ Statements produce a pair of events, using ClickHouse's `type` vocabulary - `QueryStart` is emitted when the statement begins executing. - One terminal event follows: `QueryFinish`, or `ExceptionWhileProcessing` if it - failed after execution began, or `ExceptionBeforeStart` if it failed before - any engine saw it (auth or policy denial, a transpile error, a rejected - Describe). `ExceptionBeforeStart` events have no `QueryStart`, by definition. + failed after execution began, or `ExceptionBeforeStart` if it failed **before + execution began** — auth or policy denial, a transpile error, a failure to + obtain a worker, or an extended-protocol `Describe` whose prepare the engine + rejected. `ExceptionBeforeStart` events have no `QueryStart`, by definition. + + The boundary is *execution began*, not *an engine saw it*: `Describe` hands + the statement to a worker to learn its result schema, so a binder error there + is an `ExceptionBeforeStart` even though the engine did see the SQL. This is + the same line ClickHouse draws — analysis-time failures are + `ExceptionBeforeStart`. In practice this is the largest source of them, so + when triaging, read `ExceptionBeforeStart` as "never ran", not as "never + reached a worker". **A `QueryStart` with no terminal event is a query that never came back** — a worker OOM-killed mid-statement, a pod evicted. That row is the only evidence diff --git a/docs/design/query-log-metadata.md b/docs/design/query-log-metadata.md index e302cc9a..348fc591 100644 --- a/docs/design/query-log-metadata.md +++ b/docs/design/query-log-metadata.md @@ -46,7 +46,7 @@ Three things, in dependency order: (UUIDv7) per inbound statement and emits a `QueryStart` row; the component that actually executes emits the terminal row (`QueryFinish` / `ExceptionWhileProcessing`), or the CP emits `ExceptionBeforeStart` if the - statement never reached an engine. Same `Enum8` vocabulary as CH: + statement never began executing. Same `Enum8` vocabulary as CH: `QueryStart=1, QueryFinish=2, ExceptionBeforeStart=3, ExceptionWhileProcessing=4`. 2. **Extract what the statement touches** — catalog / schema / table / column — and **what kind of access it is** (read, write, DDL, config, admin). @@ -141,15 +141,22 @@ stays CH-faithful; the nuance lives beside it. Note this reclassifies today's behaviour: `logQuery` currently stamps `ExceptionWhileProcessing` whenever `errCode != ""`, including for transpile -errors and policy denials that never reached an engine. Those become +errors and policy denials that never began executing. Those become `ExceptionBeforeStart`. The rule is mechanical — `execStartAt.IsZero()`. +**The boundary is "execution began", not "an engine saw it."** Prod data settled +this: the largest population of `ExceptionBeforeStart` is an extended-protocol +`Describe` failing at prepare with a binder error — the statement reaches the +worker (Describe asks it for the result schema) and still never runs. Reading the +class as "never reached a worker" would mislead triage. ClickHouse draws the line +the same way: analysis-time failures are `ExceptionBeforeStart`. + ### 2.2 Who emits what ``` CP: mint query_id (UUIDv7) ├─ extract metadata (§3), emit QueryStart [type=1] - ├─ never reached an engine → emit ExceptionBeforeStart [type=3] ← CP owns + ├─ never began executing → emit ExceptionBeforeStart [type=3] ← CP owns └─ dispatched to engine, propagate query_id │ ▼ @@ -167,10 +174,12 @@ CP: mint query_id (UUIDv7) CP's trailer-based capture is unreliable. - It survives CP-side abandonment: client disconnect mid-query, CP pod eviction. -**Why the CP still owns `ExceptionBeforeStart`:** by definition those statements -have no engine. Auth failure, transpile error, policy denial, DML-RETURNING -Describe rejection, worker acquisition failure at org cap — the worker does not -know the statement exists. +**Why the CP still owns `ExceptionBeforeStart`:** the engine either never sees +these statements or never runs them, so it cannot report their outcome. Auth +failure, transpile error, policy denial, worker acquisition failure at org cap — +the worker does not know the statement exists. An extended-protocol `Describe` +rejected at prepare does reach the worker, but only as a schema probe: there is +no execution whose end the worker could report. **Honest limitation:** the highest-frequency incident — worker OOM-killed by its own heavy query — is precisely the case where the engine *cannot* emit. That is diff --git a/server/query_event.go b/server/query_event.go index e5ebbfb6..16a83ef5 100644 --- a/server/query_event.go +++ b/server/query_event.go @@ -14,10 +14,15 @@ const ( QueryEventStart = "QueryStart" // QueryEventFinish is a statement that completed and returned to the client. QueryEventFinish = "QueryFinish" - // QueryEventExceptionBeforeStart is a statement that failed before any - // engine saw it: auth or policy denial, a transpile error, a rejected - // Describe, or a failure to obtain a worker. There is no QueryStart for - // these, by definition. + // QueryEventExceptionBeforeStart is a statement that failed BEFORE + // EXECUTION BEGAN: auth or policy denial, a transpile error, a failure to + // obtain a worker — and, in practice most often, an extended-protocol + // Describe whose prepare the engine rejected (a binder error). That last + // case is why the boundary is "execution began", not "an engine saw it": + // Describe hands the statement to the worker to learn its result schema, so + // the engine does see it, and it still never runs. ClickHouse draws the + // line the same way — analysis-time failures are ExceptionBeforeStart. + // There is no QueryStart for these, by definition. QueryEventExceptionBeforeStart = "ExceptionBeforeStart" // QueryEventExceptionWhileProcessing is a statement that failed after // execution began. @@ -43,7 +48,7 @@ func queryEventCode(eventType string) uint8 { // terminalQueryEventType classifies a completed statement. // // execStarted is what separates the two exception types: a statement that -// failed before the engine saw it is ExceptionBeforeStart, and it has no +// failed before execution began is ExceptionBeforeStart, and it has no // QueryStart row to pair with. Callers with no observation scope pass // execStarted=true, which keeps the pre-existing behaviour of labelling every // failure ExceptionWhileProcessing rather than inventing a diff --git a/server/query_event_test.go b/server/query_event_test.go index b40e437c..5f43e3b6 100644 --- a/server/query_event_test.go +++ b/server/query_event_test.go @@ -19,7 +19,7 @@ func TestTerminalQueryEventType(t *testing.T) { {"success", "", true, QueryEventFinish}, {"success without exec", "", false, QueryEventFinish}, {"failure after exec began", "42P01", true, QueryEventExceptionWhileProcessing}, - {"failure before any engine saw it", "42601", false, QueryEventExceptionBeforeStart}, + {"failure before execution began", "42601", false, QueryEventExceptionBeforeStart}, } for _, tc := range cases { t.Run(tc.name, func(t *testing.T) { @@ -291,7 +291,7 @@ func TestExecutionPathEmitsQueryStart(t *testing.T) { if !scope.execStarted { t.Fatal("reaching an engine must mark the statement as started") } - // Having reached an engine, a later failure is ExceptionWhileProcessing. + // Execution having begun, a later failure is ExceptionWhileProcessing. c.logQuery(scope.start, "UPDATE foo SET x = 1", "", "UPDATE", 0, 0, "XX000", "boom", "simple") last := exec.entries[len(exec.entries)-1] if last.Type != QueryEventExceptionWhileProcessing { diff --git a/server/query_metrics.go b/server/query_metrics.go index 2009265a..c9aa0710 100644 --- a/server/query_metrics.go +++ b/server/query_metrics.go @@ -59,11 +59,17 @@ type queryMetricsScope struct { // event. For a batched simple query it is the individual statement, not the // whole message. queryText string - // execStarted records that the statement reached an engine. It is what + // execStarted records that the statement began EXECUTING. It is what // separates ExceptionBeforeStart from ExceptionWhileProcessing, and it is // set at the single point where a query becomes cancellable // (queryContextInner) so every execution path — simple, batched, extended, // COPY, cursor — marks it without its own call. + // + // Note this is narrower than "an engine saw the statement": the + // extended-protocol Describe path prepares the statement on the worker to + // learn its result schema without going through queryContextInner, so a + // binder error there is correctly ExceptionBeforeStart even though the + // engine did see it. execStarted bool // startLogged guards QueryStart emission so a statement that takes several // cancellable contexts (COPY, cursor FETCH) still logs exactly one start. @@ -123,7 +129,7 @@ func (c *clientConn) endStatementScope(scope *queryMetricsScope) { } } -// markExecStarted records that the statement reached an engine, and emits its +// markExecStarted records that the statement began executing, and emits its // QueryStart event the first time. Both happen here because this is the same // instant: the query has become cancellable, so it is live from the client's // point of view, and any failure from now on is ExceptionWhileProcessing. diff --git a/server/querylog.go b/server/querylog.go index ea85c00e..850170ee 100644 --- a/server/querylog.go +++ b/server/querylog.go @@ -508,7 +508,7 @@ func (c *clientConn) logQuery(start time.Time, query, transpiledQuery, cmdType s query = usersecrets.RedactForLog(query) transpiledQuery = usersecrets.RedactForLog(transpiledQuery) - // A failure that never reached an engine is ExceptionBeforeStart and has no + // A failure before execution began is ExceptionBeforeStart and has no // QueryStart row to pair with. Without a scope we cannot know, so assume // the statement started — claiming it never did would be a stronger // statement than the evidence supports. diff --git a/server/querymeta/querymeta.go b/server/querymeta/querymeta.go index c007c203..66cbed67 100644 --- a/server/querymeta/querymeta.go +++ b/server/querymeta/querymeta.go @@ -419,6 +419,28 @@ func (e *extractor) statement(node *pg_query.Node, cte map[string]struct{}) { e.setKind(KindOther) e.addKind(AccessAdmin) + case *pg_query.Node_CallStmt: + // CALL invokes a procedure whose body extraction cannot see, so the + // access it performs is genuinely undeterminable — AccessUnknown, which + // is what a gate denies on. + // + // It is NOT marked incomplete: the statement parsed fine and we saw all + // of it. "Parsed, but its access is opaque" and "we could not parse it" + // are different facts and must stay distinguishable — a consumer that + // treats incomplete as "retry with a better parser" would be wrong here, + // because no parser can see inside the procedure. Both still deny. + // + // The procedure name is recorded so a policy can allowlist specific + // procedures rather than refusing CALL wholesale. + e.setKind(KindOther) + e.addKind(AccessUnknown) + if call := stmt.CallStmt.Funccall; call != nil { + e.addFunction(functionName(call)) + for _, arg := range call.Args { + e.read(arg, cte) + } + } + default: // An unrecognized statement type is recorded as unknown rather than // ignored: a future gate must see that we could not classify it. diff --git a/server/querymeta/querymeta_test.go b/server/querymeta/querymeta_test.go index 99efa9b0..4a649c21 100644 --- a/server/querymeta/querymeta_test.go +++ b/server/querymeta/querymeta_test.go @@ -432,3 +432,51 @@ func TestExtractHandlesEmptyAndGarbage(t *testing.T) { } } } + +// TestExtractCallStatement covers a statement type real prod traffic hit that +// extraction had no case for. A procedure's body is invisible to us, so its +// access is undeterminable — but the statement itself parses, and that +// distinction has to survive into the result. +func TestExtractCallStatement(t *testing.T) { + meta := Extract("CALL my_schema.rebuild_rollups(1, 'daily')") + + if !meta.HasKind(AccessUnknown) { + t.Fatalf("a procedure body is opaque, so access is unknown; got %v", meta.AccessKinds) + } + // "We parsed it but cannot see what it does" is NOT the same fact as "we + // could not parse it". A consumer must be able to tell them apart; both + // deny, but only one is fixable by a better parser. + if !meta.Complete { + t.Fatalf("CALL parses fine — it must not be reported as an incomplete extraction (%s)", + meta.IncompleteReason) + } + // The procedure name lets a policy allowlist specific procedures instead of + // refusing CALL wholesale. + found := false + for _, fn := range meta.Functions { + if fn == "rebuild_rollups" { + found = true + } + } + if !found { + t.Fatalf("the called procedure must be recorded, got functions %v", meta.Functions) + } +} + +// TestUnknownAccessDistinguishesOpaqueFromUnparseable is the property the CALL +// case exists to protect: both deny, but they are different facts. +func TestUnknownAccessDistinguishesOpaqueFromUnparseable(t *testing.T) { + opaque := Extract("CALL do_something()") + unparseable := Extract("PIVOT main.events ON kind USING sum(v)") + + if !opaque.HasKind(AccessUnknown) || !opaque.Complete { + t.Fatalf("opaque-but-parsed should be complete+unknown, got complete=%v kinds=%v", + opaque.Complete, opaque.AccessKinds) + } + if unparseable.Complete { + t.Fatal("unparseable input must be reported incomplete") + } + if unparseable.IncompleteReason == "" { + t.Fatal("an incomplete extraction must say why") + } +} diff --git a/tests/mw-dev/README.md b/tests/mw-dev/README.md index 68d044fe..0d84d0ab 100644 --- a/tests/mw-dev/README.md +++ b/tests/mw-dev/README.md @@ -185,9 +185,11 @@ normal `go test ./...` lane. - **query log access metadata** — a `SELECT` and an `INSERT` over the same table must log different `access_kinds` and land in `read_relations` / - `write_relations` respectively, and a DuckDB-native statement the PostgreSQL + `write_relations` respectively; a DuckDB-native statement the PostgreSQL parser rejects must log `metadata_complete=false` rather than an empty - relation list. These are the signals a future authorization policy will be + relation list; and a `CALL` must log `access_kinds=unknown` with + `metadata_complete=true` — parseable but opaque, which is a different fact + from unparseable even though both deny. These are the signals a future authorization policy will be evaluated against, so "referenced nothing" and "we could not tell" have to stay distinguishable on real traffic, not just in unit fixtures. diff --git a/tests/mw-dev/e2e/harness.sh b/tests/mw-dev/e2e/harness.sh index e3441e16..e8aba179 100755 --- a/tests/mw-dev/e2e/harness.sh +++ b/tests/mw-dev/e2e/harness.sh @@ -3669,6 +3669,24 @@ query_log_access_metadata() { # org password log "query_log_access_metadata: no row for $marker_n (statement may have been rejected pre-log); skipping incomplete check" fi + # A CALL is parseable but its procedure body is not: access must come back + # `unknown` while metadata_complete stays TRUE. This pins the distinction the + # extraction depends on — "parsed, but its access is opaque" is a different + # fact from "we could not parse it", and only the latter is fixable by a + # better parser. Both deny, so conflating them would quietly turn an + # allowlistable procedure call into a parser bug report. + marker_c="qlcall_$(date +%s)_$$" + pg "$1" "$2" ducklake "CALL pragma_version() /* $marker_c */" >/dev/null + crow="$(ql_meta_row "$1" "$2" "$marker_c")" || fail "query_log_access_metadata: no row for $marker_c" + case "$crow" in + unknown\|*) : ;; + *) fail "query_log_access_metadata: CALL access_kinds should be 'unknown' (row: $crow)" ;; + esac + case "$crow" in + *"|true|"*) : ;; + *) fail "query_log_access_metadata: CALL parses, so metadata_complete must be true (row: $crow)" ;; + esac + pg_try "$1" "$2" ducklake "DROP TABLE IF EXISTS $tbl" >/dev/null 2>&1 || true log "query_log access metadata OK on $1" } @@ -3877,7 +3895,7 @@ main() { # mid-run image bump); it stays covered by the controlplane/ unit tests. log "SKIP version-reaper (needs an in-run image bump; see README)" - log "PASS: admin-no-query-token + models-explorer-api(redaction) + admin-console-api(me/live/metrics/auth-gate) + admin-rbac-viewer(403 mutate/audit) + admin-impersonation(round-trip+audit) + project-reader(team-wide-read/cross-project-deny/read-only/legacy-override-grant) + project-user(in-project-dml+ddl/cross-project-deny/unqualified-target-deny/namespace-ddl-deny/reader-stays-read-only) + wire + binary-copy(native+fallback+route-guard+rollback) + malformed-startup-resilience + jsonb-concat + cold-burst-absorption + pipeline-error-recovery + cancel-reuse + activation(DuckLake) + ducklake-explain + ext-forks + worker-pod + concurrency + durability + crash-recovery + busy-only-do-not-disrupt + graceful-drain + one-session-per-worker + parallel-cold-burst-ramp + worker-sizing(cnpg DuckLake) + org-default-profile(cnpg) + persistent-user-secrets(cnpg, cross-user isolation) + user-kill-switch(cnpg) + user-disable-block(cnpg) + connection-duration-logged + compute-usage-pull-api(cnpg, compute+storage) + query-log-round-trip(cnpg, view+query_id+QueryStart/terminal pair) + query-log-access-metadata(read/write split + incomplete-not-empty) + duckling-shard-backfill(cnpg) + isolation + lifecycle-teardown(+org-delete/name-release), on cnpg (3 parallel lanes)" + log "PASS: admin-no-query-token + models-explorer-api(redaction) + admin-console-api(me/live/metrics/auth-gate) + admin-rbac-viewer(403 mutate/audit) + admin-impersonation(round-trip+audit) + project-reader(team-wide-read/cross-project-deny/read-only/legacy-override-grant) + project-user(in-project-dml+ddl/cross-project-deny/unqualified-target-deny/namespace-ddl-deny/reader-stays-read-only) + wire + binary-copy(native+fallback+route-guard+rollback) + malformed-startup-resilience + jsonb-concat + cold-burst-absorption + pipeline-error-recovery + cancel-reuse + activation(DuckLake) + ducklake-explain + ext-forks + worker-pod + concurrency + durability + crash-recovery + busy-only-do-not-disrupt + graceful-drain + one-session-per-worker + parallel-cold-burst-ramp + worker-sizing(cnpg DuckLake) + org-default-profile(cnpg) + persistent-user-secrets(cnpg, cross-user isolation) + user-kill-switch(cnpg) + user-disable-block(cnpg) + connection-duration-logged + compute-usage-pull-api(cnpg, compute+storage) + query-log-round-trip(cnpg, view+query_id+QueryStart/terminal pair) + query-log-access-metadata(read/write split + incomplete-not-empty + CALL opaque-but-complete) + duckling-shard-backfill(cnpg) + isolation + lifecycle-teardown(+org-delete/name-release), on cnpg (3 parallel lanes)" } main "$@"