Content-Type: multipart/mixed; boundary="------------fN1inPCvOwKVfufQULVw7HFx"
Message-ID: <acf3141b-c78d-4f28-8e15-92ed8144331e@arenadata.io>
Date: Thu, 7 Nov 2024 22:19:16 +0300
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Content-Language: en-US
To: pgsql-general@postgresql.org
From: Evgeniy Ratkov <e.ratkov@arenadata.io>
Subject: How to recover correctly master and replica using backup made by
 pg_basebackup?
Archived-At: <https://www.postgresql.org/message-id/acf3141b-c78d-4f28-8e15-92ed8144331e%40arenadata.io>
Precedence: bulk

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

Hello.

I try to use pg_basebackup to make backup and recover master and replica 
from it.
I recover master with action "promote". Next, I recover replica from the 
same
backup with action "shutdown". After it, I start replica with configured 
connection
and replication slot to the master. I get error, because replica reads 
and applies
all WAL of irrelevant timeline, which contains logs after restore point.

I wrote Perl script for pg_basebackup's TAP tests. It is attached as 
file "050_check_replication.pl".
It works on PostgreSQL 17, commit 
7d85d87f4d5c35fd5b2d38adaef63dfbfa542ccc after
applying small patch, which adds possibility to start node with shutdown 
option.
Patch is attached as file "add_node_start_with_shutdown.diff".

Script generates situation when timeline changes several times. Small 
schema may
explain it:

Timeline 1:
   Create the first backup
   Create restore point 'rp_repl_bug'
Timeline 1 -> 2:
   Recovery with promote using the first backup and 'rp_repl_bug'
   Create the second backup
   Create restore point 'rp_repl_bug2'
Timeline 2 -> 3:
   Recovery with promote using the second backup and 'rp_repl_bug2'
Timeline 1 -> 4:
   Recovery with promote using the first backup and 'rp_repl_bug'

After it I get "00000004.history" file, which looks strange:
1    0/3000090    at restore point "rp_repl_bug"
2    0/5000090    at restore point "rp_repl_bug2"
3    0/3000090    at restore point "rp_repl_bug"

Next, I try to restore replica from the first backup. Replica did not 
find WAL for
timeline 4 and downloaded and applied WAL for timeline 2.

cp: cannot stat '${ARCHIVE_PATH}/000000040000000000000003': No such file 
or directory
LOG:  redo starts at 0/2000028
cp: cannot stat '${ARCHIVE_PATH}/000000040000000000000003': No such file 
or directory
'${ARCHIVE_PATH}/000000020000000000000003' -> 
'${REPLICA_PGDATA}/pg_wal/RECOVERYXLOG'
LOG:  restored log file "000000020000000000000003" from archive
LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 
0/2000120
LOG:  consistent recovery state reached at 0/2000120
LOG:  recovery stopping at restore point "rp_repl_bug", time 2024-11-05 
22:00:16.037126+03

Than, at the next replica's start (with configured connection to the 
master and
replication slot) replica can not start receiving WAL from master, 
because it
applied all WAL from timeline 2 including all lines after LSN, where it 
should
switch timeline:

LOG:  entering standby mode
LOG:  redo starts at 0/2000028
LOG:  consistent recovery state reached at 0/3000090
LOG:  database system is ready to accept read-only connections
LOG:  started streaming WAL from primary at 0/4000000 on timeline 4
FATAL:  could not receive data from WAL stream: ERROR:  requested 
starting point 0/4000000 is ahead of the WAL flush position of this 
server 0/3002000

If I restart replica, it will not start:
LOG:  database system was shut down in recovery at 2024-11-05 22:00:18 MSK
LOG:  entering standby mode
FATAL:  requested timeline 4 is not a child of this server's history
DETAIL:  Latest checkpoint is at 0/3000090 on timeline 2, but in the 
history of the requested timeline, the server forked off from that 
timeline at 0/5000090.
LOG:  startup process (PID 2384880) exited with exit code 1

Questions:

1) Why does mirror not switch to the next timeline when it get LSN in 
WAL, which
there is in the history file? And why does mirror apply all WAL?
2) Why does 00000004.history contain info about switching from 2 and 3 
timelines
even if the 4 timeline was switched from the first timeline?

Thank you in advance.

--------------fN1inPCvOwKVfufQULVw7HFx
Content-Type: text/x-patch; charset=UTF-8;
 name="add_node_start_with_shutdown.diff"
Content-Disposition: attachment; filename="add_node_start_with_shutdown.diff"
Content-Transfer-Encoding: base64

