Subject: Re: Why is src/test/modules/committs/t/002_standby.pl flaky?
To: Thomas Munro <thomas.munro@gmail.com>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, Andrew Dunstan <andrew@dunslane.net>,
 pgsql-hackers <pgsql-hackers@postgresql.org>
References: <CA+hUKG+OeoETZQ=Qw5Ub5h3tmwQhBmDA=nuNO3KG=zWfUypFAw@mail.gmail.com>
 <e4ddf83b-b399-aea4-498d-eb8e35e055e9@dunslane.net>
 <1600941.1641685316@sss.pgh.pa.us> <1609152.1641691036@sss.pgh.pa.us>
 <c20eb022-f576-0cc5-d796-91ffaf10a2ca@gmail.com>
 <CA+hUKGKwiqnkmuj6tJ6E+wBDDDhB3d6_Lzmm3O=ZhRb9P8ETAA@mail.gmail.com>
 <CA+hUKG+9kOBvurZoouprt0it=7XutQR17NMpfTeyYJNyc6V_5w@mail.gmail.com>
 <3b904d7b-ef84-6f1b-9326-9f88c1374eb8@gmail.com>
 <CA+hUKGKaq1Nv79sQptmDCgJc2tGUKogW-YxAyTyF1WvJerR0RQ@mail.gmail.com>
 <CA+hUKGKPpbC2EM2tSy5-1cfj+-1d2PVwLU4kBNg8E+og+B3fbg@mail.gmail.com>
 <5d507424-13ce-d19f-2f5d-ab4c6a987316@gmail.com>
 <CA+hUKG+o_QzN1LrEPGJLa6JiZU4DpLRybkwZjdCErs2qsB6axg@mail.gmail.com>
From: Alexander Lakhin <exclusion@gmail.com>
Message-ID: <1fe6b898-1722-d190-03c0-bf4c4884a748@gmail.com>
Date: Tue, 11 Jan 2022 18:00:01 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101
 Thunderbird/78.14.0
MIME-Version: 1.0
In-Reply-To: <CA+hUKG+o_QzN1LrEPGJLa6JiZU4DpLRybkwZjdCErs2qsB6axg@mail.gmail.com>
Content-Type: multipart/mixed;
 boundary="------------83B695FCA3DBFE846E5AB342"
Content-Language: en-US
Archived-At: <https://www.postgresql.org/message-id/1fe6b898-1722-d190-03c0-bf4c4884a748%40gmail.com>
Precedence: bulk

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

10.01.2022 23:52, Thomas Munro wrote:
>> I'm yet to find out whether the other 
>> WaitLatchOrSocket' users (e. g. postgres_fdw) can suffer from the
>> disconnected socket state, but this approach definitely works for
>> walreceiver.
> I see where you're going: there might be safe call sequences and
> unsafe call sequences, and maybe walreceiver is asking for trouble by
> double-polling.  I'm not sure about that; I got the impression
> recently that it's possible to get FD_CLOSE while you still have
> buffered data to read, so then the next recv() will return > 0 and
> then we don't have any state left anywhere to remember that we saw
> FD_CLOSE, even if you're careful to poll and read in the ideal
> sequence.  I could be wrong, and it would be nice if there is an easy
> fix along those lines...  The documentation around FD_CLOSE is
> unclear.
I had no strong opinion regarding unsafe sequence, though initially I
suspected that exactly the second libpqrcv_PQgetResult call could cause
the issue. But after digging into WaitLatchOrSocket I'd inclined to put
the fix deeper to satisfy all possible callers.
At the other hand, I've shared Tom's concerns regarding other clients,
that can stuck on WaitForMultipleObjects() just as walreceiver does, and
hoped that only walreceiver suffer from a graceful server socket closing.
So to get these doubts cleared, I've made a simple test for postgres_fdw
(please look at the attachment; you can put it into
contrib/postgres_fdw/t and run `vcregress taptest contrib\postgres_fdw`).
This test shows for me:
===
...
t/001_disconnection.pl .. # 12:13:39.481084 executing query...
# 12:13:43.245277 result:       0
# 0|0

# 12:13:43.246342 executing query...
# 12:13:46.525924 result:       0
# 0|0

# 12:13:46.527097 executing query...
# 12:13:47.745176 result:       3
#
# psql:<stdin>:1: WARNING:  no connection to the server
# psql:<stdin>:1: ERROR:  FATAL:  terminating connection due to
administrator co
mmand
# server closed the connection unexpectedly
#       This probably means the server terminated abnormally
#       before or while processing the request.
# CONTEXT:  remote SQL command: FETCH 100 FROM c1
# 12:13:47.794612 executing query...
# 12:13:51.073318 result:       0
# 0|0

# 12:13:51.074347 executing query...
===

With the simple logging added to connection.c:
                /* Sleep until there's something to do */
elog(LOG, "pgfdw_get_result before WaitLatchOrSocket");
                wc = WaitLatchOrSocket(MyLatch,
                                       WL_LATCH_SET | WL_SOCKET_READABLE |
                                       WL_EXIT_ON_PM_DEATH,
                                       PQsocket(conn),
                                       -1L, PG_WAIT_EXTENSION);
elog(LOG, "pgfdw_get_result after WaitLatchOrSocket");

