Skip to content

test(testutil): wait for a login through PgBouncer before returning its URL - #112

Merged
Kiran01bm merged 4 commits into
mainfrom
kiran01bm/pgbouncer-fixture-readiness
Sep 13, 2026
Merged

test(testutil): wait for a login through PgBouncer before returning its URL#112
Kiran01bm merged 4 commits into
mainfrom
kiran01bm/pgbouncer-fixture-readiness

Conversation

@Kiran01bm

Copy link
Copy Markdown
Collaborator

Why

The PgBouncer fixture waited only for the pooler's published port to be listening. Docker's host-side port forwarder accepts a client before PgBouncer inside the container does, so a test client that arrived in that window was accepted and then cut off on its first read — surfacing in CI as read: connection reset by peer in the pkg/dbconn session-state tests, intermittently across PostgreSQL versions.

What

StartPostgresBehindPgBouncer now polls until a login through the pooler runs SELECT 1 on the server behind it — the property the returned URL promises — with a named deadline and poll interval, and fails with the last login error if that never happens. No test timeouts were changed.

Verification

  • scripts/test-flaky.sh TestNewPoolRefusesAConnectionThatDiscardsSessionTimeouts 20 ./pkg/dbconn/ — 20/20 pass
  • go test -race -run TestNewPool ./pkg/dbconn/ — both pool-mode tests pass
  • make lint — 0 issues

…ts URL

StartPostgresBehindPgBouncer waited only for the pooler's port to be
listening. The host side of a published port accepts a client before the
container's process does, so a client that arrived in that window was cut
off on its first read, which surfaced as a connection reset in the tests
that use the fixture. The fixture now polls until a login through the
pooler runs a statement on the server behind it — the property the
returned URL promises — and reports the last login error if that never
happens.

Amp-Thread-ID: https://ampcode.com/threads/T-01a07fb2-9632-732b-bd7b-2f143a81bc06
@Kiran01bm
Kiran01bm marked this pull request as ready for review September 13, 2026 08:06
@chatgpt-codex-connector

Copy link
Copy Markdown

You have reached your Codex usage limits for code reviews. You can see your limits in the Codex usage dashboard.

@aparajon

Copy link
Copy Markdown
Collaborator

🤖 Adversarial review 1/2 — does the readiness wait hold in the failure it guards against? 9049d2f7, 1 file, +41/−2.

The change is right in kind: a bound port is not readiness, and the property the returned URL promises is a login that reaches the server behind the pooler. Two things about this wait do not survive contact with the state it exists for, and both are cheap.

What I ran. go build ./..., go vet ./internal/testutil/, gofmt -l — clean. TestNewPoolRefusesAConnectionThatDiscardsSessionTimeouts and TestNewPoolAcceptsSessionPooling pass on this head. Mutation testing on internal/testutil/pgbouncer.go, six mutations, two caught:

Mutation Result
poolerReadyDeadline → 1 ns CAUGHT
probe pointed at a dead endpoint CAUGHT
awaitPooledLogin never called SURVIVED
probe stops at login, never runs SELECT 1 SURVIVED
a failed login no longer short-circuits before the deferred close SURVIVED
poolerReadyPoll longer than the deadline SURVIVED

The survivors are expected — no test fails on a race that did not happen on that run — but they are why the two constants and the probe body are held in place by their comments alone, and both findings below are about exactly those.


1. The deadline is shorter than PgBouncer's own login timeout, so in the failure this guards against the probe makes one attempt and reports no error

I reproduced the state the wait exists for: the pinned image, published, with DB_HOST pointed at a name that does not resolve — the pooler up, the server behind it not reachable.

testcontainers' internal check (6432 = 0x1920)   00000000:1920   exit=0
host-side dial to the published port             OK
a pgx login through it                           failed to receive message: timeout

PgBouncer's own log says what it did with that client:

LOG     C-0x…: postgres/postgres@…:65487 closing because: client_login_timeout (server down) (age=60s)
WARNING C-0x…: pooler error: client_login_timeout (server down)

