Non working timeout detection in logical worker
Hello,
Jehan-Guillaume (in Cc) reported me today a problem with logical
replication, where in case of network issue the walsender is correctly
terminating at the given wal_sender_timeout but the logical worker
kept waiting indefinitely.
The issue is apparently a simple thinko, the timestamp of the last
received activity being unconditionally set at the beginning of the
main processing loop, making any reasonable timeout setting
ineffective. Trivial patch to fix the problem attached.
Attachments:
fix_logical_worker_timeout-v1.diffapplication/octet-stream; name=fix_logical_worker_timeout-v1.diffDownload
diff --git a/src/backend/replication/logical/worker.c b/src/backend/replication/logical/worker.c
index 11e6331f49..ff62303638 100644
--- a/src/backend/replication/logical/worker.c
+++ b/src/backend/replication/logical/worker.c
@@ -1089,6 +1089,8 @@ UpdateWorkerStats(XLogRecPtr last_lsn, TimestampTz send_time, bool reply)
static void
LogicalRepApplyLoop(XLogRecPtr last_received)
{
+ TimestampTz last_recv_timestamp = GetCurrentTimestamp();
+
/*
* Init the ApplyMessageContext which we clean up after each replication
* protocol message.
@@ -1107,7 +1109,6 @@ LogicalRepApplyLoop(XLogRecPtr last_received)
int len;
char *buf = NULL;
bool endofstream = false;
- TimestampTz last_recv_timestamp = GetCurrentTimestamp();
bool ping_sent = false;
long wait_time;
On Thu, Oct 17, 2019 at 08:00:15PM +0200, Julien Rouhaud wrote:
Jehan-Guillaume (in Cc) reported me today a problem with logical
replication, where in case of network issue the walsender is correctly
terminating at the given wal_sender_timeout but the logical worker
kept waiting indefinitely.The issue is apparently a simple thinko, the timestamp of the last
received activity being unconditionally set at the beginning of the
main processing loop, making any reasonable timeout setting
ineffective. Trivial patch to fix the problem attached.
Right, good catch. That's indeed incorrect. The current code would
just keep resetting the timeout if walrcv_receive() returns 0 roughly
once per NAPTIME_PER_CYCLE. The ping sent to the server once reaching
half of wal_receiver_timeout was also broken because of that.
In short, applied and back-patched down to 10.
--
Michael
On Fri, Oct 18, 2019 at 7:32 AM Michael Paquier <michael@paquier.xyz> wrote:
On Thu, Oct 17, 2019 at 08:00:15PM +0200, Julien Rouhaud wrote:
Jehan-Guillaume (in Cc) reported me today a problem with logical
replication, where in case of network issue the walsender is correctly
terminating at the given wal_sender_timeout but the logical worker
kept waiting indefinitely.The issue is apparently a simple thinko, the timestamp of the last
received activity being unconditionally set at the beginning of the
main processing loop, making any reasonable timeout setting
ineffective. Trivial patch to fix the problem attached.Right, good catch. That's indeed incorrect. The current code would
just keep resetting the timeout if walrcv_receive() returns 0 roughly
once per NAPTIME_PER_CYCLE. The ping sent to the server once reaching
half of wal_receiver_timeout was also broken because of that.In short, applied and back-patched down to 10.
Thanks Michael!
On Fri, 18 Oct 2019 07:47:13 +0200
Julien Rouhaud <rjuju123@gmail.com> wrote:
On Fri, Oct 18, 2019 at 7:32 AM Michael Paquier <michael@paquier.xyz> wrote:
On Thu, Oct 17, 2019 at 08:00:15PM +0200, Julien Rouhaud wrote:
Jehan-Guillaume (in Cc) reported me today a problem with logical
replication, where in case of network issue the walsender is correctly
terminating at the given wal_sender_timeout but the logical worker
kept waiting indefinitely.The issue is apparently a simple thinko, the timestamp of the last
received activity being unconditionally set at the beginning of the
main processing loop, making any reasonable timeout setting
ineffective. Trivial patch to fix the problem attached.Right, good catch. That's indeed incorrect. The current code would
just keep resetting the timeout if walrcv_receive() returns 0 roughly
once per NAPTIME_PER_CYCLE. The ping sent to the server once reaching
half of wal_receiver_timeout was also broken because of that.In short, applied and back-patched down to 10.
Thanks Michael!
Thank you both guys!