Enhance libpq encryption negotiation tests with new GUC
authorHeikki Linnakangas <heikki.linnakangas@iki.fi>
Sun, 7 Apr 2024 23:49:37 +0000 (02:49 +0300)
committerHeikki Linnakangas <heikki.linnakangas@iki.fi>
Sun, 7 Apr 2024 23:49:37 +0000 (02:49 +0300)
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

src/backend/tcop/backend_startup.c
src/backend/utils/misc/guc_tables.c
src/test/libpq_encryption/t/001_negotiate_encryption.pl

index 0b9f899cd8b2f1450f97e3246dfdcdf20de04013..64df3ff32a26deefd469d42bd64f002e7add88a1 100644 (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)
index f9bb2b0f9e502cb2682588dbdc134167ee6b01d1..83e3a59d7e9799296d648e4d45910ac56f20f1be 100644 (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."),
index ed33988aa78da2c2002babf35c89b6cf6db0821f..f277edda82554bfa67be55bc3481b2e723732580 100644 (file)
 # 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,
 # 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
-
-# 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
+# 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 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
-
-gssuser     disable      disable      fail
-.           .            allow        fail
-.           .            prefer       fail
-.           .            require      fail
-.           prefer       *            gss
-.           require      *            gss
-
-nogssuser   disable      disable      plain
-.           .            allow        plain
-.           .            prefer       plain
-.           .            require      fail
-.           prefer       disable      plain
-.           .            allow        plain
-.           .            prefer       plain
-.           .            require      fail
-.           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       *            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      connect, authfail            -> 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
-
-gssuser     disable      *            fail
-.           prefer       *            gss
-.           require      *            gss
-
-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
-
-nogssuser   disable      disable      plain
-.           .            allow        plain
-.           .            prefer       ssl
-.           .            require      ssl
-.           prefer       disable      plain
-.           .            allow        plain
-.           .            prefer       ssl
-.           .            require      ssl
-.           require      *            fail
-
-nossluser   disable      disable      plain
-.           .            allow        plain
-.           .            prefer       plain
-.           .            require      fail
-.           prefer       *            gss
-.           require      *            gss
+# 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      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      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
+
+# 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         # 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;
+}