I see in 001_disconnection_local.log:
...
2022-01-11 15:13:52.875 MSK|Administrator|postgres|61dd747f.5e4|LOG: 
pgfdw_get_result after WaitLatchOrSocket
2022-01-11 15:13:52.875
MSK|Administrator|postgres|61dd747f.5e4|STATEMENT:  SELECT * FROM large
WHERE a = fx2(a)
2022-01-11 15:13:52.875 MSK|Administrator|postgres|61dd747f.5e4|LOG: 
pgfdw_get_result before WaitLatchOrSocket
2022-01-11 15:13:52.875
MSK|Administrator|postgres|61dd747f.5e4|STATEMENT:  SELECT * FROM large
WHERE a = fx2(a)
2022-01-11 15:14:36.976 MSK|||61dd74ac.840|DEBUG:  autovacuum:
processing database "postgres"
2022-01-11 15:14:51.088 MSK|Administrator|postgres|61dd747f.5e4|LOG: 
pgfdw_get_result after WaitLatchOrSocket
2022-01-11 15:14:51.088
MSK|Administrator|postgres|61dd747f.5e4|STATEMENT:  SELECT * FROM large
WHERE a = fx2(a)
2022-01-11 15:14:51.089 MSK|Administrator|postgres|61dd747f.5e4|LOG: 
pgfdw_get_result before WaitLatchOrSocket
2022-01-11 15:14:51.089
MSK|Administrator|postgres|61dd747f.5e4|STATEMENT:  SELECT * FROM large
WHERE a = fx2(a)
2022-01-11 15:15:37.006 MSK|||61dd74e9.9e8|DEBUG:  autovacuum:
processing database "postgres"
2022-01-11 15:16:37.116 MSK|||61dd7525.ad0|DEBUG:  autovacuum:
processing database "postgres"
2022-01-11 15:17:37.225 MSK|||61dd7561.6a0|DEBUG:  autovacuum:
processing database "postgres"
2022-01-11 15:18:36.916 MSK|||61dd7470.704|LOG:  checkpoint starting: time
...
2022-01-11 15:36:38.225 MSK|||61dd79d6.2a0|DEBUG:  autovacuum:
processing database "postgres"
...

So here we get similar hanging on WaitLatchOrSocket().
Just to make sure that it's indeed the same issue, I've removed socket
shutdown&close and the test executed to the end (several times). Argh.

Best regards,
Alexander

--------------83B695FCA3DBFE846E5AB342
Content-Type: application/x-perl;
 name="001_disconnection.pl"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="001_disconnection.pl"

# Test postgres_fdw reaction on target server disconnection

use strict;
use warnings;

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

use Time::HiRes qw( time );
use DateTime;

use threads;
use threads::shared;

sub restart_thread {
	my @args = @_;
	my ($server) = @args;
	$SIG{'KILL'} = sub { threads->exit(); };
	sleep(3);
	for (my $i = 0; $i < 100; $i++) {
		sleep(5);
		$server->restart();
	}
}

my $foreign = PostgreSQL::Test::Cluster->new('foreign');
$foreign->init();

$foreign->append_conf(
	'postgresql.conf', qq{
log_min_messages = DEBUG1
log_min_error_statement = log
log_connections = on
log_disconnections = on
log_line_prefix = '%m|%u|%d|%c|'
log_statement = 'all'
	});
$foreign->start;
my $foreign_port = $foreign->port;

my $local = PostgreSQL::Test::Cluster->new('local');
$local->init();

$local->append_conf(
	'postgresql.conf', qq{
log_min_messages = DEBUG1
log_min_error_statement = log
log_connections = on
log_disconnections = on
log_line_prefix = '%m|%u|%d|%c|'
log_statement = 'all'
	});
$local->start();

$foreign->safe_psql('postgres', qq{
CREATE TABLE large(a int, t text);
INSERT INTO large SELECT x, rpad(x::text, 100) FROM generate_series(0, 999999) x;
});


$local->safe_psql('postgres', qq{
CREATE EXTENSION postgres_fdw;
CREATE SERVER fpg FOREIGN DATA WRAPPER postgres_fdw OPTIONS (dbname 'postgres', port '$foreign_port');
CREATE USER MAPPING FOR CURRENT_USER SERVER fpg;
CREATE FUNCTION fx2(i integer) RETURNS int AS 'begin return i * 2; end;' LANGUAGE plpgsql;
});

$local->safe_psql('postgres', 'IMPORT FOREIGN SCHEMA public FROM SERVER fpg INTO public;');
print($local->psql('postgres', 'EXPLAIN (VERBOSE) SELECT * FROM large WHERE a = fx2(a)') . "\n");
my $thread = threads->create('restart_thread', $foreign);
for (my $i = 0; $i < 20; $i++) {
	diag(DateTime->from_epoch( epoch => time )->strftime('%H:%M:%S.%6N') . " executing query...");
	my ($ret, $stdout, $stderr) = $local->psql('postgres', 'SELECT * FROM large WHERE a = fx2(a)');
	diag(DateTime->from_epoch( epoch => time )->strftime('%H:%M:%S.%6N') . " result: \t$ret\n$stdout\n$stderr");
	sleep(0.2);
}
$thread->kill('KILL')->detach;
sleep(2);
$foreign->_update_pid(1);
ok(1);

--------------83B695FCA3DBFE846E5AB342--