Enhance libpq encryption negotiation tests with new GUC

The new "log_connection_negotiation" server option causes the server
to print messages to the log when it receives a SSLRequest or
GSSENCRequest packet from the client. Together with "log_connections",
it gives a trace of how a connection and encryption is
negotiatated. Use the option in the libpq_encryption test, to verify
in more detail how libpq negotiates encryption with different
gssencmode and sslmode options.

This revealed a couple of cases where libpq retries encryption or
authentication, when it should already know that it cannot succeed.  I
marked them with XXX comments in the test tables. They only happen
when the connection was going to fail anyway, and only with rare
combinations of options, so they're not serious.

Discussion: https://www.postgresql.org/message-id/CAEze2Wja8VUoZygCepwUeiCrWa4jP316k0mvJrOW4PFmWP0Tcw@mail.gmail.com
This commit is contained in:
Heikki Linnakangas 2024-04-08 02:49:37 +03:00
parent 20f9b61cc1
commit 705843d294
3 changed files with 248 additions and 152 deletions

View File

@ -37,6 +37,9 @@
#include "utils/ps_status.h"
#include "utils/timeout.h"
/* GUCs */
bool Trace_connection_negotiation = false;
static void BackendInitialize(ClientSocket *client_sock, CAC_state cac);
static int ProcessStartupPacket(Port *port, bool ssl_done, bool gss_done);
static void SendNegotiateProtocolVersion(List *unrecognized_protocol_options);
@ -474,6 +477,16 @@ ProcessStartupPacket(Port *port, bool ssl_done, bool gss_done)
SSLok = 'N'; /* No support for SSL */
#endif
if (Trace_connection_negotiation)
{
if (SSLok == 'S')
ereport(LOG,
(errmsg("SSLRequest accepted")));
else
ereport(LOG,
(errmsg("SSLRequest rejected")));
}
retry1:
if (send(port->sock, &SSLok, 1, 0) != 1)
{
@ -519,6 +532,16 @@ retry1:
GSSok = 'G';
#endif
if (Trace_connection_negotiation)
{
if (GSSok == 'G')
ereport(LOG,
(errmsg("GSSENCRequest accepted")));
else
ereport(LOG,
(errmsg("GSSENCRequest rejected")));
}
while (send(port->sock, &GSSok, 1, 0) != 1)
{
if (errno == EINTR)

View File

@ -96,6 +96,7 @@
/* XXX these should appear in other modules' header files */
extern bool Log_disconnections;
extern bool Trace_connection_negotiation;
extern int CommitDelay;
extern int CommitSiblings;
extern char *default_tablespace;
@ -1224,6 +1225,16 @@ struct config_bool ConfigureNamesBool[] =
false,
NULL, NULL, NULL
},
{
{"trace_connection_negotiation", PGC_POSTMASTER, DEVELOPER_OPTIONS,
gettext_noop("Log details of pre-authentication connection handshake."),
NULL,
GUC_NOT_IN_SAMPLE
},
&Trace_connection_negotiation,
false,
NULL, NULL, NULL
},
{
{"log_disconnections", PGC_SU_BACKEND, LOGGING_WHAT,
gettext_noop("Logs end of a session, including duration."),

View File

@ -18,17 +18,21 @@
# Each combination is represented by a line in a table. The line lists
# the options specifying the test case, and an expected outcome. The
# expected outcome includes whether the connection succeeds or fails,
# and whether it uses SSL, GSS or no encryption.
# and whether it uses SSL, GSS or no encryption. It also includes a
# condensed trace of what steps were taken during the negotiation.
# That can catch cases like useless retries, or if the encryption
# methods are attempted in wrong order, even when it doesn't affect
# the final outcome.
#
# TEST TABLE FORMAT
# -----------------
#
# Example of the test table format:
#
# # USER GSSENCMODE SSLMODE OUTCOME
# testuser disable allow plain
# . . prefer ssl
# testuser require * fail
# # USER GSSENCMODE SSLMODE EVENTS -> OUTCOME
# testuser disable allow connect, authok -> plain
# . . prefer connect, sslaccept, authok -> ssl
# testuser require * connect, gssreject -> fail
#
# USER, GSSENCMODE and SSLMODE fields are the libpq 'user',
# 'gssencmode' and 'sslmode' options used in the test. As a shorthand,
@ -37,6 +41,23 @@
# as a wildcard; it is expanded to mean all possible values of that
# field.
#
# The EVENTS field is a condensed trace of expected steps during the
# negotiation:
#
# connect: a TCP connection was established
# reconnect: TCP connection was disconnected, and a new one was established
# sslaccept: client requested SSL encryption and server accepted it
# sslreject: client requested SSL encryption but server rejected it
# gssaccept: client requested GSSAPI encryption and server accepted it
# gssreject: client requested GSSAPI encryption but server rejected it
# authok: client sent startup packet and authentication was performed successfully
# authfail: client sent startup packet but server rejected the authentication
#
# The event trace can be used to verify that the client negotiated the
# connection properly in more detail than just by looking at the
# outcome. For example, if the client opens spurious extra TCP
# connections, that would show up in the EVENTS.
#
# The OUTCOME field indicates the expected result of the test:
#
# plain: an unencrypted connection was established
@ -80,7 +101,11 @@ $node->init;
$node->append_conf(
'postgresql.conf', qq{
listen_addresses = '$hostaddr'
# Capturing the EVENTS that occur during tests requires these settings
log_connections = on
log_disconnections = on
trace_connection_negotiation = on
lc_messages = 'C'
});
my $pgdata = $node->data_dir;
@ -190,20 +215,19 @@ my $server_config = {
### Run tests with GSS and SSL disabled in the server
###
my $test_table = q{
# USER GSSENCMODE SSLMODE OUTCOME
testuser disable disable plain
. . allow plain
. . prefer plain
. . require fail
. prefer disable plain
. . allow plain
. . prefer plain
. . require fail
# USER GSSENCMODE SSLMODE EVENTS -> OUTCOME
testuser disable disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslreject, authok -> plain
. . require connect, sslreject -> fail
. prefer disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslreject, authok -> plain
. . require connect, sslreject -> fail
# All attempts with gssencmode=require fail because no credential
# cache has been configured in the client (and the server isn't
# configured for GSS either)
. require * fail
# All attempts with gssencmode=require fail without connecting because
# no credential cache has been configured in the client
. require * - -> fail
};
note("Running tests with SSL and GSS disabled in the server");
test_matrix($node, $server_config,
@ -218,19 +242,19 @@ SKIP:
skip "SSL not supported by this build" if $ssl_supported == 0;
$test_table = q{
# USER GSSENCMODE SSLMODE OUTCOME
testuser disable disable plain
. . allow plain
. . prefer ssl
. . require ssl
ssluser . disable fail
. . allow ssl
. . prefer ssl
. . require ssl
nossluser . disable plain
. . allow plain
. . prefer plain
. . require fail
# USER GSSENCMODE SSLMODE EVENTS -> OUTCOME
testuser disable disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslaccept, authok -> ssl
. . require connect, sslaccept, authok -> ssl
ssluser . disable connect, authfail -> fail
. . allow connect, authfail, reconnect, sslaccept, authok -> ssl
. . prefer connect, sslaccept, authok -> ssl
. . require connect, sslaccept, authok -> ssl
nossluser . disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslaccept, authfail, reconnect, authok -> plain
. . require connect, sslaccept, authfail -> fail
};
# Enable SSL in the server
@ -256,35 +280,50 @@ SKIP:
{
skip "GSSAPI/Kerberos not supported by this build" if $gss_supported == 0;
$test_table = q{
# USER GSSENCMODE SSLMODE OUTCOME
testuser disable disable plain
. . allow plain
. . prefer plain
. . require fail
. require * gss
. prefer * gss
# USER GSSENCMODE SSLMODE EVENTS -> OUTCOME
testuser disable disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslreject, authok -> plain
. . require connect, sslreject -> fail
. prefer * connect, gssaccept, authok -> gss
. require disable connect, gssaccept, authok -> gss
. . allow connect, gssaccept, authok -> gss
. . prefer connect, gssaccept, authok -> gss
. . require connect, gssaccept, authok -> gss # If both GSS and SSL is possible, GSS is chosen over SSL, even if sslmode=require
gssuser disable disable fail
. . allow fail
. . prefer fail
. . require fail
. prefer * gss
. require * gss
gssuser disable disable connect, authfail -> fail
nogssuser disable disable plain
. . allow plain
. . prefer plain
. . require fail
. prefer disable plain
. . allow plain
. . prefer plain
. . require fail
. require * fail
# XXX: after the reconnection and SSL negotiation failure, libpq tries
# again to authenticate in plaintext. That's unnecessariy and doomed
# to fail. We already know the server doesn't accept that because of
# the first authentication failure.
. . allow connect, authfail, reconnect, sslreject, authfail -> fail
. . prefer connect, sslreject, authfail -> fail
. . require connect, sslreject -> fail
. prefer * connect, gssaccept, authok -> gss
. require * connect, gssaccept, authok -> gss
nogssuser disable disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslreject, authok -> plain
. . require connect, sslreject, -> fail
. prefer disable connect, gssaccept, authfail, reconnect, authok -> plain
. . allow connect, gssaccept, authfail, reconnect, authok -> plain
. . prefer connect, gssaccept, authfail, reconnect, sslreject, authok -> plain
. . require connect, gssaccept, authfail, reconnect, sslreject -> fail
. require disable connect, gssaccept, authfail -> fail
# XXX: libpq retries the connection unnecessarily in this case:
. . allow connect, gssaccept, authfail, reconnect, gssaccept, authfail -> fail
. . prefer connect, gssaccept, authfail -> fail
. . require connect, gssaccept, authfail -> fail
};
# Sanity check that the connection fails when no kerberos ticket
# is present in the client
connect_test($node, 'user=testuser gssencmode=require sslmode=disable', 'fail');
connect_test($node, 'user=testuser gssencmode=require sslmode=disable', '- -> fail');
$krb->create_principal('gssuser', $gssuser_password);
$krb->create_ticket('gssuser', $gssuser_password);
@ -294,19 +333,6 @@ nogssuser disable disable plain
test_matrix($node, $server_config,
['testuser', 'gssuser', 'nogssuser'],
\@all_sslmodes, \@all_gssencmodes, parse_table($test_table));
# Check that logs match the expected 'no pg_hba.conf entry' line, too, as
# that is not tested by test_matrix.
connect_test($node, 'user=nogssuser gssencmode=require sslmode=prefer', 'fail',
'no pg_hba.conf entry for host "127.0.0.1", user "nogssuser", database "postgres", GSS encryption');
# With 'gssencmode=prefer', libpq will first negotiate GSSAPI
# encryption, but the connection will fail because pg_hba.conf
# forbids GSSAPI encryption for this user. It will then reconnect
# with SSL, but the server doesn't support it, so it will continue
# with no encryption.
connect_test($node, 'user=nogssuser gssencmode=prefer sslmode=prefer', 'plain',
'no pg_hba.conf entry for host "127.0.0.1", user "nogssuser", database "postgres", GSS encryption');
}
###
@ -317,57 +343,72 @@ SKIP:
skip "GSSAPI/Kerberos or SSL not supported by this build" unless ($ssl_supported && $gss_supported);
$test_table = q{
# USER GSSENCMODE SSLMODE OUTCOME
testuser disable disable plain
. . allow plain
. . prefer ssl
. . require ssl
. prefer disable gss
. . allow gss
. . prefer gss
. . require gss # If both GSS and SSL is possible, GSS is chosen over SSL, even if sslmode=require
. require disable gss
. . allow gss
. . prefer gss
. . require gss # If both GSS and SSL is possible, GSS is chosen over SSL, even if sslmode=require
# USER GSSENCMODE SSLMODE EVENTS -> OUTCOME
testuser disable disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslaccept, authok -> ssl
. . require connect, sslaccept, authok -> ssl
. prefer disable connect, gssaccept, authok -> gss
. . allow connect, gssaccept, authok -> gss
. . prefer connect, gssaccept, authok -> gss
. . require connect, gssaccept, authok -> gss # If both GSS and SSL is possible, GSS is chosen over SSL, even if sslmode=require
. require disable connect, gssaccept, authok -> gss
. . allow connect, gssaccept, authok -> gss
. . prefer connect, gssaccept, authok -> gss
. . require connect, gssaccept, authok -> gss # If both GSS and SSL is possible, GSS is chosen over SSL, even if sslmode=require
gssuser disable * fail
. prefer * gss
. require * gss
gssuser disable disable connect, authfail -> fail
. . allow connect, authfail, reconnect, sslaccept, authfail -> fail
. . prefer connect, sslaccept, authfail, reconnect, authfail -> fail
. . require connect, sslaccept, authfail -> fail
. prefer * connect, gssaccept, authok -> gss
. require disable connect, gssaccept, authok -> gss
. . allow connect, gssaccept, authok -> gss
. . prefer connect, gssaccept, authok -> gss
. . require connect, gssaccept, authok -> gss # If both GSS and SSL is possible, GSS is chosen over SSL, even if sslmode=require
ssluser disable disable fail
. . allow ssl
. . prefer ssl
. . require ssl
. prefer disable fail
. . allow ssl
. . prefer ssl
. . require ssl
. require disable fail
. . allow fail
. . prefer fail
. . require fail # If both GSS and SSL are required, the sslmode=require is effectively ignored and GSS is required
ssluser disable disable connect, authfail -> fail
. . allow connect, authfail, reconnect, sslaccept, authok -> ssl
. . prefer connect, sslaccept, authok -> ssl
. . require connect, sslaccept, authok -> ssl
. prefer disable connect, gssaccept, authfail, reconnect, authfail -> fail
. . allow connect, gssaccept, authfail, reconnect, authfail, reconnect, sslaccept, authok -> ssl
. . prefer connect, gssaccept, authfail, reconnect, sslaccept, authok -> ssl
. . require connect, gssaccept, authfail, reconnect, sslaccept, authok -> ssl
. require disable connect, gssaccept, authfail -> fail
nogssuser disable disable plain
. . allow plain
. . prefer ssl
. . require ssl
. prefer disable plain
. . allow plain
. . prefer ssl
. . require ssl
. require * fail
# XXX: libpq retries the connection unnecessarily in this case:
. . allow connect, gssaccept, authfail, reconnect, gssaccept, authfail -> fail
nossluser disable disable plain
. . allow plain
. . prefer plain
. . require fail
. prefer * gss
. require * gss
. . prefer connect, gssaccept, authfail -> fail
. . require connect, gssaccept, authfail -> fail # If both GSS and SSL are required, the sslmode=require is effectively ignored and GSS is required
nogssuser disable disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslaccept, authok -> ssl
. . require connect, sslaccept, authok -> ssl
. prefer disable connect, gssaccept, authfail, reconnect, authok -> plain
. . allow connect, gssaccept, authfail, reconnect, authok -> plain
. . prefer connect, gssaccept, authfail, reconnect, sslaccept, authok -> ssl
. . require connect, gssaccept, authfail, reconnect, sslaccept, authok -> ssl
. require disable connect, gssaccept, authfail -> fail
# XXX: libpq retries the connection unnecessarily in this case:
. . allow connect, gssaccept, authfail, reconnect, gssaccept, authfail -> fail
. . prefer connect, gssaccept, authfail -> fail
. . require connect, gssaccept, authfail -> fail
nossluser disable disable connect, authok -> plain
. . allow connect, authok -> plain
. . prefer connect, sslaccept, authfail, reconnect, authok -> plain
. . require connect, sslaccept, authfail -> fail
. prefer * connect, gssaccept, authok -> gss
. require * connect, gssaccept, authok -> gss
};
# Sanity check that GSSAPI is still enabled from previous test.
connect_test($node, 'user=testuser gssencmode=prefer sslmode=prefer', 'gss');
connect_test($node, 'user=testuser gssencmode=prefer sslmode=prefer', 'connect, gssaccept, authok -> gss');
# Enable SSL
$node->adjust_conf('postgresql.conf', 'ssl', 'on');
@ -378,22 +419,6 @@ nossluser disable disable plain
test_matrix($node, $server_config,
['testuser', 'gssuser', 'ssluser', 'nogssuser', 'nossluser'],
\@all_sslmodes, \@all_gssencmodes, parse_table($test_table));
# Test case that server supports GSSAPI, but it's not allowed for
# this user. Special cased because we check output
connect_test($node, 'user=nogssuser gssencmode=require sslmode=prefer', 'fail',
'no pg_hba.conf entry for host "127.0.0.1", user "nogssuser", database "postgres", GSS encryption');
# with 'gssencmode=prefer', libpq will first negotiate GSSAPI
# encryption, but the connection will fail because pg_hba.conf
# forbids GSSAPI encryption for this user. It will then reconnect
# with SSL.
connect_test($node, 'user=nogssuser gssencmode=prefer sslmode=prefer', 'ssl',
'no pg_hba.conf entry for host "127.0.0.1", user "nogssuser", database "postgres", GSS encryption');
# Setting both gssencmode=require and sslmode=require fails if
# GSSAPI is not available.
connect_test($node, 'user=nogssuser gssencmode=require sslmode=require ', 'fail');
}
###
@ -403,8 +428,8 @@ SKIP:
{
skip "Unix domain sockets not supported" unless ($unixdir ne "");
connect_test($node, "user=localuser gssencmode=prefer sslmode=require host=$unixdir", 'plain');
connect_test($node, "user=localuser gssencmode=require sslmode=prefer host=$unixdir", 'fail');
connect_test($node, "user=localuser gssencmode=prefer sslmode=require host=$unixdir", 'connect, authok -> plain');
connect_test($node, "user=localuser gssencmode=require sslmode=prefer host=$unixdir", '- -> fail');
}
done_testing();
@ -434,30 +459,35 @@ sub test_matrix
sslmode=>$client_mode,
);
my $key = "$test_user $gssencmode $client_mode";
my $res = $expected{$key};
if (!defined $res) {
$res = "<expected result missing>";
my $expected_events = $expected{$key};
if (!defined($expected_events)) {
$expected_events = "<line missing from expected output table>";
}
connect_test($pg_node, "user=$test_user gssencmode=$gssencmode sslmode=$client_mode", $res);
connect_test($pg_node, "user=$test_user gssencmode=$gssencmode sslmode=$client_mode", $expected_events);
}
}
}
}
# Try to establish a connection to the server using libpq. Verify the
# negotiation events and outcome.
sub connect_test
{
local $Test::Builder::Level = $Test::Builder::Level + 1;
my ($node, $connstr, $expected_outcome, @expect_log_msgs)
= @_;
my ($node, $connstr, $expected_events_and_outcome) = @_;
my $test_name = " '$connstr' -> $expected_outcome";
my $test_name = " '$connstr' -> $expected_events_and_outcome";
my $connstr_full = "";
$connstr_full .= "dbname=postgres " unless $connstr =~ m/dbname=/;
$connstr_full .= "host=$host hostaddr=$hostaddr " unless $connstr =~ m/host=/;
$connstr_full .= $connstr;
# Get the current size of the logfile before running the test.
# After the test, we can then check just the new lines that have
# appeared. (This is the same approach that the $node->log_contains
# function uses).
my $log_location = -s $node->logfile;
# XXX: Pass command with -c, because I saw intermittent test
@ -477,18 +507,18 @@ sub connect_test
my $outcome = $ret == 0 ? $stdout : 'fail';
is($outcome, $expected_outcome, $test_name) or diag("$stderr");
# Parse the EVENTS from the log file.
my $log_contents =
PostgreSQL::Test::Utils::slurp_file($node->logfile, $log_location);
my @events = parse_log_events($log_contents);
if (@expect_log_msgs)
{
# Match every message literally.
my @regexes = map { qr/\Q$_\E/ } @expect_log_msgs;
my %params = ();
$params{log_like} = \@regexes;
$node->log_check($test_name, $log_location, %params);
}
# Check that the events and outcome match the expected events and
# outcome
my $events_and_outcome = join(', ', @events) . " -> $outcome";
is($events_and_outcome, $expected_events_and_outcome, $test_name) or diag("$stderr");
}
# Parse a test table. See comment at top of the file for the format.
sub parse_table
{
my ($table) = @_;
@ -509,15 +539,19 @@ sub parse_table
# Ignore empty lines (includes comment-only lines)
next if $line eq '';
my @cols = split /\s+/, $line;
die "test table line \"$line\" has incorrect number of columns\n" if scalar(@cols) != 4 ;
$line =~ m/^(\S+)\s+(\S+)\s+(\S+)\s+(\S.*)\s*->\s*(\S+)\s*$/ or die "could not parse line \"$line\"";
$user = $1 unless $1 eq ".";
$gssencmode = $2 unless $2 eq ".";
$sslmode = $3 unless $3 eq ".";
$user = $cols[0] unless $cols[0] eq ".";
$gssencmode = $cols[1] unless $cols[1] eq ".";
$sslmode = $cols[2] unless $cols[2] eq ".";
my $outcome = $cols[3];
# Normalize the whitespace in the "EVENTS -> OUTCOME" part
my @events = split /,\s*/, $4;
my $outcome = $5;
my $events_str = join(', ', @events);
$events_str =~ s/\s+$//; # trim whitespace
my $events_and_outcome = "$events_str -> $outcome";
my %expanded = expand_expected_line($user, $gssencmode, $sslmode, $outcome);
my %expanded = expand_expected_line($user, $gssencmode, $sslmode, $events_and_outcome);
%expected = (%expected, %expanded);
}
return %expected;
@ -546,3 +580,31 @@ sub expand_expected_line
}
return %result;
}
# Scrape the server log for the negotiation events that match the
# EVENTS field of the test tables.
sub parse_log_events
{
my ($log_contents) = (@_);
my @events = ();
my @lines = split /\n/, $log_contents;
foreach my $line (@lines) {
push @events, "reconnect" if $line =~ /connection received/ && scalar(@events) > 0;
push @events, "connect" if $line =~ /connection received/ && scalar(@events) == 0;
push @events, "sslaccept" if $line =~ /SSLRequest accepted/;
push @events, "sslreject" if $line =~ /SSLRequest rejected/;
push @events, "gssaccept" if $line =~ /GSSENCRequest accepted/;
push @events, "gssreject" if $line =~ /GSSENCRequest rejected/;
push @events, "authfail" if $line =~ /no pg_hba.conf entry/;
push @events, "authok" if $line =~ /connection authenticated/;
}
# No events at all is represented by "-"
if (scalar @events == 0) {
push @events, "-"
}
return @events;
}