Large-payload reads hang until a client-side deadline kills them (ams)

Questions / Help
1

App: shine-music-school (org personal)
Region: ams — app and MPG cluster co-located
MPG cluster: 9g6y30wgm9krv5ml, PostgreSQL 16.14
Machines: 801935a66d16d8, d8d5d46b4d9438 (2 × shared-1x, 2 GB)
Client: psycopg 3.3.4 + psycopg_pool, min 3 / max 10 per machine, direct MPG
endpoint (no PgBouncer), statement_timeout=5000, lock_timeout=2000,
keepalives 1/30/10/3, tcp_user_timeout=10000

Summary

On two endpoints only, a request occasionally acquires a healthy pooled
connection, sends a query, and never receives a response. The TCP socket stays
established and the peer keeps acknowledging at the network level. Nothing
server-side ends it: statement_timeout cannot fire because the server appears
never to have received the statement, and tcp_user_timeout cannot fire because
the bytes are being acknowledged.

Before we deployed a client-side deadline these ran to exactly 600 seconds
and then failed with a bare psycopg.OperationalError. Since 2026-09-07 22:52
UTC our own watchdog kills them at ~9.2 s, so the symptom is now capped, but the
underlying event is still happening roughly 8 times a day.

This looks like the issue reported in
https://community.fly.io/t/intermittent-client-side-hangs-on-managed-postgres/27736,
where large result payloads intermittently never resolve on MPG (0% failure on
AWS RDS, ~1% on MPG above 500 KB), and which was reported fixed around 30 April
to 5 May 2026 “just that there were a few physical hosts that missed the
rollout”.

Our main question: did the hosts running the machines above receive that
rollout?

Why we think it is payload-size related

Only two endpoints have EVER produced this fault, out of a large API surface.
Both are the two biggest single reads in the application:

Endpoint Response size
GET /api/students ~1,294 KB of JSON (717 rows)
GET /api/scoreboard the other large aggregate read

Every other route in the app returns small payloads and has never hung.

Evidence

Recorded by our own fault logger. elapsed_ms is the wall time of the failing
attempt; pool_* are the pool gauges sampled at the moment of the fault, which
show the pool was NOT exhausted.

The 600-second events (before our client deadline existed)

UTC Machine Elapsed Route Pool at fault
2026-09-07 09:01:45 801935a66d16d8 600,095 ms /api/scoreboard size 9, available 8, waiting 0
2026-09-07 10:54:52 d8d5d46b4d9438 600,100 ms /api/students size 9, available 8, waiting 0
2026-09-07 17:48:43 801935a66d16d8 600,092 ms /api/scoreboard size 7, available 6, waiting 0
2026-09-07 18:19:21 d8d5d46b4d9438 600,106 ms /api/students size 10, available 9, waiting 0
2026-09-07 19:31:26 d8d5d46b4d9438 600,082 ms /api/scoreboard size 9, available 8, waiting 0

Note how tightly clustered 600,082 to 600,106 ms is. Something is imposing a
600-second bound, and it is not us: we had no timeout of any kind that could
produce it, which is why we went looking.

The same events after our 9-second client deadline (2026-09-07 22:52 UTC onward)

UTC Machine Elapsed Route Pool at fault
2026-09-08 08:10:07 801935a66d16d8 9,281 ms /api/students size 7, available 6, waiting 0
2026-09-08 10:46:58 d8d5d46b4d9438 9,245 ms /api/scoreboard size 7, available 6, waiting 0
2026-09-08 10:48:24 801935a66d16d8 9,151 ms /api/students size 7, available 6, waiting 0
2026-09-08 12:15:50 801935a66d16d8 9,169 ms /api/students size 7, available 6, waiting 0
2026-09-08 13:34:54 801935a66d16d8 9,339 ms /api/scoreboard size 6, available 5, waiting 0
2026-09-08 14:27:13 d8d5d46b4d9438 9,262 ms /api/scoreboard size 7, available 6, waiting 0
2026-09-08 15:04:53 801935a66d16d8 9,272 ms /api/students size 7, available 6, waiting 0
2026-09-08 19:08:45 d8d5d46b4d9438 9,136 ms /api/scoreboard size 8, available 7, waiting 0

Both machines are affected, so it is not one bad machine.

What we ruled out, and how

  • Pool exhaustion. The gauges above are captured at fault time: 5 to 9
    connections free and nobody queueing. (We did separately have a genuine pool
    exhaustion problem on other routes, visible as ~15,000 ms faults with
    available: 0. We found and fixed that ourselves on 2026-09-07; it was our
    bug, it is gone from the log after that date, and it is not what this report
    is about.)
  • PostgreSQL. No setting on the cluster is 600 seconds. statement_timeout
    is 5,000 ms and never fired on these, which is itself the tell: the server
    does not appear to have received the statement.
  • PgBouncer. Not in the path; we connect to the direct endpoint.
  • A dead socket. tcp_user_timeout=10000 was already deployed and did not
    fire, and the next occurrence came 34 minutes later on a still-working app, so
    the peer was still acknowledging.
  • Our own code. Reproduced locally with a TCP proxy that keeps calling
    recv() and stops forwarding: psycopg then waits on a live, silent socket
    indefinitely, which is exactly the observed behaviour.

What we would like

  1. Confirmation of whether the physical hosts for 801935a66d16d8 and
    d8d5d46b4d9438, and the MPG cluster 9g6y30wgm9krv5ml, received the fix
    rolled out around 2026-04-30 to 2026-05-05 for the large-payload hang.
  2. If they did, whether this is a regression or a distinct issue.
  3. Anything you would like us to capture next time it happens. We log every
    occurrence with timestamps and pool state and can add packet captures or a
    pg_stat_activity snapshot at fault time if that is useful.

Happy to give timestamps in any format, or to grant access. We are not blocked,
because our client-side deadline contains it, but we are absorbing an unexplained
9-second failure on the two heaviest pages roughly eight times a day.

3

Hi there, thanks for reporting this. We’re looking into whether the fix mentioned in https://community.fly.io/t/intermittent-client-side-hangs-on-managed-postgres/27736 somehow stopped working as expected. I’ll report back once I know more.

4

ok thanks, please let me know

5

Hi, we checked and there’s no regression on the large-payload issue you mentioned earlier. We actually rearchitected the fix post-facto so it’s basically impossible for that to be the actual problem. We also updated all hosts so it’s not a straggler un-updated host either.

Have you looked at metrics for your cluster to confirm it’s not CPU-throttled or otherwise constrained, which might explain these sporadic stalls?

Can you tell us if what you’re running to generate the payload is one big query or a bunch of small queries or something else?

Thanks!

6

Thanks for checking. Answers to both questions, with data from our own fault log.

  1. CPU throttling / constraints. The cluster is shine-pg (9g6y30wgm9krv5ml, basic plan, one replica, ams, 63 MB database). We cannot see your host metrics, but everything we can see says the server was not the bottleneck:
  • statement_timeout is 5 s on every session and has never fired for these requests. The wait ends only when OUR client-side deadline cancels it: 600 s before we added a deadline, 9.1 to 9.3 s since. A throttled query finishes late; these never finish.
  • Server-side statement times over the same period peak in the tens of milliseconds (pg_stat_monitor max_exec_time 31 ms).
  • The pool was idle on every occurrence: 5 to 8 free connections, 0 waiting (pool stats are captured with each fault).
  • Total load is tiny: two shared-1x machines, roughly 3,000 requests per machine per hour, 20 mostly idle backends.
  1. Query shape. Each affected endpoint runs ONE large statement plus a dozen small ones, and only the two endpoints with a large statement have ever hung. GET /api/students runs a single SELECT <42 columns> FROM students ORDER BY created_at DESC returning ~750 rows (a few hundred KB on the wire); GET /api/scoreboard ran SELECT * FROM students (72 columns, same rows, larger). The small statements on the same connections, and every small endpoint in the app, have never hung. That is the size correlation from thread 27736.

Occurrences since your last message (UTC, machine, endpoint, ms until our cancel), all QueryDeadlineExceeded from our client watchdog:

2026-09-14T15:17:03Z d8d5d46b4d9438 /api/scoreboard 9344
2026-09-14T17:35:10Z 801935a66d16d8 /api/scoreboard 9104
2026-09-15T07:03:54Z 801935a66d16d8 /api/scoreboard 9133
2026-09-15T07:12:54Z 801935a66d16d8 /api/scoreboard 9162
2026-09-15T07:21:54Z d8d5d46b4d9438 /api/scoreboard 9320
2026-09-15T09:40:27Z d8d5d46b4d9438 /api/students 9158
2026-09-15T12:06:12Z d8d5d46b4d9438 /api/students 9304
2026-09-16T08:43:12Z 801935a66d16d8 /api/students 9212
2026-09-16T11:40:11Z 801935a66d16d8 /api/students 9176
2026-09-16T17:02:06Z 801935a66d16d8 /api/students 9158
2026-09-16T17:10:26Z 801935a66d16d8 /api/scoreboard 9103

Both app machines hit it, so it is not one bad machine on our side. Per day: 7 Sep 26 (5 of them 600 s, before the deadline), 8 Sep 8, 9 to 13 Sep 0 to 1, 14 Sep 2, 15 Sep 5, 16 Sep 4.

Today we removed the scoreboard’s large read on our side (it now runs one small aggregate query), so from 2026-09-17 18:37 UTC only /api/students still carries a large result. If the stalls follow the large read and leave the scoreboard alone, that is one more data point for the size hypothesis; we will report either way.

If it helps, we can add server-side cursors (row batches instead of one large response) to /api/students as an experiment, or run any probe you want from our machines against direct.9g6y30wgm9krv5ml.flympg.net.

7

Thanks for the details! I’ll await your report on what your changes show.

One thing - is there any way you could run select * from pg_stat_activity at the moment you get a stuck query?

Given the frequency, I imagine you could try running the query in a loop, while also running select * from pg_stat_activity in a loop, so you can catch it in the act.

8

Two updates since my last message.

We shrank the large reads on our side, and the stall moved to the next-largest one.

  • 18:37 UTC: /api/scoreboard no longer runs its large SELECT (one small aggregate query now).
  • 18:47 UTC: one more stall on /api/students, still the old single large response, machine 801935a66d16d8.
  • 19:13 UTC: /api/students switched to a server-side cursor, FETCH batches of 50 rows, about 53 KB per response instead of one ~800 KB response.
  • 19:54 UTC: for the first time ever, a stall on a THIRD endpoint, GET /api/gestion/lane?include_archived=true, machine d8d5d46b4d9438, 9318 ms until our cancel. That endpoint runs three queries returning up to 400 rows each with a JSON column, a few hundred KB in one response. It had never stalled in the fault log before; it became the largest single response in the app once the other two were reduced.
  • 20:09 UTC: those three reads batched the same way.

So since 20:09 UTC no query in the app returns a single response above roughly 55 KB. Every stall we have ever recorded (26 since 7 Sep with per-fault detail) was on whichever endpoint returned the largest single response at the time. We will report whether any stall occurs on the small-response shape; as of now, none has.

If your host logs can be checked, the two timestamps above are the freshest, both against direct.9g6y30wgm9krv5ml.flympg.net from shine-music-school in ams.

On pg_stat_activity: yes, and we will do both. Tonight we are adding a snapshot of pg_stat_activity (taken from a second connection at the moment our client watchdog fires, before it cancels) to every fault record, so each future stall carries the server’s view of that backend: state, wait_event, query_start, and whether the statement ever arrived. Separately we will run your loop on one app machine: the old single large SELECT from students every couple of seconds with a client deadline, and pg_stat_activity polled beside it, so we catch it in the act even though production no longer sends large responses. We will post the first captures.

9

Report, as promised. Short version: batching changed nothing, the loop caught four stalls with pg_stat_activity, and each time the backend had reached idle within 10 ms of query_start and was in ClientRead when we looked 9 s later. What is late or missing is the reply on its way back to us, and that way runs through fly-proxy.