It parks a client whose server is not yet available and closes it after client_login_timeout60 s by default. poolerReadyDeadline is 30 s, and pgx.Connect runs on t.Context() with no bound of its own. Two consequences follow, and I measured both:

  • EventuallyWithT re-arms its ticker only when the previous condition goroutine returns — in testify v1.11.1 tickC = ticker.C is set solely on the case collect := <-ch arm. One parked attempt therefore consumes the entire budget: one attempt in 30 s, and poolerReadyPoll never applies. The surviving "poll interval longer than the deadline" mutation is the same fact seen from the other side.
  • lastFinishedTickErrs stays empty, so nothing is copied onto t. The description's "fails with the last login error if that never happens" holds only when attempts terminate.

Calling awaitPooledLogin against that bound-but-unserving pooler, beside a control that refuses instantly:

hung pooler (the real case)   Error:    Condition never satisfied
                              Messages: the pooler did not accept a login that reached the server within 30s
                              — no login error reported at all

refused endpoint (control)    Error:    Received unexpected error:
                                        … dial error: dial tcp 127.0.0.1:1: connect: connection refused
                              Messages: log in through the pooler

The case where a CI reader most needs the reason is the one that produces none, and the 30 s buys a single attempt rather than three hundred. The fix is a per-attempt bound, not a bigger deadline: a context.WithTimeout of a few seconds around each attempt makes the poll interval mean something again and leaves a real error behind every tick. Raising poolerReadyDeadline past 60 s would let the wait eventually succeed but would still report one attempt and no retries.

2. The cause both new comments name is not the one left open here

:128-130 and :149-151 both attribute the window to Docker's host-side forwarder — "accepts a client before the container does", "accepted by the port forwarder and then cut off on its first read". For this image and this pinned testcontainers, that window is already closed by the wait strategy being replaced.

wait.ForListeningPort is HostPortStrategy, and in testcontainers-go v0.43 it runs an internal check after the external dial: Execing /bin/sh -c in the container to grep the port out of /proc/net/tcp*, falling back to nc -vz localhost <port> from inside. It degrades to the host dial alone only when /bin/sh is missing or not executable, and then it just logs and returns nil. edoburu/pgbouncer:v1.25.2-p0 ships /bin/sh -> /bin/busybox and a readable /proc/net/tcp, and the strategy's exact command exits 0 against it (above). So by the time the old wait returned, PgBouncer had bound 6432 inside the container — the forwarder was not running ahead of it.

What is left open is PgBouncer's own state, and its log names it: bound and accepting is not the same as having a usable server pool, so it holds the client and closes it with server down. That is a better argument for this PR than the one in the comment — an EOF a full minute after connect looks far more like a broken pooler than an early caller does. Worth correcting in the code, since the comment is the durable artifact here and the next person to debug a fixture flake will start from it. The silent degradation is worth a clause too: it is precisely the path that would make the comment true, and it makes no noise when it happens.

3. t.Logf runs on testify's condition goroutine

The deferred close at :160-164 logs on t from inside the condition, which EventuallyWithT runs as go checkCond(). On the success path that is safe — the closure's own defers run before checkCond's send on ch unblocks the test goroutine. On the timeout path it is not: require calls FailNow, the test goroutine Goexits, and the in-flight attempt is still holding a connection whose context is cancelled just before cleanups run. A Close that then fails logs into a test that may already be finished, which panics rather than failing.

The window is small — container teardown gives the orphan several seconds — and Rotate in ministack.go already carries the same shape in its own Eventuallyf probe, so this is inherited rather than introduced. Dropping the log, or collecting the close error onto collect like every other assertion in the closure, removes it without changing anything observable.


Invariants. The tests this fixture feeds are what prove LK-2 holds across a pooler: a transaction-mode endpoint discards the session bounds every strong lock depends on, so NewPool refuses rather than running unbounded while believing itself bounded. This PR neither extends nor weakens the entry — it keeps the test that pins it from failing for a reason unrelated to the rule. Worth noting that the fixture is in the default suite (no build tag, and docs/testing.md:380-383 presents it that way), so a 30 s unexplained wait is paid by every run that hits the race, which is the practical case for finding 1.

This review was generated by Claude Code (claude-opus-5).

@aparajon

Copy link
Copy Markdown
Collaborator

🤖 Review 2/2 — two lenses: OSS adoption, and integration ease for importers.

Lens 1: OSS adoption

