Content-Type: multipart/alternative;
 boundary="------------Mbqq4TnGn0pzoLhD9zataQC0"
Message-ID: <74ff6252-3450-4508-9d16-1cdc891b3cb9@gmail.com>
Date: Mon, 1 Jun 2026 23:00:00 +0300
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: Exit walsender before confirming remote flush in logical
 replication
To: "Hayato Kuroda (Fujitsu)" <kuroda.hayato@fujitsu.com>,
 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>,
 "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>
 <923f6d11-f43b-48c8-a8ed-3f7da6493374@gmail.com>
 <OS9PR01MB1214984918640A7AC5BEE2A0AF5152@OS9PR01MB12149.jpnprd01.prod.outlook.com>
Content-Language: en-US
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: 
 <OS9PR01MB1214984918640A7AC5BEE2A0AF5152@OS9PR01MB12149.jpnprd01.prod.outlook.com>
Archived-At: 
 <https://www.postgresql.org/message-id/74ff6252-3450-4508-9d16-1cdc891b3cb9%40gmail.com>
Precedence: bulk

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

Dear Kuroda-san,

01.06.2026 06:57, Hayato Kuroda (Fujitsu) wrote:
>> 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;
> ...
>
> 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
> ```

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

>
> Is there a possibility that walsender was shut down during the authentication,
> especially in-between BackendInitialize() and end of PerformAuthentication()?
>
>> 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:
> Verified it could reproduce the failure, but there were no "canceling authentication
> 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
--------------Mbqq4TnGn0pzoLhD9zataQC0
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">Dear Kuroda-san,<br>
      <br>
      01.06.2026 06:57, Hayato Kuroda (Fujitsu) wrote:<span
      style="white-space: pre-wrap">
</span></div>
    <blockquote type="cite"
cite="mid:OS9PR01MB1214984918640A7AC5BEE2A0AF5152@OS9PR01MB12149.jpnprd01.prod.outlook.com">
      <pre wrap="" class="moz-quote-pre">
</pre>
      <blockquote type="cite">
        <pre wrap="" class="moz-quote-pre">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;
</pre>
      </blockquote>
      <pre wrap="" class="moz-quote-pre">...

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
```</pre>
    </blockquote>
    <br>
    I'm sorry. I switched to the wrong log file during my
    investigation.  <br>
    <br>
    <blockquote type="cite"
cite="mid:OS9PR01MB1214984918640A7AC5BEE2A0AF5152@OS9PR01MB12149.jpnprd01.prod.outlook.com">
      <pre wrap="" class="moz-quote-pre">

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

</pre>
      <blockquote type="cite">
        <pre wrap="" class="moz-quote-pre">I think this can be explained by the fact that walrcv-&gt;ready_to_display
is set before WalReceiverMain's loop reached. I've reproduced this test
failure with:
</pre>
      </blockquote>
      <pre wrap="" class="moz-quote-pre">
Verified it could reproduce the failure, but there were no "canceling authentication
due to timeout" in the publisher log on my env.
</pre>
    </blockquote>
    <br>
    I think the original failure can be reproduced with:<br>
    --- a/src/backend/libpq/auth.c<br>
    +++ b/src/backend/libpq/auth.c<br>
    @@ -645,6 +645,7 @@ ClientAuthentication(Port *port)<br>
     #endif<br>
         }<br>
     <br>
    +if (am_walsender) pg_usleep(500 * 1000);<br>
         if ((log_connections &amp; LOG_CONNECTION_AUTHENTICATION)
    &amp;&amp;<br>
             status == STATUS_OK &amp;&amp;<br>
             !MyClientConnectionInfo.authn_id)<br>
    <br>
    With this modification, I can see:<br>
    #   Failed test 'walsender exits due to wal_sender_shutdown_timeout
    even when both physical and logical replication are stalled'<br>
    #   at t/038_walsnd_shutdown_timeout.pl line 189.<br>
    # Looks like you failed 1 test of 4.<br>
    t/038_walsnd_shutdown_timeout.pl .. Dubious, test returned 1 (wstat
    256, 0x100)<br>
    Failed 1/4 subtests <br>
    <br>
    038_walsnd_shutdown_timeout_publisher.log contains:<br>
    2026-06-01 22:32:35.166 EEST [1851879][client backend][0/0:0]
    FATAL:  terminating connection due to administrator command<br>
    2026-06-01 22:32:35.166 EEST [1851879][client backend][0/0:0]
    DETAIL:  Signal sent by PID 1851819, UID 1000.<br>
    2026-06-01 22:32:35.166 EEST [1851878][walsender][26/1:0] FATAL: 
    canceling authentication due to timeout<br>
    <br>
    Best regards,<br>
    Alexander<br>
  </body>
</html>

--------------Mbqq4TnGn0pzoLhD9zataQC0--