ZGlmZiAtLWdpdCBhL3NyYy90ZXN0L3BlcmwvUG9zdGdyZVNRTC9UZXN0L0NsdXN0ZXIucG0g
Yi9zcmMvdGVzdC9wZXJsL1Bvc3RncmVTUUwvVGVzdC9DbHVzdGVyLnBtCmluZGV4IDAwNzU3
MWU5NDguLmUxOGViM2FhY2UgMTAwNjQ0Ci0tLSBhL3NyYy90ZXN0L3BlcmwvUG9zdGdyZVNR
TC9UZXN0L0NsdXN0ZXIucG0KKysrIGIvc3JjL3Rlc3QvcGVybC9Qb3N0Z3JlU1FML1Rlc3Qv
Q2x1c3Rlci5wbQpAQCAtMTExMiw3ICsxMTEyLDcgQEAgaW5zdGVhZCByZXR1cm4gYSB0cnVl
IG9yIGZhbHNlIHZhbHVlIHRvIGluZGljYXRlIHN1Y2Nlc3Mgb3IgZmFpbHVyZS4KIAogPWN1
dAogCi1zdWIgc3RhcnQKK3N1YiBfc3RhcnQKIHsKIAlteSAoJHNlbGYsICVwYXJhbXMpID0g
QF87CiAJbXkgJHBvcnQgPSAkc2VsZi0+cG9ydDsKQEAgLTExNTAsMTEgKzExNTAsMjMgQEAg
c3ViIHN0YXJ0CiAJCUJBSUxfT1VUKCJwZ19jdGwgc3RhcnQgZmFpbGVkIikgdW5sZXNzICRw
YXJhbXN7ZmFpbF9va307CiAJCXJldHVybiAwOwogCX0KK30KIAorc3ViIHN0YXJ0Cit7CisJ
bXkgKCRzZWxmKSA9IEBfOworCSRzZWxmLT5fc3RhcnQ7CiAJJHNlbGYtPl91cGRhdGVfcGlk
KDEpOwogCXJldHVybiAxOwogfQogCitzdWIgc3RhcnRfd2l0aF9lbmFibGVkX3NodXRkb3du
Cit7CisJbXkgKCRzZWxmKSA9IEBfOworCSRzZWxmLT5fc3RhcnQ7CisJcmV0dXJuIDE7Cit9
CisKID1wb2QKIAogPWl0ZW0gJG5vZGUtPmtpbGw5KCkK
--------------fN1inPCvOwKVfufQULVw7HFx
Content-Type: application/x-perl; name="050_check_replication.pl"
Content-Disposition: attachment; filename="050_check_replication.pl"
Content-Transfer-Encoding: 7bit

use strict;
use warnings;
use File::Basename qw(basename dirname);
use File::Compare;
use File::Path qw(rmtree);

use PostgreSQL::Test::Cluster;
use PostgreSQL::Test::Utils;
use Test::More;

# Set umask so test directories and files are created with default permissions
umask(0077);

my $tempdir = PostgreSQL::Test::Utils::tempdir;
my $basebackupdir = $tempdir . '/basebackup';
my $basebackupdir2 = $tempdir . '/basebackup2';
my $archivedir =  $tempdir . '/archive';

my $primary = PostgreSQL::Test::Cluster->new('primary');
my $replica = PostgreSQL::Test::Cluster->new('replica');

# Initialize primary
$primary->init(allows_streaming => 1, extra => ['--data-checksums']);
$primary->append_conf("postgresql.conf", "archive_mode = 'on'");
$primary->append_conf("postgresql.conf", "archive_command = 'cp -rv %p $archivedir/'");
$primary->start;

# Initialize replica
$replica->init(extra => ['--data-checksums']);

my $primary_pgdata = $primary->data_dir;
my $replica_pgdata = $replica->data_dir;
my $replica_port = $replica->port;

mkdir($basebackupdir);
mkdir($basebackupdir2);
mkdir($archivedir);

$primary->safe_psql('postgres', 'CREATE DATABASE test_db');
$primary->safe_psql('test_db', 'CREATE TABLE test as select generate_series(1,10)');
$primary->safe_psql('postgres', 'CREATE ROLE postgres WITH LOGIN REPLICATION');

$primary->command_ok([ 'pg_basebackup', '-D', "$basebackupdir", '-p', $primary->port, '--verbose' ],
	'pg_basebackup runs');
ok(-f "$basebackupdir/PG_VERSION", 'backup was created');

$primary->safe_psql('test_db', "SELECT pg_create_restore_point('rp_repl_bug')");
$primary->stop('smart');

