Content-Type: multipart/mixed; boundary="------------lQc5VQdCXRS5p8dFB6Bw20ti"
Message-ID: <72bd036d-4f2a-8d50-b56e-6b1e3b9ba0a9@gmail.com>
Date: Thu, 11 May 2023 21:00:00 +0300
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.4.2
Subject: Re: BUG #17928: Standby fails to decode WAL on termination of primary
Content-Language: en-US
To: pgsql-bugs@lists.postgresql.org, Thomas Munro <thomas.munro@gmail.com>
References: <17928-aa92416a70ff44a2@postgresql.org>
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: <17928-aa92416a70ff44a2@postgresql.org>
Archived-At: 
 <https://www.postgresql.org/message-id/72bd036d-4f2a-8d50-b56e-6b1e3b9ba0a9%40gmail.com>
Precedence: bulk

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

11.05.2023 11:00, PG Bug reporting form wrote:
> The following bug has been logged on the website:
>
> Bug reference:      17928
> ...
> `git bisect` for this behavior blames 3f1ce9734 (where
> XLogDecodeNextRecord() -> XLogReadRecordAlloc() call was introduced).
>
> A reproducer for the anomaly to follow.
The TAP test that demonstrates the issue is attached. To catch the failure
faster, I place it in multiple directories src/test/recoveryX/t, add
minimal Makefiles, and run (on tmpfs):
for ((i=1;i<=10;i++)); do echo "iteration $i"; NO_TEMP_INSTALL=1 parallel --halt now,fail=1 -j7 --linebuffer --tag make 
-s check -C src/test/{} ::: recovery1 recovery2 recovery3 recovery4 recovery5 recovery6 recovery7 || break; done

iteration 1
recovery1       +++ tap check in src/test/recovery1 +++
recovery2       +++ tap check in src/test/recovery2 +++
recovery3       +++ tap check in src/test/recovery3 +++
recovery4       +++ tap check in src/test/recovery4 +++
recovery5       +++ tap check in src/test/recovery5 +++
recovery6       +++ tap check in src/test/recovery6 +++
recovery7       +++ tap check in src/test/recovery7 +++
...
recovery5       # Restarting primary instance (49)
recovery3       # Restarting primary instance (49)
recovery7       # Restarting primary instance (49)
recovery2       Bailout called.  Further testing stopped:  pg_ctl stop failed
recovery2       FAILED--Further testing stopped: pg_ctl stop failed
recovery2       make: *** [Makefile:6: check] Error 255
parallel: This job failed:
make -s check -C src/test/recovery2

tail src/test/recovery2/tmp_check/log/099_restart_with_stanby_standby.log
2023-05-11 20:19:22.247 MSK [2046385] DETAIL:  End of WAL reached on timeline 1 at 3/64BDFF8.
2023-05-11 20:19:22.247 MSK [2046385] FATAL:  could not send end-of-streaming message to primary: server closed the 
connection unexpectedly
                 This probably means the server terminated abnormally
                 before or while processing the request.
         no COPY in progress
2023-05-11 20:19:22.248 MSK [2037134] FATAL:  invalid memory alloc request size 2021163525
2023-05-11 20:19:22.248 MSK [2037114] LOG:  startup process (PID 2037134) exited with exit code 1
2023-05-11 20:19:22.248 MSK [2037114] LOG:  terminating any other active server processes
2023-05-11 20:19:22.248 MSK [2037114] LOG:  shutting down due to startup process failure
2023-05-11 20:19:22.249 MSK [2037114] LOG:  database system is shut down

Best regards,
Alexander
--------------lQc5VQdCXRS5p8dFB6Bw20ti
Content-Type: application/x-perl; name="099_restart_with_stanby.pl"
Content-Disposition: attachment; filename="099_restart_with_stanby.pl"
Content-Transfer-Encoding: 7bit

# Test standby with restarting primary
use strict;
use warnings;

use PostgreSQL::Test::Cluster;
use PostgreSQL::Test::Utils;
use Test::More tests => 1;

my $node_primary = PostgreSQL::Test::Cluster->new('primary');
$node_primary->init(allows_streaming => 1, auth_extra => [ '--create-role', 'repl_role' ]);

$node_primary->append_conf('postgresql.conf', "
max_connections = 100
fsync = off
log_statement = 'none'
wal_keep_size = 2000
");
$node_primary->start;
$node_primary->safe_psql('postgres', "create table tbl(id int, t1 text);");

my $backup_name = 'initial_backup';
$node_primary->backup($backup_name);

my $node_standby = PostgreSQL::Test::Cluster->new('standby');
$node_standby->init_from_backup($node_primary, $backup_name, has_streaming => 1);
$node_standby->append_conf('postgresql.conf', "
fsync = off
");

$node_standby->start;

open(FH, '>', "pgb.sql") or die $!;
print FH <<'EOF';
  insert into tbl (id, t1) select g, repeat('x', 500) from generate_series(1, 1000) g;
  truncate tbl;
EOF
close(FH);

my $pgbench;
my ($pgb_stdin, $pgb_stdout, $pgb_stderr) = ('', '', '');
my $restarts = 0;

while ($restarts < 100) {
    my $standby_state = $node_standby->safe_psql('postgres', 'SELECT 1');
    if ($standby_state != 1) { diag("Standby check failed."); last; }

    $restarts++;
    diag("Restarting primary instance ($restarts)");
    $node_primary->stop();
    $pgbench and $pgbench->finish();
    $node_primary->start();

    $pgbench = IPC::Run::start(
        ['pgbench', '--no-vacuum', '--file=pgb.sql', '--time=60', '--client=5', '--jobs=5',  $node_primary->connstr('postgres')],
        \$pgb_stdin, \$pgb_stdout, \$pgb_stderr);
    sleep(2);
}

$pgbench->finish();

ok(1, "ok");
done_testing();

--------------lQc5VQdCXRS5p8dFB6Bw20ti--