This fixture carries a claim no peer tool in the survey can make, which is why its flakiness costs more than a test. docs/testing.md says plainly that a survey of pgroll, Reshape, pg-osc, pg_repack, pg-schema-diff, pg-delta, migra, Atlas, SchemaHero and Bytebase found none testing poolers as live intermediaries, and that pg-sprite now does — in the default suite, not behind an environment gate. That is a differentiator stated in the repo's own words, and the evidence for it is exactly the two tests this fixture starts. A fixture that intermittently reports read: connection reset by peer does not just annoy contributors; it converts the sharpest claim on the page into "their pooler tests are red sometimes."

The adoption path this protects is the default one, not an edge case. A hosted PostgreSQL platform hands an operator a pooled connection string by default, so the first thing an evaluator on such a platform does is point pg-sprite at it. What they meet is a refusal — ErrNoSessionAffinity, with a message that names the session-mode endpoint to switch to. That is a good first impression precisely because it is specific and actionable, and it is the behaviour these tests pin (docs/supabase.md:191 records the same outcome for a hosted transaction endpoint). Any flake in the fixture lands on the one test that proves a stranger's very first interaction is correct.

Pinning the pooler image is the right instinct and the comment says why — "the pooling behaviour under test is the whole point of the fixture, so the version is not left to a floating tag." That discipline is what makes the 30 s / 60 s ordering in finding 1 of 1/2 worth fixing rather than tuning: client_login_timeout is a property of the pinned image, so the two numbers can be reconciled once and stay reconciled, instead of being re-guessed the next time a contributor on a slow laptop or a loaded runner eats an unexplained half-minute with no error attached.

One small thing while in docs/testing.md: the passage introduces StartPostgresBehindPgBouncer as "a real PgBouncer in both pool modes," which is now slightly under-sold — after this PR it is a real PgBouncer proven to be serving before the test runs. That sentence is where a reader decides how much to trust the claim, and the readiness property belongs in it.

Lens 2: integration ease for schemabot and other orchestrators

Nothing an importer compiles against changes here — and that is the observation, not the absence of one. The fixture lives in internal/testutil, so an orchestrator embedding pg-sprite cannot import it. Every such importer has the same problem pg-sprite just solved for itself: it accepts a connection string from an operator, that string very often points at a pooler, and the importer needs to prove its own wiring surfaces the refusal rather than a transport error. Today the only way to test that is to rebuild this fixture — the pinned image, the network alias, IGNORE_STARTUP_PARAMETERS, MAX_PREPARED_STATEMENTS, and now the readiness wait — from the test file by hand, and to re-derive each of those decisions along with it.

That is the shape of thing worth exporting once it settles. Not in this PR, and not as the whole fixture: a small pgspritetest (or an exported StartPostgresBehindPgBouncer under a _test-only build tag) offering the two pool modes would let an importer assert its own behaviour behind a pooler against the same substrate pg-sprite uses, rather than a hand-rolled approximation that drifts from it. The readiness wait this PR adds is a good argument for that: it is exactly the kind of hard-won detail an importer's copy would not have, and would rediscover as an intermittent CI failure of its own.

The error class is what matters to an importer, and the flake was crossing it. An orchestrator branches on the typed refusal — errors.Is(err, dbconn.ErrNoSessionAffinity) is a policy decision ("tell the operator to use the session-mode endpoint"), while read: connection reset by peer is an infrastructure retry. The pre-fix fixture produced the second where the contract promises the first, in the one test whose whole job is to prove the boundary between them. Anyone reading pg-sprite's CI to decide how firm that boundary is was reading the wrong signal. Finding 1 in 1/2 is the same concern one level up: a readiness failure that reports no error at all is indistinguishable, from the outside, from the pooler contract itself being flaky.

One forward-looking note. docs/supabase.md:294 already says an unrelated failure must not masquerade as the typed refusal. The converse now has a fixture behind it — the typed refusal must not be masked by an unrelated failure — and it is worth saying once in schemabot-integration.md, where an adapter author decides which errors are theirs to retry and which are the operator's to act on.

Approving. The direction is right, the fixture is the right place for it, and both findings in 1/2 are follow-ups: the per-attempt bound is the one I would take before merge, since without it the readiness failure is silent in exactly the state it was written for.

