Skip to content

fix(storage): fix the begin() leak at the source, not on release - #21

Merged
christianhuening merged 3 commits into
mainfrom
fix/after-release-log-flood
Sep 6, 2026
Merged

fix(storage): fix the begin() leak at the source, not on release#21
christianhuening merged 3 commits into
mainfrom
fix/after-release-log-flood

Conversation

@christianhuening

Copy link
Copy Markdown
Contributor

Release blocker for 0.5.0, and self-inflicted — this fixes a defect in #20.

#20 fixed the orphaned-transaction leak with an after_release hook issuing an
unconditional ROLLBACK. It works, and it is far too noisy to ship.

Postgres answers a ROLLBACK with no open transaction with WARNING: there is no transaction in progress. The common case is a clean connection, so nearly
every release produced one — logged twice over: sqlx maps the notice to a
tracing WARN on sqlx::postgres::notice, which knot's default info filter
passes, and Postgres writes it server-side because log_min_messages defaults
to warning, which an operator cannot turn off from inside knot.

Measured on an idle dev server:

log before after
knot 44053 / 44102 lines (99.9%) 0
postgres 23000 / 23031 lines (~767/min) 0 in a 60s sample

That buries every real error and fills disks.

Why not just make the ROLLBACK conditional

Because there is no reliable way to ask whether a connection is in a
transaction. sqlx guards its own rollback with the transaction status from
ReadyForQuery, but that accessor is pub(crate).

I tried the timestamp proxies and measured them rather than trusting the
reasoning. Both fail, in the direction that matters — on a clean connection:

proxy delta on a clean connection
now() vs statement_timestamp() ~60µs
pg_stat_activity.xact_start vs query_start ~685µs

Under the extended protocol the implicit transaction starts at Parse, slightly
before the statement timestamp. Either check would have fired on every release
— the same flood, just with extra steps. I had written the first one and a
confident comment explaining why it was exact before the test disproved it.

What this does instead

Fixes the defect where it happens. sqlx::Pool::begin is not cancellation-safe:
drop the future after BEGIN reaches Postgres but before begin() returns and
sqlx never receives a Transaction to roll back, and holds no record one is
open.

knot_storage::begin runs the BEGIN on a detached task. The caller can be
cancelled, but the task still runs to completion — so the Transaction is
always constructed and always dropped, and sqlx's own Drop issues the
ROLLBACK. All nine .begin() call sites move to it; the after_release hook
is deleted.

idle_in_transaction_session_timeout and application_name stay. The first is
a backstop; the second is what made the original diagnosis possible.

Tests

  • the_raw_pool_begin_is_not_cancellation_safe — characterises the upstream
    behaviour and fails if sqlx ever fixes it, which is the signal that the
    wrapper can be retired.
  • knot_begin_survives_cancellation — the guard. Checks after every
    cancellation, because a later successful begin()/rollback() on the same
    pooled connection would roll the orphaned transaction back and hide the bug.
  • The after_release-specific test in pool_hygiene.rs is deleted with the
    hook it pinned.

Verification

cargo fmt, clippy -D warnings, 340 nextest tests, targeted e2e (4/4),
and a 60-second sample against a running server: 0 warnings in either log,
0 stranded transactions.

🤖 Generated with Claude Code

christianhuening and others added 3 commits September 6, 2026 09:44
#20 fixed the orphaned-transaction leak with an `after_release` hook that
issued an unconditional ROLLBACK. That works, and it is far too noisy to ship.

Postgres answers a ROLLBACK with no open transaction with `WARNING: there is
no transaction in progress`, and the common case is a clean connection, so
nearly every release produced one. It was logged twice over: sqlx maps the
notice to a tracing WARN on `sqlx::postgres::notice`, which knot's default
`info` filter passes, and Postgres writes it server-side because
log_min_messages defaults to `warning` — which an operator cannot turn off
from inside knot. Measured on an idle dev server:

    knot log:      44053 of 44102 lines   (99.9%)
    postgres log:  23000 of 23031 lines   (99.9%, ~767/min)

