Content-Type: multipart/alternative;
 boundary="------------AnvyfELGeRtVE94oOS8BLF6N"
Message-ID: <923f6d11-f43b-48c8-a8ed-3f7da6493374@gmail.com>
Date: Sun, 31 May 2026 14:00:01 +0300
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: Exit walsender before confirming remote flush in logical
 replication
To: Fujii Masao <masao.fujii@gmail.com>
Cc: Andres Freund <andres@anarazel.de>,
 Andrey Silitskiy <a.silitskiy@postgrespro.ru>,
 Alexander Korotkov <aekorotkov@gmail.com>,
 Greg Sabino Mullane <htamfids@gmail.com>, Japin Li <japinli@hotmail.com>,
 Ronan Dunklau <ronan@dunklau.fr>, Vitaly Davydov <v.davydov@postgrespro.ru>,
 "Hayato Kuroda (Fujitsu)" <kuroda.hayato@fujitsu.com>,
 "Takamichi Osumi (Fujitsu)" <osumi.takamichi@fujitsu.com>,
 "pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>,
 "sawada.mshk@gmail.com" <sawada.mshk@gmail.com>,
 "michael@paquier.xyz" <michael@paquier.xyz>,
 "peter.eisentraut@enterprisedb.com" <peter.eisentraut@enterprisedb.com>,
 "dilipbalaut@gmail.com" <dilipbalaut@gmail.com>,
 "amit.kapila16@gmail.com" <amit.kapila16@gmail.com>,
 Kyotaro Horiguchi <horikyota.ntt@gmail.com>,
 Peter Smith <smithpb2250@gmail.com>
References: <aed6b990-e7d8-40d1-96a4-64ccbfbda876@postgrespro.ru>
 <CAHGQGwHZnhodg7+xQZQOoRhX+emPUoPPgKZm7fOYOH3DpxxC8g@mail.gmail.com>
 <CAPpHfdvzwRo8chZax1_qscfuQJer5r8oQpYDqOURbP9uHTZrsQ@mail.gmail.com>
 <fa4f3713-3e9e-4e6d-8be1-4ca5e2fe8bff@postgrespro.ru>
 <8a250eda-77c2-4872-b675-35513b74b8af@postgrespro.ru>
 <CAHGQGwE-vmNX_DGo5k4YiCzAwLvT0qijnSK9P1jwXm5rUS-sKw@mail.gmail.com>
 <CAHGQGwGkenMEafuytQM4u4_hT43ynLm_JvPoUZ0QsChiNhB6YA@mail.gmail.com>
 <5734c326-9051-4cda-b0d9-dd7b87b2218e@postgrespro.ru>
 <CAHGQGwHScfvDU742KEn9e3A6uJH3FEAnQVOKc_y--7MTyJKKQw@mail.gmail.com>
 <CAHGQGwEaqDGst+35MoB_s0TaQO+FRH8u4Dv7Z+FjCWda5RHC1g@mail.gmail.com>
 <vwlugmsogfn36jhm56zwrgd7m6xe6ircltvfh3kzt6kldvbtht@f45dgow5uhnx>
Content-Language: en-US
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: <vwlugmsogfn36jhm56zwrgd7m6xe6ircltvfh3kzt6kldvbtht@f45dgow5uhnx>
Archived-At: 
 <https://www.postgresql.org/message-id/923f6d11-f43b-48c8-a8ed-3f7da6493374%40gmail.com>
Precedence: bulk

This is a multi-part message in MIME format.
--------------AnvyfELGeRtVE94oOS8BLF6N
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit

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
--------------AnvyfELGeRtVE94oOS8BLF6N
Content-Type: text/html; charset=UTF-8
Content-Transfer-Encoding: 8bit

<!DOCTYPE html>
<html>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
  </head>
  <body>
    <div class="moz-cite-prefix">Hello Fujii-san,<br>
      <br>
      06.04.2026 18:32, Andres Freund wrote:<br>
    </div>
    <blockquote type="cite"
cite="mid:vwlugmsogfn36jhm56zwrgd7m6xe6ircltvfh3kzt6kldvbtht@f45dgow5uhnx">
      <pre wrap="" class="moz-quote-pre">Hi,

