Content-Type: multipart/alternative;
 boundary="------------VoSDEU1esE7qw88Uy1BzSYxf"
Message-ID: <180bf13e-235d-46a9-9788-7d6cee40bcdc@gmail.com>
Date: Thu, 5 Feb 2026 07:00:01 +0200
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: BUG: Former primary node might stuck when started as a standby
To: Aleksander Alekseev <aleksander@timescale.com>,
 pgsql-hackers <pgsql-hackers@postgresql.org>
References: <b0102688-6d6c-c86a-db79-e0e91d245b1a@gmail.com>
 <CAJ7c6TOqnv7cZ53RfBv9towSDzNOUVQ74WzPeN7LwoKMuW4tOA@mail.gmail.com>
 <74ea5e7e-9aa0-4d7a-85df-71a9d200a8d8@gmail.com>
 <CAJ7c6TO-_=rfN0Mb1RrChmrQvLtXoWw9aDezwC9g48-Va3E2EQ@mail.gmail.com>
Content-Language: en-US
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: 
 <CAJ7c6TO-_=rfN0Mb1RrChmrQvLtXoWw9aDezwC9g48-Va3E2EQ@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/180bf13e-235d-46a9-9788-7d6cee40bcdc%40gmail.com>
Precedence: bulk

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

Hello,

22.01.2024 13:00, Aleksander Alekseev wrote:
>> Perhaps that's true generally, but as we can see, without the extra
>> records replayed, this scenario works just fine. Moreover, existing tests
>> rely on it, e.g., 009_twophase.pl or 012_subtransactions.pl (in fact, my
>> research of the issue was initiated per a test failure).
> I suggest focusing on particular flaky tests then and how to fix them.

For the record: skink produced the same failure with 009_twophase.pl
yesterday [1]:

366/366 postgresql:recovery / recovery/009_twophase TIMEOUT        15000.31s   killed by signal 15 SIGTERM

[15:11:30.591](0.807s) ok 11 - Restore of prepared transaction on promoted standby
### Enabling streaming replication for node "london"
### Starting node "london"
# Running: pg_ctl --wait --pgdata 
/home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/recovery/009_twophase/data/t_009_twophase_london_data/pgdata 
--log /home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/recovery/009_twophase/log/009_twophase_london.log 
--options --cluster-name=london start
waiting for server to start....... done
server started
# Postmaster PID for node "london" is 4181556
death by signal at /home/bf/bf-build/skink-master/HEAD/pgsql/src/test/perl/PostgreSQL/Test/Cluster.pm line 181.
# Postmaster PID for node "london" is 4181556
### Stopping node "london" using mode immediate
# Running: pg_ctl --pgdata 
/home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/recovery/009_twophase/data/t_009_twophase_london_data/pgdata 
--mode immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "london"
# Postmaster PID for node "paris" is 4147391
### Stopping node "paris" using mode immediate
# Running: pg_ctl --pgdata 
/home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/recovery/009_twophase/data/t_009_twophase_paris_data/pgdata 
--mode immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "paris"
[19:19:46.999](14896.408s) # Tests were run but no plan was declared and done_testing() was not seen.
[19:19:46.999](0.000s) # Looks like your test exited with 4 just after 11.