This review was generated by Claude Code (claude-opus-5).

@aparajon aparajon left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🤖 Approving. The readiness wait is the right property to gate on, go build/go vet/gofmt are clean, and both pooled dbconn tests pass on this head. Findings are in the two review comments above — the one I would take before merge is the per-attempt bound, since the 30 s deadline sits under PgBouncer's 60 s client_login_timeout and the wait therefore reports nothing in exactly the state it was written for.

This stamp was left by Claude Code (claude-opus-5).

…the cause

PgBouncer holds a client it cannot yet hand a server for its whole
client_login_timeout, which is longer than the readiness deadline, so a probe
with no bound of its own spent the deadline on one held attempt and left no
error for the deadline to report. Each attempt now carries its own timeout,
so the poll interval applies and the last login error is what a reader sees.

The comments attributed the window to the published port's host side; the
listening-port wait already checks the bind inside the container, and what
remains open is the pooler's own readiness to serve a login. The close error
of a probe connection is collected with the attempt's other assertions
rather than logged from the condition goroutine. docs/testing.md states the
readiness the fixture now proves.

Amp-Thread-ID: https://ampcode.com/threads/T-01a07fb2-9632-732b-bd7b-2f143a81bc06
@Kiran01bm

Copy link
Copy Markdown
Collaborator Author

🤖 Adversarial review response — created by Kiran's code review agent (Amp, Claude) — block/pg-sprite pull/112, follow-up commit

All three findings in 1/2 and the docs/testing.md sentence from 2/2 are fixed in one follow-up commit; the two forward-looking 2/2 items stay out of this test-fixture PR.

# Finding Status Explanation
1 C1-F1 — the 30 s deadline sits under PgBouncer's client_login_timeout, so one held login consumes the whole wait and EventuallyWithTf reports nothing Fixed Each probe runs under context.WithTimeout(t.Context(), poolerReadyAttempt) (5 s), so the 100 ms poll applies between attempts and every attempt ends with an error the deadline can carry. Reproduced the state — pinned image, LISTEN_PORT set, DB_HOST a name that does not resolve, port bound in the container — and the wait now ends at 30 s with the last attempt's error attached instead of "Condition never satisfied" alone. The two testify facts relied on hold in v1.11.1: tickC is re-armed only when the condition returns, and lastFinishedTickErrs is what the deadline reports. No timeout was raised.
2 C1-F2 — the comments blame the port forwarder, but the open cause is the pooler accepting a client before it can serve one Fixed Confirmed against testcontainers-go v0.43.0 that ForListeningPort checks the bind inside the container after the host dial and degrades silently to the host dial only when /bin/sh is missing. The wait-strategy comment now says a bound port means the process is listening while PgBouncer holds or closes a login before it has a server, and names the silent degradation; the awaitPooledLogin comment attributes the cut-off to the pooler, not the forwarder.
3 C1-F3t.Logf from the condition goroutine after FailNow may have ended the test Fixed The probe connection's close error is collected onto collect with the attempt's other assertions; nothing logs on t from the goroutine.
4 C2docs/testing.md says the fixture waits for the port, not for a login Fixed The sentence now says the fixture returns its URL only once a login through it has run a statement on the server behind it.
5 C2 — export the fixture for importers; add a "typed refusal must not be masked by an unrelated failure" line to docs/schemabot-integration.md Rejected Agreed in direction; both are contract additions for importers, not part of making this fixture's wait hold, so they belong to a change of their own.
6 C1 — the change is right in kind (a bound port is not readiness); go build/vet/gofmt clean and both NewPool pool-mode tests pass; the four mutation survivors are expected, since no test fails on a race that did not happen; the invariants entry is neither extended nor weakened No action Verified correct by the review; unchanged.

Source: block/pg-sprite#112, review comments 5652184395 and 5652184618 and review 5190209963 at head 9049d2f7; fixes in the follow-up commit

@Kiran01bm
Kiran01bm enabled auto-merge (squash) September 13, 2026 23:03
@Kiran01bm
Kiran01bm merged commit 38301d4 into main Sep 13, 2026
16 checks passed
@Kiran01bm
Kiran01bm deleted the kiran01bm/pgbouncer-fixture-readiness branch September 13, 2026 23:07
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.

2 participants