That buries every real error and fills disks, so it is a release blocker.

Making the ROLLBACK conditional needs to know whether the connection is in a
transaction, and there is no reliable way to ask. sqlx guards its own rollback
with the transaction status from ReadyForQuery, but that accessor is
pub(crate). The timestamp proxies do not work either: under the extended
protocol the implicit transaction starts at Parse, so on a CLEAN connection
`now()` and `statement_timestamp()` differ by ~60us and pg_stat_activity's
`xact_start` and `query_start` by ~685us. Both were measured, and both would
have made the check fire on every release — the same flood.

So this fixes the defect where it happens instead. `sqlx::Pool::begin` is not
cancellation-safe: drop the future after BEGIN reaches Postgres but before
`begin()` returns, and sqlx never receives a `Transaction` to roll back and
holds no record one is open. `knot_storage::begin` runs the BEGIN on a
detached task, so the caller can be cancelled but the task still completes —
the `Transaction` is always constructed and always dropped, and sqlx's own
`Drop` issues the ROLLBACK. All nine `.begin()` call sites move to it.

The `after_release` hook is gone. `idle_in_transaction_session_timeout` and
`application_name` stay: the first is a backstop, the second is what made the
original diagnosis possible.

Tests split to match. `the_raw_pool_begin_is_not_cancellation_safe` pins the
upstream behaviour and fails if sqlx ever fixes it, which is when the wrapper
can be retired. `knot_begin_survives_cancellation` is the guard, checking
after every cancellation because a later successful begin()/rollback() on the
same pooled connection would roll the orphaned transaction back and hide it.
The `after_release`-specific test in pool_hygiene.rs is deleted with the hook.

Verified: fmt, clippy, 340 nextest tests, targeted e2e, and a 60s sample of a
running server — 0 warnings in either log, down from ~767/min, with no
stranded transaction.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Two timing bets in the cancellation tests, both of which passed on a Docker
Desktop VM and failed on CI, where Postgres is a host service.

a_cancelled_fetch_does_not_strand_its_connection used a fixed 3ms deadline
against an 8MB fetch. On CI the whole fetch landed first, so nothing was ever
cancelled — caught only because the test asserts that it WAS cancelled rather
than silently proving nothing. The deadline is now swept from microseconds
upward over a smaller payload, so some attempt lands mid-flight on any
hardware, and the stranding check runs after every cancellation instead of
once at the end.

knot_begin_survives_cancellation slept a fixed 2ms before checking. The
wrapper guarantees the transaction is always rolled back, not that it is
rolled back by any particular instant: the detached task still has to finish
its BEGIN and let Drop send the ROLLBACK. It now polls for the connection to
come clean with a 5s ceiling, which is still decisive — the bug it guards
against never resolves, at any deadline.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
the_raw_pool_begin_is_not_cancellation_safe reproduces by landing a
cancellation in the gap between BEGIN reaching Postgres and begin() returning,
and the width of that gap is connection latency. Against Postgres in Docker
Desktop it hits on the first cancellation. On CI, where Postgres is a host
service over loopback, 2997 cancelled calls stranded nothing.

That makes it useless as a gate: it cannot distinguish "sqlx fixed it
upstream" from "the window was never reachable here", which is the only
thing it exists to tell you. So it is #[ignore]d with instructions to run it
deliberately on a setup with real latency.

knot_begin_survives_cancellation stays as the CI gate, with a comment that is
honest about the same sensitivity: it is green everywhere and decisive where
the window exists, which is the setup that found the bug.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@christianhuening
christianhuening merged commit b1e1d5d into main Sep 6, 2026
5 checks passed
@christianhuening
christianhuening deleted the fix/after-release-log-flood branch September 6, 2026 08:51
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant