public inbox for [email protected]
help / color / mirror / Atom feedFrom: Alexander Lakhin <[email protected]>
To: pgsql-hackers <[email protected]>
To: Thomas Munro <[email protected]>
Subject: WaitEventSetWaitBlock() can still hang on Windows due to connection reset
Date: Tue, 22 Oct 2024 13:00:00 +0300
Message-ID: <[email protected]> (raw)
Hello hackers,
[ a follow-up to [1] separated to focus on this issue ]
Let me bring your attention to a failure [2], 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] https://www.postgresql.org/message-id/CA%2BhUKGKn%2BxWjaEnQ%2BiYYs7STG7_nNP5w5VMb1vSvQfAkkOxOUA%40ma...
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2024-10-14%2010%3A08%3A17
Best regards,
Alexander
Attachments:
[application/x-perl] 099_primary_restart.pl (1.4K, ../[email protected]/2-099_primary_restart.pl)
download
[text/x-log] 099_primary_restart_standby_1.log (190.3K, ../[email protected]/3-099_primary_restart_standby_1.log)
download
[text/x-patch] walreceiver-win-socket-debugging.patch (3.9K, ../[email protected]/4-walreceiver-win-socket-debugging.patch)
download | inline diff:
diff --git a/src/backend/replication/libpqwalreceiver/libpqwalreceiver.c b/src/backend/replication/libpqwalreceiver/libpqwalreceiver.c
index 97f957cd87..9acf524e8f 100644
--- a/src/backend/replication/libpqwalreceiver/libpqwalreceiver.c
+++ b/src/backend/replication/libpqwalreceiver/libpqwalreceiver.c
@@ -221,6 +221,7 @@ libpqrcv_connect(const char *conninfo, bool replication, bool logical,
* Per spec for PQconnectPoll, first wait till socket is write-ready.
*/
status = PGRES_POLLING_WRITING;
+fprintf(stderr, "!!!libpqrcv_connect| before loop\n");
do
{
int io_flag;
@@ -236,11 +237,16 @@ libpqrcv_connect(const char *conninfo, bool replication, bool logical,
else
io_flag = WL_SOCKET_WRITEABLE;
+fprintf(stderr, "!!!libpqrcv_connect| before WaitLatchOrSocket(io_flag: %d)\n",
+io_flag);
+debug_latch = true;
rc = WaitLatchOrSocket(MyLatch,
WL_EXIT_ON_PM_DEATH | WL_LATCH_SET | io_flag,
PQsocket(conn->streamConn),
0,
WAIT_EVENT_LIBPQWALRECEIVER_CONNECT);
+debug_latch = false;
+fprintf(stderr, "!!!libpqrcv_connect| after WaitLatchOrSocket, rc: %d\n", rc);
/* Interrupted? */
if (rc & WL_LATCH_SET)
@@ -253,6 +267,7 @@ libpqrcv_connect(const char *conninfo, bool replication, bool logical,
if (rc & io_flag)
status = PQconnectPoll(conn->streamConn);
} while (status != PGRES_POLLING_OK && status != PGRES_POLLING_FAILED);
+fprintf(stderr, "!!!libpqrcv_connect| after loop\n");
if (PQstatus(conn->streamConn) != CONNECTION_OK)
goto bad_connection_errmsg;
diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c
index a27aee63de..e14d8cbd59 100644
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -300,12 +300,14 @@ WalReceiverMain(char *startup_data, size_t startup_data_len)
/* Establish the connection to the primary for XLOG streaming */
appname = cluster_name[0] ? cluster_name : "walreceiver";
+elog(LOG, "!!!WalReceiverMain| before walrcv_connect");
wrconn = walrcv_connect(conninfo, true, false, false, appname, &err);
if (!wrconn)
ereport(ERROR,
(errcode(ERRCODE_CONNECTION_FAILURE),
errmsg("streaming replication receiver \"%s\" could not connect to the primary server: %s",
appname, err)));
+elog(LOG, "!!!WalReceiverMain| wrconn: %p", wrconn);
/*
* Save user-visible connection string. This clobbers the original
diff --git a/src/backend/storage/ipc/latch.c b/src/backend/storage/ipc/latch.c
index 608eb66abe..e6506cf6a3 100644
--- a/src/backend/storage/ipc/latch.c
+++ b/src/backend/storage/ipc/latch.c
@@ -98,6 +98,8 @@
#endif
#endif
+bool debug_latch = false;
+
/* typedef in latch.h */
struct WaitEventSet
{
@@ -2029,6 +2034,8 @@ WaitEventSetWaitBlock(WaitEventSet *set, int cur_timeout,
occurred_events->fd = cur_event->fd;
return 1;
}
+if (debug_latch)
+fprintf(stderr, "\t!!!WaitEventSetWaitBlock| WL_SOCKET_READABLE, cur_event->fd: %d, WSAGetLastError(): %d\n", cur_event->fd, WSAGetLastError());
}
/*
@@ -2069,8 +2076,12 @@ WaitEventSetWaitBlock(WaitEventSet *set, int cur_timeout,
*
* Need to wait for ->nevents + 1, because signal handle is in [0].
*/
+if (debug_latch)
+fprintf(stderr, "\t!!!WaitEventSetWaitBlock| before WaitForMultipleObjects\n");
rc = WaitForMultipleObjects(set->nevents + 1, set->handles, FALSE,
cur_timeout);
+if (debug_latch)
+fprintf(stderr, "\t!!!WaitEventSetWaitBlock| WaitForMultipleObjects returned: %d\n", rc);
/* Check return code */
if (rc == WAIT_FAILED)
diff --git a/src/include/storage/latch.h b/src/include/storage/latch.h
index 7e194d536f..5387afdedc 100644
--- a/src/include/storage/latch.h
+++ b/src/include/storage/latch.h
@@ -193,4 +193,5 @@ extern void InitializeLatchWaitSet(void);
extern int GetNumRegisteredWaitEvents(WaitEventSet *set);
extern bool WaitEventSetCanReportClosed(void);
+extern PGDLLIMPORT bool debug_latch;
#endif /* LATCH_H */
view thread (3+ messages) latest in thread
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected]
Subject: Re: WaitEventSetWaitBlock() can still hang on Windows due to connection reset
In-Reply-To: <[email protected]>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox