adapter: make statement logging single-owner for frontend sequencing

[aljoscha]

NOTE: This looks big, but a large chunk is moving tests around, in a separate commit.

Motivation

Part 3 of 7 in a stack that moves DELETE, UPDATE and INSERT ... SELECT
off the coordinator onto the session task, using optimistic concurrency
control.

This part is a restructuring, not a bugfix. A statement sequenced from the
session task has its end-of-execution logging obligation handed between
several places, and each of them can be the last one to hold it. Whether a log
row appears, and what reason it carries, depends on which path the statement
takes out of the session task. That is survivable while the only such
statement is a peek. It stops being survivable in part 6.

Read-then-write is a long-running operation, so part 6 bounds it with
cancellation and statement_timeout in a tokio::select! that drops the
operation's future when either fires. The obligation must not live inside that
future. If it does, dropping the future runs the guard's Drop, which reports
aborted with no message, and a user who just saw "canceling statement due to
statement timeout" finds a log row recording neither the error nor its text.
Hoisting the obligation into the frame beside the select! is what makes that
drop safe, which is why this lands before the path that needs it rather than
with it.

Closes SQL-589

Description

ExecutionLogging is a slot that owns the obligation for one
SessionClient::execute call, with a single retirement site that maps the
call's outcome to an end reason. Handing the statement back to the coordinator
passes the obligation as data in Command::Execute, and handle_execute arms
it again on receipt, which is safe because the command travels a channel only
the coordinator loop drains.

Three defects follow from the old structure and go away with it:

• an EXECUTE that unrolled to its inner statement got a guard whose retire
  channel was already dropped, so if that guard ever ran its Drop the end
  event went nowhere and the entry stayed open forever
• a statement whose future is dropped mid-flight was recorded as aborted
  rather than carrying its error
• a plan that passes the AST allowlist but then fails the plan-kind check
  bailed out after logging had begun, closing the frontend's entry as errored
  while the coordinator started its own from scratch, so one statement produced
  two log rows and counted query_total twice

None of the three is reachable from SQL on the peek path, which is why none of
them gets a test here. The first needs a drop in the few microseconds between
installing the guard and the takeover, or a shutdown. The second needs an inner
future for something to drop, and the peek path has none. The third sits behind
soft_panic_or_log. They are latent, which is the point: the caller that
reaches the second one arrives in part 6, which carries its tests.

Frontend-sequenced subscribes also start counting towards
mz_subscribe_outputs. The only site bumping it was handle_execute, which a
statement the frontend took over never reaches, and SessionMetrics had no
accessor for it, so those subscribes went uncounted. That is a behavior change
beyond the restructuring.

End events also move from Client::send, which panics when the coordinator is
gone, to a try_send that drops them. A guard can outlive the coordinator
during shutdown, and losing one end event is cheaper than panicking in Drop
and taking the connection with it. Every other logging event keeps the
asserting send.

end_statement_execution takes the end timestamp from its caller. The frontend
already recorded when execution finished and the handler discarded it, so
finished_at and the ExecutionFinished lifecycle event charged the statement
for however long its message waited in the coordinator's queue. The client
never waited for that queue, because the response leaves the session task while
the end event is a fire-and-forget send on an unbounded channel. began_at
already came from the frontend's clock, so the two ends of a statement's
duration were being read from different clocks.

Verification

test_statement_logging_finished_at_excludes_coordinator_queue covers the
finished_at change, which is the one thing here observable from SQL today. It
stalls the coordinator inside Catalog::transact and then runs a constant
SELECT from a session whose catalog snapshot is already warm, so the
statement needs nothing from the coordinator. The logged finished_at has to
fall before the client saw the statement return. On the old code it lands about
three seconds later.

All existing test_statement_logging_* tests are unchanged and pass. The
remaining tests for these paths are DML-specific and arrive with part 6, which
adds a harness asserting the frontend and coordinator paths produce the same
mz_statement_execution_history rows for the same statement, plus the
cancellation and statement-timeout tests that reach the latent defects above.

The second commit moves the existing tests out of server.rs into
statement_logging.rs. It is a pure move: every moved item is byte-identical
to its previous form, and the only other edits are the imports each file now
needs. server.rs was 7585 lines, of which the statement logging tests and
their harness were a contiguous 994-line block.

[linear-code]

SQL-589

[aljoscha]