# apply base backup to generate the second timeline from the first (1 -> 2)
$primary->command_ok([ 'rm', '-rf', $primary_pgdata ],
	'first rm primary pgdata');
$primary->command_ok([ 'cp', '-r', $basebackupdir, $primary_pgdata ],
	'first copy basebackup to primary');
# configure recovery
$primary->set_recovery_mode;
open my $conf, '>', "$primary_pgdata/postgresql.auto.conf";
print $conf "synchronous_standby_names = '*'\n";
print $conf "recovery_target_action = 'promote'\n";
print $conf "restore_command = 'cp -vr $archivedir/%f $primary_pgdata/%p'\n";
print $conf "recovery_target_name = 'rp_repl_bug'\n";
close $conf;
$primary->start;

$primary->safe_psql('test_db', "SELECT pg_switch_wal()");

$primary->command_ok([ 'pg_basebackup', '-D', "$basebackupdir2", '-p', $primary->port, '--verbose' ],
	'second pg_basebackup runs');
ok(-f "$basebackupdir2/PG_VERSION", 'backup was created');

$primary->safe_psql('test_db', "SELECT pg_create_restore_point('rp_repl_bug2')");
$primary->stop('smart');

# apply base backup to generate the third timeline from the second (2 -> 3)
$primary->command_ok([ 'rm', '-rf', $primary_pgdata ],
	'second rm primary pgdata');
$primary->command_ok([ 'cp', '-r', $basebackupdir2, $primary_pgdata ],
	'second copy basebackup to primary');
# configure recovery
$primary->set_recovery_mode;
open $conf, '>', "$primary_pgdata/postgresql.auto.conf";
print $conf "synchronous_standby_names = '*'\n";
print $conf "recovery_target_action = 'promote'\n";
print $conf "restore_command = 'cp -vr $archivedir/%f $primary_pgdata/%p'\n";
print $conf "recovery_target_name = 'rp_repl_bug2'\n";
close $conf;
$primary->start;

$primary->safe_psql('test_db', "SELECT pg_switch_wal()");
$primary->stop('smart');

# apply base backup to generate the fourth timeline from the first (1 -> 4)
$primary->command_ok([ 'rm', '-rf', $primary_pgdata ],
	'second rm primary pgdata');
$primary->command_ok([ 'cp', '-r', $basebackupdir, $primary_pgdata ],
	'second copy basebackup to primary');
# configure recovery
$primary->set_recovery_mode;
open $conf, '>', "$primary_pgdata/postgresql.auto.conf";
print $conf "synchronous_standby_names = '*'\n";
print $conf "recovery_target_action = 'promote'\n";
print $conf "restore_command = 'cp -vr $archivedir/%f $primary_pgdata/%p'\n";
print $conf "recovery_target_name = 'rp_repl_bug'\n";
close $conf;
$primary->start;

$primary->safe_psql('test_db', "SELECT pg_create_physical_replication_slot('internal_wal_replication_slot')");

# configure replica to recovery
$replica->command_ok([ 'rm', '-rf', $replica_pgdata ],
	'rm replica pgdata');
$replica->command_ok([ 'cp', '-r', $basebackupdir, $replica_pgdata ],
	'copy basebackup to replica');

$replica->set_recovery_mode;
open $conf, '>', "$replica_pgdata/postgresql.auto.conf";
print $conf "synchronous_standby_names = '*'\n";
print $conf "recovery_target_action = 'shutdown'\n";
print $conf "restore_command = 'cp -vr $archivedir/%f $replica_pgdata/%p'\n";
print $conf "recovery_target_name = 'rp_repl_bug'\n";
close $conf;
$replica->adjust_conf('postgresql.conf', 'port', $replica_port);
$replica->start_with_enabled_shutdown;

$replica->start;

# configure primary connection with replication slot
unlink "$replica_pgdata/recovery.signal";
$replica->set_standby_mode;
open $conf, '>', "$replica_pgdata/postgresql.auto.conf";
print $conf "primary_conninfo = ";
print $conf "'user=postgres port=" . $primary->port;
print $conf " host=" . $primary->host;
print $conf " sslmode=prefer sslcompression=1 gssencmode=prefer";
print $conf " krbsrvname=postgres target_session_attrs=any";
print $conf " application_name=gp_walreceiver'\n";
print $conf "primary_slot_name = 'internal_wal_replication_slot'\n";
close $conf;

$replica->reload;

# After restart replica does not start because of error
$replica->restart;

$replica->teardown_node;
$primary->teardown_node;

done_testing();

--------------fN1inPCvOwKVfufQULVw7HFx--