Content-Type: multipart/mixed; boundary="------------2WjKRzPQvlP7FQoSlkG7Wwg1"
Message-ID: <b0102688-6d6c-c86a-db79-e0e91d245b1a@gmail.com>
Date: Thu, 18 Jan 2024 21:00:01 +0300
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.4.2
Content-Language: en-US
To: pgsql-hackers <pgsql-hackers@postgresql.org>
From: Alexander Lakhin <exclusion@gmail.com>
Subject: BUG: Former primary node might stuck when started as a standby
Archived-At: 
 <https://www.postgresql.org/message-id/b0102688-6d6c-c86a-db79-e0e91d245b1a%40gmail.com>
Precedence: bulk

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

Hello hackers,

[ reporting this bug here due to limitations of the bug reporting form ]

When a node, that acted as a primary, becomes a standby as in the
following script:
[ ... some WAL-logged activity ... ]
$primary->teardown_node;
$standby->promote;

$primary->enable_streaming($standby);
$primary->start;

it might not go online, due to the error:
new timeline N forked off current database system timeline M before current recovery point X/X

A complete TAP test is attached.
I put it in src/test/recovery/t, run as follows:
for i in `seq 100`; do echo "iteration $i"; timeout 60 make -s check -C src/test/recovery PROVE_TESTS="t/099*" || break; 
done
and get:
...
iteration 7
# +++ tap check in src/test/recovery +++
t/099_change_roles.pl .. ok
All tests successful.
Files=1, Tests=20, 14 wallclock secs ( 0.01 usr  0.00 sys +  4.20 cusr  4.75 csys =  8.96 CPU)
Result: PASS
iteration 8
# +++ tap check in src/test/recovery +++
t/099_change_roles.pl .. 9/? make: *** [Makefile:23: check] Terminated