hey aj, you're saying in the PR description that logging is wrong today, but we don't add any tests that show what's wrong, or anything that is fixed by our changes?

[aljoscha]

Fair hit, and checking it properly turned up that two of the four claims were wrong.

finished_at was the one that is testable today, and it now has a test.
test_statement_logging_finished_at_excludes_coordinator_queue stalls the
coordinator inside Catalog::transact with the existing failpoint, then runs a
constant SELECT from a session whose catalog snapshot is already warm, so the
statement never needs the coordinator. The logged finished_at has to fall
before the client saw the statement return. On the old code the end event waits
behind the stall and lands about three seconds late. The assertion cannot
false-fail on the fixed code, since both timestamps are taken in the session
task before the response goes out.

Two claims were wrong and I have rewritten them.

"A statement that failed before the frontend took it over produced no row" does
not reproduce. That was true before #36453, which added the up-front
begin_statement_logging in unroll_sql_execute; on current main an EXECUTE
whose unroll fails already gets an errored row. The one remaining no-row case is
a verify_portal failure, and that is deliberate and matches the coordinator,
which says so in a comment.

"End events were sent with try_send, so a full channel dropped them" is
backwards. There is no try_send anywhere in src/adapter on main, and
inner_cmd_tx is unbounded, so a full channel cannot happen. Main's send
panics. This PR is what introduces the try_send, deliberately, because a
guard can outlive the coordinator during shutdown and losing one end event beats
panicking in Drop. That is a real behavior change in the opposite direction
and it was hiding in a line claiming to fix a bug.

Two claims are real but not reachable from SQL today, so they get no test
here and the description now says so. The EXECUTE guard with a dead retire
channel needs a drop in the few microseconds between installing it and the
takeover, or a shutdown. The aborted-instead-of-error case needs an inner
future for something to drop, and the peek path has none: cancelled peeks are
retired by the coordinator as canceled, and the optimizer's statement_timeout
already retires as error. The caller that reaches both is the read-then-write
in part 6, which is where their tests live.

[aljoscha]

@ggevay we once again change statement logging, but this one actually looks quite decent 😅

[ggevay]

LGTM, nice cleanup of the logging-obligation handling.

[ggevay]

FYI, this closes a real gap in passing: before this commit, frontend-sequenced SUBSCRIBEs never bumped mz_subscribe_outputs. The only bump site in the tree was in handle_execute, which a taken-over statement never reaches, and SessionMetrics had no accessor for it. Worth a line in the PR description, since it is a small behavior change beyond restructuring.

[ggevay]

nit: "is not logged" threw me briefly. The statement's own entry is never begun, but an adopted outer entry still gets its Errored end from the retirement site in SessionClient::execute. Maybe "does not begin an entry, mirroring the coordinator"?

[ggevay]

Optional, and fine as a follow-up after the whole stack has landed: ExecuteContextGuard and StatementLoggingGuard are the same concept in two flavors, the armed end-of-execution obligation with a coordinator channel vs a session-task channel, but the names do not show the symmetry. Something like CoordStatementLoggingGuard vs FrontendStatementLoggingGuard would make it visible at a glance. We filed SQL-600 for a broader consolidation of these types (deferred until the stack lands), which would subsume this rename.

[aljoscha]

(This is aj, Aljoscha's agent, acting on his behalf. He's away, so replies here
are mine and he'll review when he's back.)

Both taken.

mz_subscribe_outputs is now in the description. You're right that it's a
behavior change and not just restructuring, and it deserved to be called out.
Verified it the way you described: at this PR's parent the only bump site is
handle_execute, which a taken-over statement never reaches, and
SessionMetrics had no accessor, so frontend-sequenced subscribes went
uncounted entirely. This is the second thing in this PR that was a real delta
hiding inside a "cleanup", after the try_send change, so thanks for reading it
that closely.

Comment reworded. Your reading is right and mine was sloppy, since "is not
logged" suggests nothing is recorded at all. It now says the failed verification
does not begin an entry, mirroring the coordinator, and notes explicitly that an
adopted outer entry still gets its Errored end from the retirement site in
SessionClient::execute.

On the guard naming, agreed on the substance: ExecuteContextGuard and
StatementLoggingGuard really are one concept in two flavors and the names hide
it. Leaving it to SQL-600 as you suggested, since renaming across the stack now
would churn parts 4 through 7 for no behavior change, and the consolidation
there is the better shape anyway.