Content-Type: multipart/mixed; boundary="------------PVwN0cJ0Xx5GEsnbMLeWYxGu"
Message-ID: <f15d665f-4cd1-4894-037c-afdbe369287e@gmail.com>
Date: Wed, 29 May 2024 14: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
Content-Language: en-US
From: Alexander Lakhin <exclusion@gmail.com>
Subject: 001_rep_changes.pl fails due to publisher stuck on shutdown
To: pgsql-hackers <pgsql-hackers@postgresql.org>
Archived-At: <https://www.postgresql.org/message-id/f15d665f-4cd1-4894-037c-afdbe369287e%40gmail.com>
Precedence: bulk

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

Hello hackers,

As a recent buildfarm test failure [1] shows:
[14:33:02.374](0.333s) ok 23 - update works with dropped subscriber column
### Stopping node "publisher" using mode fast
# Running: pg_ctl -D 
/home/bf/bf-build/adder/HEAD/pgsql.build/testrun/subscription/001_rep_changes/data/t_001_rep_changes_publisher_data/pgdata 
-m fast stop
waiting for server to shut down.. ... ... ... .. failed
pg_ctl: server does not shut down
# pg_ctl stop failed: 256
# Postmaster PID for node "publisher" is 2222549
[14:39:04.375](362.001s) Bail out!  pg_ctl stop failed

001_rep_changes_publisher.log
2024-05-16 14:33:02.907 UTC [2238704][client backend][4/22:0] LOG: statement: DELETE FROM tab_rep
2024-05-16 14:33:02.925 UTC [2238704][client backend][:0] LOG: disconnection: session time: 0:00:00.078 user=bf 
database=postgres host=[local]
2024-05-16 14:33:02.939 UTC [2222549][postmaster][:0] LOG:  received fast shutdown request
2024-05-16 14:33:03.000 UTC [2222549][postmaster][:0] LOG:  aborting any active transactions
2024-05-16 14:33:03.049 UTC [2222549][postmaster][:0] LOG: background worker "logical replication launcher" (PID 
2223110) exited with exit code 1
2024-05-16 14:33:03.062 UTC [2222901][checkpointer][:0] LOG: shutting down
2024-05-16 14:39:04.377 UTC [2222549][postmaster][:0] LOG:  received immediate shutdown request
2024-05-16 14:39:04.382 UTC [2222549][postmaster][:0] LOG:  database system is shut down

the publisher node may hang on stopping.

I reproduced the failure (with aggressive autovacuum) locally and
discovered that it happens because:
1) checkpointer calls WalSndInitStopping() (which sends
  PROCSIG_WALSND_INIT_STOPPING to walsender), and then spins inside
  WalSndWaitStopping() indefinitely, because:
2) walsender receives the signal, sets got_STOPPING = true, but can't exit
WalSndLoop():
3) it never sets got_SIGUSR2 (to get into WalSndDone()) in
  XLogSendLogical():
4) it never sets WalSndCaughtUp to true:
5) logical_decoding_ctx->reader->EndRecPtr can't reach flushPtr in
  XLogSendLogical():
6) EndRecPtr doesn't advance in XLogNextRecord():
7) XLogDecodeNextRecord() fails do decode a record that crosses a page
  boundary:
8) ReadPageInternal() (commented "Wait for the next page to become
  available") constantly returns XLREAD_FAIL:
9) state->routine.page_read()/logical_read_xlog_page() constantly returns
  -1:
10) flushptr = WalSndWaitForWal() stops advancing, because
  got_STOPPING == true (see 2).

That is, walsender doesn't let itself to catch up, if it gets the stop
signal when it's lagging behind and decoding a record requires reading
the next wal page.

Please look at the reproducing test (based on 001_rep_changes.pl) attached.
If fails for me as below:
# 17
Bailout called.  Further testing stopped:  pg_ctl stop failed
FAILED--Further testing stopped: pg_ctl stop failed
make: *** [Makefile:21: check] Ошибка 255

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=adder&dt=2024-05-16%2014%3A22%3A38
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dikkop&dt=2024-04-24%2014%3A38%3A35 (apparently the same)

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

# Copyright (c) 2021-2024, PostgreSQL Global Development Group

# Basic logical replication test
use strict;
use warnings FATAL => 'all';
use PostgreSQL::Test::Cluster;
use PostgreSQL::Test::Utils;
use Test::More;

# Initialize publisher node
my $node_publisher = PostgreSQL::Test::Cluster->new('publisher');
$node_publisher->init(allows_streaming => 'logical');

$node_publisher->append_conf('postgresql.conf',
qq{
autovacuum_naptime = 1
autovacuum_vacuum_threshold = 1
});
    
$node_publisher->start;

# Create subscriber node
my $node_subscriber = PostgreSQL::Test::Cluster->new('subscriber');
$node_subscriber->init;
$node_subscriber->start;

# Create some preexisting content on publisher
$node_publisher->safe_psql('postgres',
	"CREATE TABLE tab_rep (a int primary key)");

# Setup structure on subscriber
$node_subscriber->safe_psql('postgres',
	"CREATE TABLE tab_rep (a int primary key)");

# Setup logical replication
my $publisher_connstr = $node_publisher->connstr . ' dbname=postgres';
$node_publisher->safe_psql('postgres', "CREATE PUBLICATION tap_pub");
$node_publisher->safe_psql('postgres', "ALTER PUBLICATION tap_pub ADD TABLE tab_rep");

$node_subscriber->safe_psql('postgres',
	"CREATE SUBSCRIPTION tap_sub CONNECTION '$publisher_connstr' PUBLICATION tap_pub"
);

# Wait for initial table sync to finish
$node_subscriber->wait_for_subscription_sync($node_publisher, 'tap_sub');

for (my $i = 1; $i <= 100; $i++)
{
$node_publisher->wait_for_catchup('tap_sub');
diag("$i");

$node_publisher->safe_psql('postgres',
	"INSERT INTO tab_rep SELECT generate_series(1, (random() * 40000)::integer) ");
$node_publisher->safe_psql('postgres', "DELETE FROM tab_rep");

$node_publisher->stop('fast');
$node_publisher->start();
}

ok(1);
done_testing();

--------------PVwN0cJ0Xx5GEsnbMLeWYxGu--