With wal_debug enabled (and log_min_messages=DEBUG2, log_statement=all),
I see the following in the _node1.log:
2024-01-18 15:21:02.258 UTC [663701] 099_change_roles.pl LOG: INSERT @ 0/304DBF0:  - Transaction/COMMIT: 2024-01-18 
15:21:02.258739+00
2024-01-18 15:21:02.258 UTC [663701] 099_change_roles.pl STATEMENT: INSERT INTO t VALUES (10, 'inserted on node1');
2024-01-18 15:21:02.258 UTC [663701] 099_change_roles.pl LOG:  xlog flush request 0/304DBF0; write 0/0; flush 0/0
2024-01-18 15:21:02.258 UTC [663701] 099_change_roles.pl STATEMENT: INSERT INTO t VALUES (10, 'inserted on node1');
2024-01-18 15:21:02.258 UTC [663671] node2 DEBUG:  write 0/304DBF0 flush 0/304DB78 apply 0/304DB78 reply_time 2024-01-18 
15:21:02.2588+00
2024-01-18 15:21:02.258 UTC [663671] node2 DEBUG:  write 0/304DBF0 flush 0/304DBF0 apply 0/304DB78 reply_time 2024-01-18 
15:21:02.258809+00
2024-01-18 15:21:02.258 UTC [663671] node2 DEBUG:  write 0/304DBF0 flush 0/304DBF0 apply 0/304DBF0 reply_time 2024-01-18 
15:21:02.258864+00
2024-01-18 15:21:02.259 UTC [663563] DEBUG:  server process (PID 663701) exited with exit code 0
2024-01-18 15:21:02.260 UTC [663563] DEBUG:  forked new backend, pid=663704 socket=8
2024-01-18 15:21:02.261 UTC [663704] 099_change_roles.pl LOG: statement: INSERT INTO t VALUES (1000 * 1 + 608, 
'background activity');
2024-01-18 15:21:02.261 UTC [663704] 099_change_roles.pl LOG: INSERT @ 0/304DC40:  - Heap/INSERT: off: 12, flags: 0x00
2024-01-18 15:21:02.261 UTC [663704] 099_change_roles.pl STATEMENT: INSERT INTO t VALUES (1000 * 1 + 608, 'background 
activity');
2024-01-18 15:21:02.261 UTC [663563] DEBUG:  postmaster received shutdown request signal
2024-01-18 15:21:02.261 UTC [663563] LOG:  received immediate shutdown request
2024-01-18 15:21:02.261 UTC [663704] 099_change_roles.pl LOG: INSERT @ 0/304DC68:  - Transaction/COMMIT: 2024-01-18 
15:21:02.261828+00
2024-01-18 15:21:02.261 UTC [663704] 099_change_roles.pl STATEMENT: INSERT INTO t VALUES (1000 * 1 + 608, 'background 
activity');
2024-01-18 15:21:02.261 UTC [663704] 099_change_roles.pl LOG:  xlog flush request 0/304DC68; write 0/0; flush 0/0
2024-01-18 15:21:02.261 UTC [663704] 099_change_roles.pl STATEMENT: INSERT INTO t VALUES (1000 * 1 + 608, 'background 
activity');
...
2024-01-18 15:21:02.262 UTC [663563] LOG:  database system is shut down
...
2024-01-18 15:21:02.474 UTC [663810] LOG:  starting PostgreSQL 16.1 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 
11.3.0-1ubuntu1~22.04) 11.3.0, 64-bit
...
2024-01-18 15:21:02.478 UTC [663816] LOG:  REDO @ 0/304DBC8; LSN 0/304DBF0: prev 0/304DB78; xid 898; len 8 - 
Transaction/COMMIT: 2024-01-18 15:21:02.258739+00
2024-01-18 15:21:02.478 UTC [663816] LOG:  REDO @ 0/304DBF0; LSN 0/304DC40: prev 0/304DBC8; xid 899; len 3; blkref #0: 
rel 1663/5/16384, blk 1 - Heap/INSERT: off: 12, flags: 0x00
2024-01-18 15:21:02.478 UTC [663816] LOG:  REDO @ 0/304DC40; LSN 0/304DC68: prev 0/304DBF0; xid 899; len 8 - 
Transaction/COMMIT: 2024-01-18 15:21:02.261828+00
...
2024-01-18 15:21:02.481 UTC [663819] LOG:  fetching timeline history file for timeline 20 from primary server
2024-01-18 15:21:02.481 UTC [663819] LOG:  started streaming WAL from primary at 0/3000000 on timeline 19
...
2024-01-18 15:21:02.481 UTC [663819] DETAIL:  End of WAL reached on timeline 19 at 0/304DBF0.
...
2024-01-18 15:21:02.481 UTC [663816] LOG:  new timeline 20 forked off current database system timeline 19 before current 
recovery point 0/304DC68

In this case, node1 wrote to it's WAL record 0/304DC68, but sent to node2
only record 0/304DBF0, then node2, being promoted to primary, forked a next
timeline from it, but when node1 was started as a standby, it first
replayed 0/304DC68 from WAL, and then could not switch to the new timeline
starting from the previous position.

Reproduced on REL_12_STABLE .. master.

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

use strict;
use warnings FATAL => 'all';

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

use IPC::Run;
use threads;
use threads::shared;

sub bgactivity
{
	my @args = @_;
	my ($n, $port, $db_name) = @args;
	$SIG{'KILL'} = sub { print("Thread killed.\n"); threads->exit(); };

	my $try = 1;
	while (1)
	{
		my ($stdout, $stderr);
		my $cmd = [ 'psql', '-h', $ENV{'PGHOST'}, '-p', $port, '-d', $db_name, '-c', "INSERT INTO t VALUES (1000 * $n + $try, 'background activity');" ];
		my $result = IPC::Run::run($cmd, '>', \$stdout, '2>', \$stderr);
		$try += 1;
		sleep(0.001);
	}
}

# Set up two replication nodes, which will switch roles.

my $node1 = PostgreSQL::Test::Cluster->new("node1");
$node1->init(allows_streaming => 1);
$node1->start;
$node1->backup('initial_backup');

my $node2 = PostgreSQL::Test::Cluster->new('node2');
$node2->init_from_backup($node1, 'initial_backup', has_streaming => 1);
$node2->start;

$node1->psql('postgres', "ALTER SYSTEM SET synchronous_standby_names = 'node2'; SELECT pg_reload_conf()");
$node2->psql('postgres', "ALTER SYSTEM SET synchronous_standby_names = 'node1'; SELECT pg_reload_conf()");

$node1->psql('postgres', "CREATE TABLE t(id int, message text)");

my $numthreads = 2;
my @threads;
foreach my $ti (1 .. $numthreads)
{
    push @threads, threads->create('bgactivity', $ti, $node1->port, 'postgres');
}

for (my $i = 1; $i <= 20; $i++)
{
my ($primary, $standby) = ($node1, $node2);

$primary->safe_psql('postgres', "INSERT INTO t VALUES ($i, 'inserted on node1');");

# change roles
$primary->teardown_node;
$standby->promote;

$primary->enable_streaming($standby);
$primary->start;

($primary, $standby) = ($node2, $node1);

$primary->safe_psql('postgres', "INSERT INTO t VALUES ($i, 'inserted on node2');");

# change roles back
$primary->teardown_node;
$standby->promote;

$primary->enable_streaming($standby);
$primary->start;

ok(1);
}

for my $thread (@threads)
{
	$thread->kill('KILL')->detach;
}

done_testing();

--------------2WjKRzPQvlP7FQoSlkG7Wwg1--