On 2026-04-06 11:40:24 +0900, Fujii Masao wrote:
</pre>
      <blockquote type="cite">
        <pre wrap="" class="moz-quote-pre">
I've pushed the patch. Thanks!
</pre>
      </blockquote>
      <pre wrap="" class="moz-quote-pre">
Failed on CI just now:

<a class="moz-txt-link-freetext" href="https://cirrus-ci.com/task/6745359004729344?logs=test_world#L410">https://cirrus-ci.com/task/6745359004729344?logs=test_world#L410</a>
<a class="moz-txt-link-freetext" href="https://api.cirrus-ci.com/v1/artifact/task/6745359004729344/testrun/build/testrun/subscription/038_walsnd_shutdown_timeout/log/regress_log_038_walsnd_shutdown_timeout">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>
</pre>
    </blockquote>
    <br>
    A recent failure occurred on the buildfarm [1] indicates another
    stability<br>
    issue, this time with the test itself, I guess:<br>
    [21:12:03.301](0.068s) ok 3 - have walreceiver pid 2275585<br>
    ### Stopping node "publisher" using mode fast<br>
    # 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<br>
    waiting for server to shut down.... done<br>
    server stopped<br>
    # No postmaster PID for node "publisher"<br>
    [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<br>
    [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'<br>
    #   at
/home/bf/bf-build/tamandua/HEAD/pgsql/src/test/subscription/t/038_walsnd_shutdown_timeout.pl
    line 189.<br>
    ### Stopping node "subscriber" using mode fast<br>
    <br>
    038_walsnd_shutdown_timeout_subscriber.log doesn't really contain
    the<br>
    expected warning:<br>
    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<br>
    2026-05-29 21:12:03.232 CEST [2271870][client backend][4/6:0] LOG: 
    statement: BEGIN;<br>
    2026-05-29 21:12:03.232 CEST [2271870][client backend][4/6:0] LOG: 
    statement: LOCK TABLE test_tab IN EXCLUSIVE MODE;<br>
    2026-05-29 21:12:03.232 CEST [2271870][client backend][4/6:0] LOG: 
    statement: ;<br>
    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<br>
        DETAIL:  Logical replication is waiting on the standby
    associated with replication slot "test_slot".<br>
        HINT:  Start the standby associated with the replication slot
    "test_slot", or amend parameter "synchronized_standby_slots".<br>
    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<br>
        DETAIL:  Logical replication is waiting on the standby
    associated with replication slot "test_slot".<br>
        HINT:  Start the standby associated with the replication slot
    "test_slot", or amend parameter "synchronized_standby_slots".<br>
    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<br>
    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<br>
    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<br>
    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<br>
    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]<br>
    2026-05-29 21:12:03.767 CEST [2271017][postmaster][:0] LOG: 
    received fast shutdown request<br>
    <br>
    I think this can be explained by the fact that
    walrcv-&gt;ready_to_display<br>
    is set before WalReceiverMain's loop reached. I've reproduced this
    test<br>
    failure with:<br>
    --- a/src/backend/replication/walreceiver.c<br>
    +++ b/src/backend/replication/walreceiver.c<br>
    @@ -280,6 +280,7 @@ WalReceiverMain(const void *startup_data, size_t
    startup_data_len)<br>
         walrcv-&gt;sender_port = 0;<br>
         walrcv-&gt;ready_to_display = true;<br>
         SpinLockRelease(&amp;walrcv-&gt;mutex);<br>
    +pg_usleep(500 * 1000);<br>
     <br>
         /* Establish the connection to the primary for XLOG streaming
    */<br>
         appname = cluster_name[0] ? cluster_name : "walreceiver";<br>
    <br>
    <br>
    Could you please look if this can be improved?<br>
    <br>
    [1]
<a class="moz-txt-link-freetext" href="https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tamandua&amp;dt=2026-05-29%2019%3A03%3A21">https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tamandua&amp;dt=2026-05-29%2019%3A03%3A21</a><br>
    <br>
    Best regards,<br>
    Alexander<br>
  </body>
</html>

--------------AnvyfELGeRtVE94oOS8BLF6N--