1. Batching did not stop it. Since 2026-09-17 20:09 UTC none of the three routes that have ever stalled sends a single DB response above about 55 KB (the students list is FETCH 50 rows at a time from a server-side cursor, about 53 KB per reply). Three stalls since, all on that batched read, pool otherwise idle and nobody waiting each time:

deadline fired (UTC)      machine          what stalled
2026-09-18T07:29:31Z      d8d5d46b4d9438   FETCH #12 of the read; FETCHes 1-11 (550 rows) had answered normally (about 20 ms typical) on the same connection
2026-09-18T11:18:52Z      d8d5d46b4d9438   FETCH #4;  FETCHes 1-3 (150 rows) normal
2026-09-18T11:57:33Z      801935a66d16d8   FETCH #3;  FETCHes 1-2 (100 rows) normal

The stalled FETCH had been outstanding 9.3 to 9.4 s at the time shown (measured from before the send, so at most that). So it is not the size of the reply: a 53 KB FETCH on an open cursor, on a connection whose previous FETCHes had just answered normally, does not come back for 9 s.

What our client did at the deadline in those three cases, and what it saw: at 9.0 s it opened a fresh connection to take a pg_stat_activity snapshot (about 40 ms, then closed it), then sent a CancelRequest over another fresh connection (delivered, all three times), then shut down the stuck socket. In all three cases the stalled FETCH’s 50 rows were complete in our kernel by the time of that shutdown: the reply finished arriving inside a window of at most about 0.4 s that opened when the snapshot connection closed (a few milliseconds before the cancel went out) and ended at the shutdown, having not finished in the 9 s before. We are not claiming the cancel released it (the loop below argues against that for a large reply); we are reporting the timing because it may mean something on your side. Our snapshot from those three did not get attached to the fault record (a bug in our fault logging, being fixed), so the server-side view below comes from the loop.

2. The loop caught four, with pg_stat_activity. On machine 801935a66d16d8, outside the app: SELECT * FROM students ORDER BY created_at DESC (about 750 rows, about 800 KB) every 2 s on connection A with a 9 s client deadline. When A has not answered after 9 s, a fresh connection B snapshots pg_stat_activity before anything else, then A is cancelled, we wait 3 s for the rows, then close A and open a new one. About 8,100 runs from 07:29 to 12:05 UTC, typical run 23 to 30 ms, worst normal run 1.6 s, four stalls:

query sent (query_start, UTC) backend pid backend went idle (state_change) backend at +9.2 s snapshot from a new conn cancel delivered rows within 3 s of cancel
10:40:37.189 20864 10:40:37.196 (+7 ms) idle, ClientRead ok, 207 ms yes no
10:45:02.912 22954 10:45:02.921 (+9 ms) idle, ClientRead ok, 203 ms yes no
11:46:56.287 23006 11:46:56.293 (+6 ms) idle, ClientRead ok, 209 ms yes no
11:51:52.924 23686 11:51:52.930 (+6 ms) idle, ClientRead ok, 208 ms yes no

What that says, each time:

  • The request was not delayed: the snapshot’s own query_start is 9.20 s after the stuck query’s query_start in all four (our 9.0 s deadline plus about 0.2 s for the snapshot connection to be ready), so the SELECT started on the server within milliseconds of being sent.
  • The server ran it and went idle 6 to 9 ms later (state idle, wait_event ClientRead, xact_start null, application_name stall-loop-A, query = our SELECT). A backend only reaches ClientRead after its final flush has returned, and a failed send would have terminated it rather than parked it there, so every send() of the 800 KB reply had returned and the socket toward its peer was alive.
  • Nine seconds later our client had still not received the complete reply (execute() had not returned; we cannot tell how much of the 800 KB had arrived), while a brand new connection from the same machine to the same endpoint connected and read pg_stat_activity in about 205 ms.
  • The cancel found nothing to cancel. The client thread was still blocked when we closed the socket, 12.2 s or more after the send.
  • Not per host: the loop’s 800 KB SELECTs on 801935a66d16d8 kept completing every 2 s right through the app’s 11:57 stall on that same machine.

3. The hop. direct.9g6y30wgm9krv5ml.flympg.net resolves, from machine 801935a66d16d8, to fdaa:52:7397:0:1::2, a Flycast address in our own network, and every established socket to port 5432 on that machine goes there. Postgres sees those connections arriving from two addresses in a network that is not ours (our machines are fdaa:52:7397:a7b:…), fdaa:a4:e5eb:a7b:623:b7c9:d13d:2 and fdaa:a4:e5eb:a7b:4ca:a99c:9a4a:2 (successive connections from the same machine have landed behind either, both are live at once, and the loop’s four stalls were two behind each). So fly-proxy terminates our connection and opens its own connection toward the cluster. The 9 s is spent somewhere between the backend’s returned send() and our socket: the Postgres host’s kernel, fly-proxy, or the network on either side of it. From our side those are indistinguishable, and the proxy is the one place we cannot see.

If those two addresses are your fly-proxy instances, or whatever sits at them, and they keep logs or metrics, the seven events are: 07:29:22 to 31 (app, d8d5d46b4d9438), 10:40:37 (pid 20864), 10:45:02 (pid 22954), 11:18:42 to 52 (app, d8d5d46b4d9438), 11:46:56 (pid 23006), 11:51:52 (pid 23686), 11:57:24 to 33 (app, 801935a66d16d8), all UTC, 2026-09-18. The full JSON of the four snapshots (every backend, 20 to 23 rows each) is on the machine; happy to paste or upload.

Two questions. Does the window-clamping fix from thread 27736 cover a 53 KB reply on a connection whose previous FETCH answered milliseconds earlier, or only replies above the threshold you used there? And is there any state in fly-proxy’s Postgres handling that would hold a backend’s reply and release it on a new connection, a CancelRequest or a FIN from the client? We cannot tell those three apart from our side; we can run any probe you want from our machines.

10

Thanks for the details! For your questions:

  1. It should cover it.
  2. Shouldn’t - the Postgres handler is mostly raw tcp (has some magic to handle tls I think but that’s about it) and we haven’t seen any of this behavior on other TCP connections.

Let’s keep exploring multiple angles: can you try getting a tcpdump on the client machine, plus ss -tinm on the stuck socket at deadline? Look for partial arrival then silence vs. zero-window vs. nothing ever sent vs. retransmits.

On my side, I’m going to try a simple repro based on what you’ve been seeing.

11

First capture is in, with ss -tinm at the deadline, and it changes the picture. Short version: the whole reply reached our machine in 0.67 s, with one 660 ms pause after the first 17.7 KB; the 9 s that follow are a libpq bug on our side, already fixed upstream in 18.6, which your pause happened to trigger. So the hangs are ours to fix, and we are upgrading. The pause is the one thing that is yours, and it is small.

Setup: same loop on 801935a66d16d8, connection A, local port 35138, peer fdaa:52:7397:0:1::2:5432 (the Flycast address), TLS; tcpdump -i any -s 160 on the machine; ss -tinm on A’s socket the moment the 9 s deadline fires. Stall at 16:14:10 UTC today.

The healthy run two seconds earlier: query sent 16:13:59.090, reply of 544,942 bytes streamed back from .096 to .109, 12.7 ms, no gaps.

The stalled run:

16:14:01.113  query out (65 bytes)
16:14:01.120  first 17,668 bytes of the reply arrive; the backend reports idle at 01.121 (state_change = query_start + 7 ms)
              ... nothing for 660 ms ...
16:14:01.781  the remaining 527,802 bytes arrive in 3 ms, as full 16 KB TLS records; the peer's TCP timestamps jump by 659 ms across the gap, so it emitted them then
16:14:01.784  our ACK covering the last byte
16:14:04.29   keepalive probe from the peer (seq = rcv_nxt - 1), again at 09.42
16:14:10.118  our 9 s deadline

