fix(querylog): correct the ExceptionBeforeStart boundary, classify CALL

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

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

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

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 {

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.

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.

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.

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")
+	}
+}

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.
 

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