pgsql.build/testrun/recovery/009_twophase/log/009_twophase_london.log
2026-02-04 15:11:35.675 CET [4181556][postmaster][:0] LOG:  starting PostgreSQL 19devel on x86_64-linux, compiled by 
gcc-15.2.0, 64-bit
2026-02-04 15:11:35.692 CET [4181556][postmaster][:0] LOG: listening on Unix socket "/tmp/IzuUID03TM/.s.PGSQL.22911"
2026-02-04 15:11:35.904 CET [4183900][startup][:0] LOG:  database system was interrupted; last known up at 2026-02-04 
15:11:14 CET
2026-02-04 15:11:36.017 CET [4183900][startup][:0] LOG:  entering standby mode
2026-02-04 15:11:36.019 CET [4183900][startup][:0] LOG:  database system was not properly shut down; automatic recovery 
in progress
2026-02-04 15:11:36.104 CET [4183900][startup][38/0:0] LOG:  redo starts at 0/03021600
2026-02-04 15:11:36.206 CET [4183900][startup][38/0:0] LOG:  invalid record length at 0/030220B8: expected at least 24, 
got 0
2026-02-04 15:11:36.209 CET [4183900][startup][38/0:0] LOG: consistent recovery state reached at 0/030220B8
2026-02-04 15:11:36.210 CET [4181556][postmaster][:0] LOG:  database system is ready to accept read-only connections
2026-02-04 15:11:36.919 CET [4184142][walreceiver][:0] LOG: fetching timeline history file for timeline 2 from primary 
server
2026-02-04 15:11:36.997 CET [4184142][walreceiver][:0] LOG:  started streaming WAL from primary at 0/03000000 on timeline 1
2026-02-04 15:11:37.076 CET [4184142][walreceiver][:0] LOG: replication terminated by primary server
2026-02-04 15:11:37.076 CET [4184142][walreceiver][:0] DETAIL:  End of WAL reached on timeline 1 at 0/03022070.
2026-02-04 15:11:37.098 CET [4183900][startup][38/0:0] LOG:  new timeline 2 forked off current database system timeline 
1 before current recovery point 0/030220B8
2026-02-04 15:11:37.103 CET [4184142][walreceiver][:0] LOG: restarted WAL streaming at 0/03000000 on timeline 1
2026-02-04 15:11:37.107 CET [4184142][walreceiver][:0] LOG: replication terminated by primary server
...

[1] https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=skink&dt=2026-02-04%2013%3A36%3A40&stg=recovery-check

Best regards,
Alexander
--------------VoSDEU1esE7qw88Uy1BzSYxf
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,<br>
      <br>
      22.01.2024 13:00, Aleksander Alekseev wrote:<span
      style="white-space: pre-wrap">
</span></div>
    <blockquote type="cite"
cite="mid:CAJ7c6TO-_=rfN0Mb1RrChmrQvLtXoWw9aDezwC9g48-Va3E2EQ@mail.gmail.com">
      <blockquote type="cite">
        <pre wrap="" class="moz-quote-pre">Perhaps that's true generally, but as we can see, without the extra
records replayed, this scenario works just fine. Moreover, existing tests
rely on it, e.g., 009_twophase.pl or 012_subtransactions.pl (in fact, my
research of the issue was initiated per a test failure).
</pre>
      </blockquote>
      <pre wrap="" class="moz-quote-pre">
I suggest focusing on particular flaky tests then and how to fix them.
</pre>
    </blockquote>
    <br>
    For the record: skink produced the same failure with 009_twophase.pl<br>
    yesterday [1]:<br>
    <br>
    366/366 postgresql:recovery /
    recovery/009_twophase                                    
    TIMEOUT        15000.31s   killed by signal 15 SIGTERM<br>
    <br>
    [15:11:30.591](0.807s) ok 11 - Restore of prepared transaction on
    promoted standby<br>
    ### Enabling streaming replication for node "london"<br>
    ### Starting node "london"<br>
    # Running: pg_ctl --wait --pgdata
/home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/recovery/009_twophase/data/t_009_twophase_london_data/pgdata
    --log
/home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/recovery/009_twophase/log/009_twophase_london.log
    --options --cluster-name=london start<br>
    waiting for server to start....... done<br>
    server started<br>
    # Postmaster PID for node "london" is 4181556<br>
    death by signal at
/home/bf/bf-build/skink-master/HEAD/pgsql/src/test/perl/PostgreSQL/Test/Cluster.pm
    line 181.<br>
    # Postmaster PID for node "london" is 4181556<br>
    ### Stopping node "london" using mode immediate<br>
    # Running: pg_ctl --pgdata
