Subject: Re: Exit walsender before confirming remote flush in logical replication

From: Alexander Lakhin <[email-masked]>
Date: Sun, 31 May 2026 14:00:01 +0300

Hello Fujii-san,

06.04.2026 18:32, Andres Freund wrote:
> Hi,
>
> On 2026-04-06 11:40:24 +0900, Fujii Masao wrote:
>> I've pushed the patch. Thanks!
> Failed on CI just now:
>
> https://cirrus-ci.com/task/6745359004729344?logs=test_world#L410
> https://api.cirrus-ci.com/v1/artifact/task/6745359004729344/testrun/build/testrun/subscription/038_walsnd_shutdown_timeout/log/regress_log_038_walsnd_shutdown_timeout

A recent failure occurred on the buildfarm [1] indicates another stability
issue, this time with the test itself, I guess:
[21:12:03.301](0.068s) ok 3 - have walreceiver pid 2275585
### Stopping node "publisher" using mode fast
# Running: pg_ctl --pgdata 
/home/bf/bf-build/tamandua/HEAD/pgsql.build/testrun/subscription/038_walsnd_shutdown_timeout/data/t_038_walsnd_shutdown_timeout_publisher_data/pgdata 
--mode fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "publisher"
[21:12:03.752](0.452s) not ok 4 - walsender exits due to wal_sender_shutdown_timeout even when both physical and logical 
replication are stalled
[21:12:03.753](0.001s) #   Failed test 'walsender exits due to wal_sender_shutdown_timeout even when both physical and 
logical replication are stalled'
#   at /home/bf/bf-build/tamandua/HEAD/pgsql/src/test/subscription/t/038_walsnd_shutdown_timeout.pl line 189.
### Stopping node "subscriber" using mode fast

038_walsnd_shutdown_timeout_subscriber.log doesn't really contain the
expected warning:
2026-05-29 21:11:58.777 CEST [2273817][logical replication apply worker][124/2:0] LOG:  logical replication apply worker 
for subscription "test_sub" has started
2026-05-29 21:12:03.232 CEST [2271870][client backend][4/6:0] LOG: statement: BEGIN;
2026-05-29 21:12:03.232 CEST [2271870][client backend][4/6:0] LOG: statement: LOCK TABLE test_tab IN EXCLUSIVE MODE;
2026-05-29 21:12:03.232 CEST [2271870][client backend][4/6:0] LOG: statement: ;
2026-05-29 21:12:03.268 CEST [2273817][logical replication apply worker][124/0:0] LOG:  received message via 
replication: WARNING: replication slot "test_slot" specified in parameter "synchronized_standby_slots" does not have 
active_pid
     DETAIL:  Logical replication is waiting on the standby associated with replication slot "test_slot".
     HINT:  Start the standby associated with the replication slot "test_slot", or amend parameter 
"synchronized_standby_slots".
2026-05-29 21:12:03.433 CEST [2273817][logical replication apply worker][124/0:0] ERROR:  could not receive data from 
WAL stream: ERROR:  replication slot "test_slot" specified in parameter "synchronized_standby_slots" does not have 
active_pid
     DETAIL:  Logical replication is waiting on the standby associated with replication slot "test_slot".
     HINT:  Start the standby associated with the replication slot "test_slot", or amend parameter 
"synchronized_standby_slots".
2026-05-29 21:12:03.437 CEST [2271017][postmaster][:0] LOG: background worker "logical replication apply worker" (PID 
2273817) exited with exit code 1
2026-05-29 21:12:03.439 CEST [2275785][logical replication apply worker][125/2:0] LOG:  logical replication apply worker 
for subscription "test_sub" has started
2026-05-29 21:12:03.441 CEST [2275785][logical replication apply worker][125/0:0] ERROR:  apply worker for subscription 
"test_sub" could not connect to the publisher: connection to server on socket "/tmp/3gDgOpAsXL/.s.PGSQL.27739" failed: 
FATAL:  the database system is shutting down
2026-05-29 21:12:03.445 CEST [2271017][postmaster][:0] LOG: background worker "logical replication apply worker" (PID 
2275785) exited with exit code 1
2026-05-29 21:12:03.763 CEST [2271870][client backend][:0] LOG: disconnection: session time: 0:00:08.180 user=bf 
database=postgres host=[local]
2026-05-29 21:12:03.767 CEST [2271017][postmaster][:0] LOG: received fast shutdown request

I think this can be explained by the fact that walrcv->ready_to_display
is set before WalReceiverMain's loop reached. I've reproduced this test
failure with:
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -280,6 +280,7 @@ WalReceiverMain(const void *startup_data, size_t startup_data_len)
      walrcv->sender_port = 0;
      walrcv->ready_to_display = true;
      SpinLockRelease(&walrcv->mutex);
+pg_usleep(500 * 1000);

      /* Establish the connection to the primary for XLOG streaming */
      appname = cluster_name[0] ? cluster_name : "walreceiver";

Could you please look if this can be improved?

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tamandua&dt=2026-05-29%2019%3A03%3A21

Best regards,
Alexander

---

From: "Hayato Kuroda (Fujitsu)" <[email-masked]>
Date: Mon, 1 Jun 2026 03:57:27 +0000

Dear Alexander, Fujii-san,

> 2026-05-29 21:11:58.777 CEST [2273817][logical replication apply worker][124/2:0] LOG:  logical replication apply worker for subscription "test_sub" has started
...

To confirm; IIUC the warning should be contained on the publisher log, not the
subscriber side. And below log appeared on the publisher;

