WaitEventSetWaitBlock() can still hang on Windows due to connection reset
Hackorum builds and tests every patch posted to the lists, not only commitfest submissions. This is Hackorum's own CI rather than the PostgreSQL project's, and it is still under testing - please report anything that looks wrong.
You can run a PostgreSQL built from this patch straight from Docker, with no checkout and no build:
docker run --rm -p 5432:5432 ghcr.io/hackorum-dev/postgres-patch:t50432psql -h localhost -U postgresBuilt from patchset v1 (message #1), July 27, 2026 at 11:09 AM.
Every patchset is also pushed to a branch of our PostgreSQL fork, so you can check out the same tree CI built. Without a PostgreSQL checkout:
git clone --branch t50432_1 https://github.com/hackorum-dev/postgres.gitIn a checkout you already have, add the fork once:
git remote add hackorum https://github.com/hackorum-dev/postgres.gitthen, for this patchset and every later one:
git fetch hackorum t50432_1 && git checkout t50432_1Patchset v1 (message #1) is on t50432_1
Hello hackers,
[ a follow-up to [1]/messages/by-id/CA+hUKGKn+xWjaEnQ+iYYs7STG7_nNP5w5VMb1vSvQfAkkOxOUA@mail.gmail.com separated to focus on this issue ]
Let me bring your attention to a failure [2]https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2024-10-14%2010%3A08%3A17, presented by drongo in the
last week, with the following diagnostics:
[10:30:30.954](2.110s) ok 5 - compare primary and standby dumps
### Restarting node "primary"
# Running: pg_ctl -w -D
C:\\prog\\bf\\root\\HEAD\\pgsql.build/testrun/recovery/027_stream_regress\\data/t_027_stream_regress_primary_data/pgdata
-l C:\\prog\\bf\\root\\HEAD\\pgsql.build/testrun/recovery/027_stream_regress\\log/027_stream_regress_primary.log restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 8908
Waiting for replication conn standby_1's replay_lsn to pass 0/158C8B98 on primary
[10:41:32.115](661.161s) # poll_query_until timed out executing this query:
# SELECT '0/158C8B98' <= replay_lsn AND state = 'streaming'
# FROM pg_catalog.pg_stat_replication
# WHERE application_name IN ('standby_1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
#
027_stream_regress_standby_1.log contains:
2024-10-14 10:30:28.483 UTC [4320:12] 027_stream_regress.pl LOG: disconnection: session time: 0:00:03.793 user=pgrunner
database=postgres host=127.0.0.1 port=61748
2024-10-14 10:30:31.442 UTC [8468:2] LOG: replication terminated by primary server
2024-10-14 10:30:31.442 UTC [8468:3] DETAIL: End of WAL reached on timeline 1 at 0/158C8B98.
2024-10-14 10:30:31.442 UTC [8468:4] FATAL: could not send end-of-streaming message to primary: server closed the
connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
no COPY in progress
2024-10-14 10:30:31.443 UTC [5452:7] LOG: invalid resource manager ID 101 at 0/158C8B98
2024-10-14 10:35:06.986 UTC [8648:21] LOG: restartpoint starting: time
2024-10-14 10:35:06.991 UTC [8648:22] LOG: restartpoint complete: wrote 0 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL
file(s) added, 0 removed, 1 recycled; write=0.001 s, sync=0.001 s, total=0.005 s; sync files=0, longest=0.000 s,
average=0.000 s; distance=15336 kB, estimate=69375 kB; lsn=0/158C8B20, redo lsn=0/158C8B20
2024-10-14 10:35:06.991 UTC [8648:23] LOG: recovery restart point at 0/158C8B20
2024-10-14 10:35:06.991 UTC [8648:24] DETAIL: Last completed transaction was at log time 2024-10-14 10:30:24.820804+00.
2024-10-14 10:41:32.510 UTC [4220:4] LOG: received immediate shutdown request
(That is, primary was restarted, but standby didn't reconnect to it,
waiting for something...)
$node_primary->restart was added to 027_stream_regress.pl on 2024-06-27
(with 0844b3968), so this can explain why is it the first noticed failure
of this kind.
I managed to reproduce this failure locally, then I reduced the 027 test
to just restarting primary in a loop, and with debug logging added (please
find attached) I could see what makes standby hang:
2024-10-22 08:42:20.016 UTC [6652] DETAIL: End of WAL reached on timeline 1 at 0/5D14C98.
2024-10-22 08:42:20.016 UTC [6652] FATAL: could not send end-of-streaming message to primary: server closed the
connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
no COPY in progress
2024-10-22 08:42:20.016 UTC [21268] LOG: invalid record length at 0/5D14C98: expected at least 24, got 0
2024-10-22 08:42:20.088 UTC [8256] LOG: !!!WalReceiverMain| before walrcv_connect
!!!libpqrcv_connect| before loop
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 64)
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 1
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 64)
!!!WaitEventSetWaitBlock| before WaitForMultipleObjects
!!!WaitEventSetWaitBlock| WaitForMultipleObjects returned: 3
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 64
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 4)
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 4
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 2)
!!!WaitEventSetWaitBlock| WL_SOCKET_READABLE, cur_event->fd: 844, WSAGetLastError(): 10054
!!!WaitEventSetWaitBlock| before WaitForMultipleObjects
2024-10-22 08:44:49.399 UTC [15352] LOG: restartpoint starting: time
...
While for a previous successful reconnect we can see:
2024-10-22 08:42:17.275 UTC [6652] LOG: !!!WalReceiverMain| before walrcv_connect
!!!libpqrcv_connect| before loop
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 64)
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 1
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 64)
!!!WaitEventSetWaitBlock| before WaitForMultipleObjects
!!!WaitEventSetWaitBlock| WaitForMultipleObjects returned: 3
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 64
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 4)
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 4
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 2)
!!!WaitEventSetWaitBlock| WL_SOCKET_READABLE, cur_event->fd: 844, WSAGetLastError(): 10035
!!!WaitEventSetWaitBlock| before WaitForMultipleObjects
!!!WaitEventSetWaitBlock| WaitForMultipleObjects returned: 3
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 2
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 4)
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 4
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 2)
!!!WaitEventSetWaitBlock| WL_SOCKET_READABLE, cur_event->fd: 844, WSAGetLastError(): 10035
!!!WaitEventSetWaitBlock| before WaitForMultipleObjects
!!!WaitEventSetWaitBlock| WaitForMultipleObjects returned: 3
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 2
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 2)
!!!WaitEventSetWaitBlock| WL_SOCKET_READABLE, cur_event->fd: 844, WSAGetLastError(): 10035
!!!WaitEventSetWaitBlock| before WaitForMultipleObjects
!!!WaitEventSetWaitBlock| WaitForMultipleObjects returned: 3
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 2
!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: 2)
!!!WaitEventSetWaitBlock| WL_SOCKET_READABLE, cur_event->fd: 844, WSAGetLastError(): 10035
!!!WaitEventSetWaitBlock| before WaitForMultipleObjects
!!!WaitEventSetWaitBlock| WaitForMultipleObjects returned: 3
!!!libpqrcv_connect| after WaitLatchOrSocket, rc: 2
!!!libpqrcv_connect| after loop
(The full log is attached too.)
In other words, if WSARecv() fails with WSAECONNRESET, calling
WaitForMultipleObjects() still leads to the hang.
I reproduced this on a8458f508~1 and on 97d891010, so the issue itself is
not new...
[1]: /messages/by-id/CA+hUKGKn+xWjaEnQ+iYYs7STG7_nNP5w5VMb1vSvQfAkkOxOUA@mail.gmail.com
[2]: https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2024-10-14%2010%3A08%3A17
Best regards,
Alexander
Dear Alexander,
While analyzing the BF failure [1]https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=drongo&dt=2025-04-12%2003%3A59%3A38&stg=recovery-check, I noticed that the same issue may happen here,
which means apply worker waited something. According to the log, apply worker (PID 2820)
stucked so that logical replication could not restart.
Regress log:
```
### Restarting node "pub"
# Running: pg_ctl --wait --pgdata C:\\prog\\bf\\root\\HEAD\\pgsql.build/...
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "pub" is 980
timed out waiting for match: (?^:Streaming transactions committing after ([A-F0-9]+/[A-F0-9]+), ...
```
Subscriber log;
```
2025-04-12 05:08:44.630 UTC [2820:1] LOG: logical replication apply worker for subscription "sub" has started
2025-04-12 05:08:44.642 UTC [5652:6] LOG: background worker "logical replication apply worker" (PID 6344) exited with exit code 1
2025-04-12 05:13:27.352 UTC [3988:1] LOG: checkpoint starting: time
2025-04-12 05:13:36.825 UTC [3988:2] LOG: checkpoint complete: wrote 62 buffers ...
2025-04-12 05:15:01.265 UTC [5652:7] LOG: received immediate shutdown request
2025-04-12 05:15:01.353 UTC [5652:8] LOG: database system is shut down
```
Publisher log;
```
2025-04-12 05:08:44.634 UTC [1112:7] LOG: database system is shut down
2025-04-12 05:08:45.685 UTC [980:1] LOG: starting PostgreSQL 18devel on...
2025-04-12 05:08:45.687 UTC [980:2] LOG: listening on IPv4 address "127.0.0.1", port 18057
2025-04-12 05:08:46.225 UTC [4392:1] LOG: database system was shut down at 2025-04-12 05:08:43 UTC
2025-04-12 05:08:46.319 UTC [980:3] LOG: database system is ready to accept connections
2025-04-12 05:15:00.408 UTC [980:4] LOG: received immediate shutdown request
2025-04-12 05:15:00.942 UTC [980:5] LOG: database system is shut down
```
Now the report has been reported for both physical and logical replication,
but I suspected that this can happen for all the application.
Best regards,
Hayato Kuroda
FUJITSU LIMITED
Dear Kuroda-san,
17.04.2025 10:10, Hayato Kuroda (Fujitsu) wrote:
Dear Alexander,
While analyzing the BF failure [1], I noticed that the same issue may happen here,
which means apply worker waited something. According to the log, apply worker (PID 2820)
stucked so that logical replication could not restart....
Now the report has been reported for both physical and logical replication,
but I suspected that this can happen for all the application.
Thank you for the analysis!
I think you're right, it's the same issue, so I've added the link to the
wiki page.
Best regards,
Alexander Lakhin
Neon (https://neon.tech)