/home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/recovery/009_twophase/data/t_009_twophase_london_data/pgdata
    --mode immediate stop<br>
    waiting for server to shut down.... done<br>
    server stopped<br>
    # No postmaster PID for node "london"<br>
    # Postmaster PID for node "paris" is 4147391<br>
    ### Stopping node "paris" using mode immediate<br>
    # Running: pg_ctl --pgdata
/home/bf/bf-build/skink-master/HEAD/pgsql.build/testrun/recovery/009_twophase/data/t_009_twophase_paris_data/pgdata
    --mode immediate stop<br>
    waiting for server to shut down.... done<br>
    server stopped<br>
    # No postmaster PID for node "paris"<br>
    [19:19:46.999](14896.408s) # Tests were run but no plan was declared
    and done_testing() was not seen.<br>
    [19:19:46.999](0.000s) # Looks like your test exited with 4 just
    after 11.<br>
    <br>
pgsql.build/testrun/recovery/009_twophase/log/009_twophase_london.log<br>
    2026-02-04 15:11:35.675 CET [4181556][postmaster][:0] LOG:  starting
    PostgreSQL 19devel on x86_64-linux, compiled by gcc-15.2.0, 64-bit<br>
    2026-02-04 15:11:35.692 CET [4181556][postmaster][:0] LOG: 
    listening on Unix socket "/tmp/IzuUID03TM/.s.PGSQL.22911"<br>
    2026-02-04 15:11:35.904 CET [4183900][startup][:0] LOG:  database
    system was interrupted; last known up at 2026-02-04 15:11:14 CET<br>
    2026-02-04 15:11:36.017 CET [4183900][startup][:0] LOG:  entering
    standby mode<br>
    2026-02-04 15:11:36.019 CET [4183900][startup][:0] LOG:  database
    system was not properly shut down; automatic recovery in progress<br>
    2026-02-04 15:11:36.104 CET [4183900][startup][38/0:0] LOG:  redo
    starts at 0/03021600<br>
    2026-02-04 15:11:36.206 CET [4183900][startup][38/0:0] LOG:  invalid
    record length at 0/030220B8: expected at least 24, got 0<br>
    2026-02-04 15:11:36.209 CET [4183900][startup][38/0:0] LOG: 
    consistent recovery state reached at 0/030220B8<br>
    2026-02-04 15:11:36.210 CET [4181556][postmaster][:0] LOG:  database
    system is ready to accept read-only connections<br>
    2026-02-04 15:11:36.919 CET [4184142][walreceiver][:0] LOG: 
    fetching timeline history file for timeline 2 from primary server<br>
    2026-02-04 15:11:36.997 CET [4184142][walreceiver][:0] LOG:  started
    streaming WAL from primary at 0/03000000 on timeline 1<br>
    2026-02-04 15:11:37.076 CET [4184142][walreceiver][:0] LOG: 
    replication terminated by primary server<br>
    2026-02-04 15:11:37.076 CET [4184142][walreceiver][:0] DETAIL:  End
    of WAL reached on timeline 1 at 0/03022070.<br>
    2026-02-04 15:11:37.098 CET [4183900][startup][38/0:0] LOG:  new
    timeline 2 forked off current database system timeline 1 before
    current recovery point 0/030220B8<br>
    2026-02-04 15:11:37.103 CET [4184142][walreceiver][:0] LOG: 
    restarted WAL streaming at 0/03000000 on timeline 1<br>
    2026-02-04 15:11:37.107 CET [4184142][walreceiver][:0] LOG: 
    replication terminated by primary server<br>
    ...<br>
    <br>
    [1]
<a class="moz-txt-link-freetext" href="https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=skink&amp;dt=2026-02-04%2013%3A36%3A40&amp;stg=recovery-check">https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=skink&amp;dt=2026-02-04%2013%3A36%3A40&amp;stg=recovery-check</a><br>
    <br>
    Best regards,<br>
    Alexander<br>
  </body>
</html>

--------------VoSDEU1esE7qw88Uy1BzSYxf--