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 "$@"