```
2026-05-29 21:12:03.426 CEST [2275591][walsender][26/1:0] FATAL:  canceling authentication due to timeout
2026-05-29 21:12:03.432 CEST [2273580][checkpointer][:0] LOG:  shutting down
```

Is there a possibility that walsender was shut down during the authentication,
especially in-between BackendInitialize() and end of PerformAuthentication()?

> is set before WalReceiverMain's loop reached. I've reproduced this test

Verified it could reproduce the failure, but there were no "canceling authentication
due to timeout" in the publisher log on my env.

Best regards,
Hayato Kuroda
FUJITSU LIMITED

---

From: Alexander Lakhin <[email-masked]>
Date: Mon, 1 Jun 2026 23:00:00 +0300

Dear Kuroda-san,

> 2026-05-29 21:12:03.432 CEST [2273580][checkpointer][:0] LOG:  shutting down

I'm sorry. I switched to the wrong log file during my investigation.

> due to timeout" in the publisher log on my env.

I think the original failure can be reproduced with:
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -645,6 +645,7 @@ ClientAuthentication(Port *port)
  #endif
      }

+if (am_walsender) pg_usleep(500 * 1000);
      if ((log_connections & LOG_CONNECTION_AUTHENTICATION) &&
          status == STATUS_OK &&
          !MyClientConnectionInfo.authn_id)

With this modification, I can see:
#   Failed test 'walsender exits due to wal_sender_shutdown_timeout even when both physical and logical replication are 
stalled'
#   at t/038_walsnd_shutdown_timeout.pl line 189.
# Looks like you failed 1 test of 4.
t/038_walsnd_shutdown_timeout.pl .. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/4 subtests

038_walsnd_shutdown_timeout_publisher.log contains:
2026-06-01 22:32:35.166 EEST [1851879][client backend][0/0:0] FATAL:  terminating connection due to administrator command
2026-06-01 22:32:35.166 EEST [1851879][client backend][0/0:0] DETAIL:  Signal sent by PID 1851819, UID 1000.
2026-06-01 22:32:35.166 EEST [1851878][walsender][26/1:0] FATAL: canceling authentication due to timeout

Best regards,
Alexander

---

From: Andrey Silitskiy <[email-masked]>
Date: Wed, 3 Jun 2026 17:32:30 +0700

Dear Alexander, Kuroda-san,

IIUC, the problem is that the walreceiver does not reach the main loop
before it receives a signal and this leads to the absence of the required
log on publisher. So what do think of this fix?

Added a check to the test scenario that the walreceiver on standby was
fully initialized and replication started. With this fix, I can not
reproduce failure anymore.

Regards,
Andrey Silitskiy

From 782c48d615abc961ab70cb33013561cedd6e6dac Mon Sep 17 00:00:00 2001
From: "a.silitskiy" <[email-masked]>
Date: Wed, 3 Jun 2026 17:24:09 +0700
Subject: [PATCH v1] Fix walsnd_shutdown_timeout test case

---
 .../subscription/t/038_walsnd_shutdown_timeout.pl  | 14 +++++++++-----
 1 file changed, 9 insertions(+), 5 deletions(-)

diff --git a/src/test/subscription/t/038_walsnd_shutdown_timeout.pl b/src/test/subscription/t/038_walsnd_shutdown_timeout.pl
index f4ed5d97852..ee5d3b77a23 100644
--- a/src/test/subscription/t/038_walsnd_shutdown_timeout.pl
+++ b/src/test/subscription/t/038_walsnd_shutdown_timeout.pl
@@ -164,16 +164,20 @@ $node_standby->append_conf(
 	hot_standby_feedback = on));
 $node_standby->start;
 
+# Wait for replication to start
+$node_publisher->safe_psql('postgres', "INSERT INTO test_tab VALUES (-1);");
+$node_standby->poll_query_until('postgres',
+ "SELECT EXISTS (SELECT 1 FROM test_tab WHERE id = -1)");
+$node_subscriber->poll_query_until('postgres',
+ "SELECT EXISTS (SELECT 1 FROM test_tab WHERE id = -1)");
+
 # Cause the logical apply worker to block on a lock by running conflicting
 # transactions on the publisher and subscriber, stalling logical replication.
-$node_publisher->wait_for_catchup('test_sub');
 $sub_session->query_safe("BEGIN; LOCK TABLE test_tab IN EXCLUSIVE MODE;");
-$node_publisher->safe_psql('postgres', "INSERT INTO test_tab VALUES (-1); ");
+$node_publisher->safe_psql('postgres', "INSERT INTO test_tab VALUES (-2); ");
 
 # Cause the standby's walreceiver to be blocked with SIGSTOP signal,
 # stalling physical replication.
-$node_standby->poll_query_until('postgres',
-	"SELECT EXISTS(SELECT 1 FROM pg_stat_wal_receiver)");
 my $receiverpid = $node_standby->safe_psql('postgres',
 	"SELECT pid FROM pg_stat_wal_receiver");
 like($receiverpid, qr/^[0-9]+$/, "have walreceiver pid $receiverpid");
@@ -184,7 +188,7 @@ $log_offset = -s $node_publisher->logfile;
 # Verify that the walsender exits due to wal_sender_shutdown_timeout
 # even when both physical and logical replication are stalled.
 # wal_sender_shutdown_timeout.
-$node_publisher->safe_psql('postgres', "INSERT INTO test_tab VALUES (-2);");
+$node_publisher->safe_psql('postgres', "INSERT INTO test_tab VALUES (-3);");
 $node_publisher->stop('fast');
 ok( $node_publisher->log_contains(
 		qr/WARNING: .* terminating walsender process due to replication shutdown timeout/,
-- 
2.34.1