Repository navigation
proposal(gw): harden pool eviction — recoverable 391 on missing pool + type-owned last-used encoding - #691
Conversation
`ConnectionPool::last_used_nanos` holds nanoseconds since the process epoch, and that is how `last_used()` decodes it. Both acquisition paths were writing it with `EpochClock::almost_now_timestamp()`, which returns seconds since the UNIX epoch. Decoded as nanoseconds, that lands ~1.785s after process start and then advances a nanosecond per second, so the stamp was effectively frozen. `last_used().elapsed()` therefore measured process uptime rather than pool idleness. The reaper wakes every 300s and disposes pools idle beyond POSTGRES_POOL_DISPOSE_INTERVAL_SEC (7200s); with a frozen stamp the tick at t=7200s reads 7198.2s and spares the pool, and the tick at t=7500s reads 7498.2s and evicts it. From then on every user data pool is evicted regardless of how heavily it is in use, and re-evicted on each subsequent tick. `get_data_pool` cannot rebuild an evicted pool because the user password is not retained past authentication, so requests from an already-authenticated client fail from 2h05m of uptime onward. The client sees "An unexpected internal error has occurred."; only the gateway log carries "Connection pool missing for user." Route both acquisition paths through a single `touch_last_used` helper that writes the encoding `last_used` decodes. Use the precise `Instant::now()` rather than either coarse `EpochClock` reading: the coarse updater is a tokio task bound to whichever runtime first initialises the global clock, and the reaper's only input should not depend on that task still being alive. The syscall is ~20ns on a path that then checks out a pooled connection. Regression introduced in v0.114-0; v0.112-0 and v0.113-0 are unaffected. Adds three regression tests that fail on the unfixed code and a `wait_for_epoch_uptime` test helper that makes process uptime a controllable input. Validated by an 8h three-arm soak on documentdb-local:pg17-0.114.0 in which the arms differ only by this fix: stock v0.114.0 first failed at 2h05m00.3s and a locally built unmodified v0.114-0 at 2h05m00.1s, while the fixed build ran 8h and 28,680 operations with zero occurrences and its reaper ticking 97 times. Full methodology and results are in the PR. Signed-off-by: Guanzhou Song <guanzhousong@microsoft.com>
A missing data pool is not an internal fault. Pools are created at authentication - the only point where the user's password is available - and legitimately disappear when the reaper disposes of one idle past its threshold. The gateway cannot rebuild the pool on its own, but the client can, by re-authenticating. Previously get_data_pool returned InternalError, which reaches clients as "An unexpected internal error has occurred." with no recovery path: in the 8h soak run for the v0.114 reaper regression, a connection that hit this state failed 193 consecutive operations and never recovered until the client re-authenticated. Returning wire code 391 turns every variant of this state - a legitimately reaped idle pool, or any future eviction bug - from an opaque outage into an actionable re-auth request. This is the pre-existing gap noted as follow-up #1 in the reaper-regression fix: it exists on v0.112 as well and is not specific to that regression. The gateway log line now also states that re-authentication was requested rather than logging an anonymous internal error. Signed-off-by: Guanzhou Song <guanzhousong@microsoft.com>
The v0.114 reaper regression was possible because the pool's last-used stamp was a bare AtomicU64 whose encoding (nanoseconds since the process epoch) lived only in a comment, while the clock API offers two u64-shaped readings with different units and bases that look interchangeable at a call site. The hotfix narrowed the field to one writer and one reader; this goes the rest of the way and makes the mistake unrepresentable. AtomicInstant, in the time module, is a lock-free timestamp cell that can only hold "now": callers store the current instant and load an Instant back, and can never supply a raw integer in any unit. The connection pool now uses it for last_used, deleting the manual encode/decode from conn_mgmt entirely. Writes keep the precise Instant::now() for the same reason as the hotfix: a liveness decision must not depend on the coarse clock's updater task being alive on whichever runtime initialised it. Signed-off-by: Guanzhou Song <guanzhousong@microsoft.com>
|
Design reasoning — why this shape, and what was considered and rejected. Why 391 is the highest-leverage change here. The v0.114 incident was two defects compounding: a wrong timestamp (fixed in #690) and the fact that eviction of a referenced pool is unrecoverable. Fixing only the timestamp leaves the cliff: the >2h-idle path still walks off it today on every released version including 0.112, and any future eviction bug walks off it too. The 391 change is small, uses machinery that already exists (same code path as expired identity tokens), and caps the blast radius of this entire failure class at "client re-authenticates" instead of "client is broken until someone restarts something." Defense in depth for a part of the system that has now demonstrated it can fail. Alternatives considered for the missing-pool case:
One behavioural note reviewers should weigh: clients that previously saw a generic error now see 391. For drivers with automatic re-auth support this is strictly better; for others it surfaces as a clearer, actionable error instead of an opaque one. Either way the state was already fatal for the request — this cannot regress a request that would otherwise have succeeded. Why Why sketch 3 is a sketch and not code. Evicting on live-session count needs two decisions that belong to the gateway team: where the per-user connection count lives (connection context vs. pool manager), and the interaction with Validation status of this branch: 463/463 unit tests pass (including two new: missing pool → 391, and the full evict → 391 → re-auth → recover cycle), fmt/clippy clean, full workspace compiles. The 8h soak in the description was run against #690's hotfix; commits here change the error surface and encoding ownership, not the reaper decision logic, so the soak's conclusion carries over. If the team wants, the same three-arm rig is scripted and can re-run against this branch overnight. |
documentdb-triage-tool
Bot
added
documentation
1 participant
Description
Proposal PR — follow-up to #690, for gateway-team discussion. Stacks on that branch: the first commit here is #690's hotfix and will drop out on rebase once it merges. The two new commits implement the parts of the longer-term hardening that are small enough to review as code; the third piece is sketched below for discussion before anyone writes it.
This PR intentionally carries the full RCA in its description (below) rather than as a file in the repo, per review feedback on #690 that an RCA document doesn't belong in the OSS tree.
What this PR adds on top of the hotfix
1.
fix(gw): missing user pool →ReauthenticationRequired(391), notInternalErrorA missing data pool is not an internal fault. Pools are created at authentication — the only point where the user's password is available — and legitimately disappear when the reaper disposes of one idle past its 2h threshold. The gateway cannot rebuild the pool on its own, but the client can, by re-authenticating. Previously
get_data_poolreturnedInternalError, which reaches clients asAn unexpected internal error has occurred.with no recovery path: in the soak run below, a connection that hit this state failed 193 consecutive operations and never recovered until re-auth.Returning wire code 391 (
ReauthenticationRequired, already plumbed through the gateway's error machinery and used for expired identity tokens) converts every variant of this state — a legitimately reaped idle pool, or any future eviction bug — from an opaque outage into an actionable request. Note this gap predates the v0.114 regression and exists on v0.112: any client that authenticates and then idles >2h hits it today.2.
refactor(gw): the last-used stamp becomes anAtomicInstanttypeThe regression was possible because the stamp was a bare
AtomicU64whose encoding lived in a comment, while the clock API offers twou64-shaped readings with different units and bases that look interchangeable at a call site. The hotfix narrowed the field to one writer/one reader with warning comments; this goes the rest of the way:AtomicInstantis a lock-free cell that can only hold "now" — callers store the current instant and load anInstantback, and can never supply a raw integer in any unit. The bug class becomes unrepresentable, and the manual encode/decode disappears fromconn_mgmtentirely.3. Sketch only — evict on ground truth, not a proxy (requesting discussion)
The reaper currently asks "when was this pool last touched?" as a proxy for "is anyone using this?" — but the gateway holds the ground truth: connection contexts know which authenticated users have live connections. Tying eviction to live-session count per user (plus a grace period) would make the timestamp heuristic, and its entire category of encoding bugs, unnecessary.
This is also, I think, the constructive form of the session-idle-timeout point raised in review discussion: session lifecycle should drive pool cleanup — the current design's flaw is that it doesn't consult sessions at all (the pool is keyed by username; reaping an
lsiddoesn't touch it). Not implemented here because it needs a decision about where the per-user connection count lives and how it interacts withmax_connections; if the team likes the direction I'll draft it as its own PR.RCA (moved here from the repo file, per feedback)
Symptom
On v0.114+, any gateway process stays healthy until ~2h of uptime, then every request from already-authenticated users fails. Clients see
An unexpected internal error has occurred.or a hang; the gateway log showsConnection pool missing for user.Recurs every ~5 min for the life of the process. Reported by an external user whose 12–48h soak harness passed on 0.112 and failed at ~2h on 0.114 across multiple machines.Root cause — three layers
Proximate:
last_used_nanosis decoded as nanoseconds since the process epoch, but commitf02641fewrote it withEpochClock::almost_now_timestamp()— seconds since the UNIX epoch. Decoded, the stamp freezes ~1.785s after process start.last_used().elapsed()therefore measured process uptime, not pool idleness, and the reaper (300s ticks, 7200s threshold) evicted every user data pool once uptime passed the threshold: the t=7200s tick reads 7198.2s and spares the pool; the t=7500s tick evicts it → first failure at exactly 2h05m of uptime.Enabling: the type system never saw the bug. Two clock functions return
u64-shaped values in different units and bases; the field's contract lived in a doc comment; the atomic erased the rest. A careful reviewer approved the regressing PR because there was nothing visibly wrong at the call site. (Commit 2 of this PR addresses exactly this.)Systemic: pool lifetime is governed by a proxy heuristic while the gateway holds ground truth, and eviction sits on an unrecoverable cliff —
get_data_poolcan't rebuild without the password, so any eviction of a still-referenced pool becomes an opaque outage. The timestamp bug was the trigger; the cliff is what made it a customer-visible catastrophe. (Commit 1 removes the cliff; sketch 3 removes the proxy.)Why 2h05m exactly
Measured, not estimated: two independent broken builds first failed at 2h05m00.3s and 2h05m00.1s of gateway uptime. Consequence for testing: a 2-hour run sits below the trigger and passes on a fully broken build. Ask for 3 hours of continuous gateway uptime.
Empirical validation — 8h three-arm soak
Three arms on
documentdb-local:pg17-0.114.0, identical image/env/load, differing only in the gateway binary (verified by md5 in each container). Predictions, including the t=7500s tick, were recorded before the run.The
unfixedarm validates the method: same build-and-swap pipeline asfixed, so its on-schedule failure attributes the clean result to the fix, not the pipeline. Load was one long-lived authenticated connection per arm at 1 op/s — long-lived becauseget_data_poolonly fails for clients authenticated before eviction; per-op reconnects would re-allocate the pool and mask the bug.Recovery/recurrence observed directly: a fresh client on the broken control arm ran 226 clean ops (re-auth rebuilds the pool), then failed at the next predicted reaper tick —
OKat 05:39:53.2Z,FAILat 05:39:55.2Z, tick due 05:39:54.5Z. The failing connection was 3.8 minutes old, and once broken never self-healed (193 consecutive failures).On the session-idle-timeout question
Raised in review: could this be about connections outliving MongoDB's 30-minute session idle timeout? The soak data says no on every axis: the failing connection was 3.8 minutes old (only needs to outlive one 5-min reaper tick); the load client was never idle (1 op/s) and was evicted anyway; the pool is keyed by username, not
lsid, so session reaping doesn't touch it; and granting 30-min recycling arithmetic still fails ~92% of operations (first tick lands ~150s after auth, everything fails until recycle at 1800s). The "2 hours" is process uptime — a different clock from connection age entirely.Detection gaps worth keeping
An unexpected internal error has occurred.A client-side detector is blind; grep the gateway log. (An early watcher in this investigation did exactly that and reported a false negative for 3 hours while the bug reproduced perfectly.)wait_for_epoch_uptime) instead of something to wait out.Type of Change
AI Disclosure
Checklist
git commit -s)