Total 545,470 bytes, contiguous, no duplicate segments, no SACK, no dup-ACKs, our window 4.1 MB throughout, every segment ACKed within 60 us. Nothing arrives after 01.784 and nothing more was needed.

ss -tinm at the deadline: ESTAB, Recv-Q 0, Send-Q 0, skmem r0, bytes_received unchanged since 01.784, lastsnd 9004, lastrcv 8332, rcv_wnd 4,130,816, rto 208, no retrans, retrnsmt 0 in /proc/net/tcp6. Not a zero window on our side, nothing to retransmit, no partial delivery, and the process had already read every byte out of the kernel.

Then our phases, one per second: a bare TCP connect to the Flycast address (326 ms), a fresh connection reading pg_stat_activity (50 ms; the stuck backend idle in ClientRead since 01.121), a full Postgres connect (29 ms), a CancelRequest (23 ms, delivered). None freed the caller. shutdown(SHUT_RDWR) on the socket did, at 14.55, and the client’s execute().fetchall() then returned all 782 rows with no error.

What that is. The reply’s last TLS record was 16,337 bytes. libpq 18.0 reads one SSL record per pqReadData() into a 16 KB buffer that still holds the tail of the previous partial row, so the end of that record, the part carrying CommandComplete and ReadyForQuery, stays decrypted inside OpenSSL. The socket is then genuinely empty, the client polls it forever, and only a socket event (our shutdown, or, before we had a client deadline, your 600 s idle close) makes it read the pending bytes and complete. PostgreSQL 18.6 (13 August) fixed exactly this: “In libpq, always drain all pending bytes from the SSL or GSS decryption buffer during pqReadData() … avoids edge cases where libpq or its calling application waits for more data to arrive on the socket, but actually all the data has already arrived.” Our psycopg-binary 3.3.4 bundles libpq 18.0; 3.3.6 bundles 18.6 (libpq 180006, verified), and we are moving to it now. Every healthy run in this capture ends with a small final record and cannot trigger it; the pause-then-burst delivery produced maximum-size records, including the last one, and that is the whole connection between your side and ours. A cancel could never help because the backend was already idle, which matches the four earlier captures.

So our earlier “the reply never arrives” was wrong, and the client-side deadline was killing a query whose answer was sitting in our own process. Sorry for the detour, and thanks for the pg_stat_activity and tcpdump asks; both were the key.

The part that is yours, for your information rather than as a blocker: at 16:14:01.12 to 01.78 the stream from the proxy side paused for 660 ms after 17,668 bytes and then resumed with 16 KB records, i.e. the data had accumulated at or upstream of the TLS-writing proxy on the MPG side; the backend had finished and flushed before the pause, and the last hop shows no loss or retransmission. We cannot see further than that. If your proxy logs or metrics show anything at that moment (a retransmit on the PG-to-proxy leg, an event-loop pause, throttling), it would explain the sub-second blips we still see a few times a day. The pcap of this connection (two 2-minute files, headers only, port 5432, 3.7 MB) is available if you want it.

We will report back after the upgrade whether the 9 s deadlines stop, which is what we expect.

12

Wow, thanks for the very detailed description and diagnostic - great find on the libpq bug!

I actually did write a repro case but I’ve had it running for hours and didn’t get a single stall - but as per your findings, it’s likely because I’m using psycopg 3.3.6. For closure, I’ll try to pin to 3.3.4 and rerun my test, but that’s mainly for my own reassurance, hopefully the fix will hold for you and you won’t get more weird issues!

13

Hahaha, that was quick. Within 10 minutes of downgrading my repro test to 3.3.4, I got 7 stalls. So I think 1) my repro is good, 2) your find/fix is good.

With psycopg-binary 3.3.4, ran for 10 minutes total:

2026-09-18T21:35:51.990+00:00 978 runs, 7 stalls, last 29 ms, slowest 407 ms

With psycopg-binary 3.3.6, ran for 5 hours total:

2026-09-18T21:23:59.386+00:00 32774 runs, 0 stalls, last 23 ms, slowest 440 ms

Fairly evident 3.3.4 is where the stall happens.

Cheers!