Add GSS information to connection authorized log message

GSS information (if used) such as if the connection was authorized using
GSS or if it was encrypted using GSS, and perhaps most importantly, what
the GSS principal used for the authentication was, is extremely useful
but wasn't being included in the connection authorized log message.

Therefore, add to the connection authorized log message that
information, in a similar manner to how we log SSL information when SSL
is used for a connection.

Author: Vignesh C
Reviewed-by: Bharath Rupireddy
Discussion: https://www.postgresql.org/message-id/CALDaNm2N1385_Ltoo%3DS7VGT-ESu_bRQa-sC1wg6ikrM2L2Z49w%40mail.gmail.com

diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index f2dd8e49144dac3c63ab34c969428fc8cc0e3344..82d451569d620a9442274066060dfc36da12450a 100644 (file)
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -245,62 +245,40 @@ PerformAuthentication(Port *port)
 
    if (Log_connections)
    {
+       StringInfoData logmsg;
+
+       initStringInfo(&logmsg);
        if (am_walsender)
-       {
-#ifdef USE_SSL
-           if (port->ssl_in_use)
-               ereport(LOG,
-                       (port->application_name != NULL
-                        ? errmsg("replication connection authorized: user=%s application_name=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-                                 port->user_name,
-                                 port->application_name,
-                                 be_tls_get_version(port),
-                                 be_tls_get_cipher(port),
-                                 be_tls_get_cipher_bits(port),
-                                 be_tls_get_compression(port) ? _("on") : _("off"))
-                        : errmsg("replication connection authorized: user=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-                                 port->user_name,
-                                 be_tls_get_version(port),
-                                 be_tls_get_cipher(port),
-                                 be_tls_get_cipher_bits(port),
-                                 be_tls_get_compression(port) ? _("on") : _("off"))));
-           else
-#endif
-               ereport(LOG,
-                       (port->application_name != NULL
-                        ? errmsg("replication connection authorized: user=%s application_name=%s",
-                                 port->user_name,
-                                 port->application_name)
-                        : errmsg("replication connection authorized: user=%s",
-                                 port->user_name)));
-       }
+           appendStringInfo(&logmsg, _("replication connection authorized: user=%s"),
+                            port->user_name);
        else
-       {
+           appendStringInfo(&logmsg, _("connection authorized: user=%s"),
+                            port->user_name);
+       if (!am_walsender)
+           appendStringInfo(&logmsg, _(" database=%s"), port->database_name);
+
+       if (port->application_name != NULL)
+           appendStringInfo(&logmsg, _(" application_name=%s"),
+                            port->application_name);
+
 #ifdef USE_SSL
-           if (port->ssl_in_use)
-               ereport(LOG,
-                       (port->application_name != NULL
-                        ? errmsg("connection authorized: user=%s database=%s application_name=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-                                 port->user_name, port->database_name, port->application_name,
-                                 be_tls_get_version(port),
-                                 be_tls_get_cipher(port),
-                                 be_tls_get_cipher_bits(port),
-                                 be_tls_get_compression(port) ? _("on") : _("off"))
-                        : errmsg("connection authorized: user=%s database=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-                                 port->user_name, port->database_name,
-                                 be_tls_get_version(port),
-                                 be_tls_get_cipher(port),
-                                 be_tls_get_cipher_bits(port),
-                                 be_tls_get_compression(port) ? _("on") : _("off"))));
-           else
+       if (port->ssl_in_use)
+           appendStringInfo(&logmsg, _(" SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)"),
+                            be_tls_get_version(port),
+                            be_tls_get_cipher(port),
+                            be_tls_get_cipher_bits(port),
+                            be_tls_get_compression(port) ? _("on") : _("off"));
 #endif
-               ereport(LOG,
-                       (port->application_name != NULL
-                        ? errmsg("connection authorized: user=%s database=%s application_name=%s",
-                                 port->user_name, port->database_name, port->application_name)
-                        : errmsg("connection authorized: user=%s database=%s",
-                                 port->user_name, port->database_name)));
-       }
+#ifdef ENABLE_GSS
+       if (be_gssapi_get_princ(port))
+           appendStringInfo(&logmsg, _(" GSS (authenticated=%s, encrypted=%s, principal=%s)"),
+                            be_gssapi_get_auth(port) ? _("yes") : _("no"),
+                            be_gssapi_get_enc(port) ? _("yes") : _("no"),
+                            be_gssapi_get_princ(port));
+#endif
+
+       ereport(LOG, errmsg_internal("%s", logmsg.data));
+       pfree(logmsg.data);
    }
 
    set_ps_display("startup");

diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index b3aeea9574b93d42a4dbaabacc25dda3c5075db7..e58e69b49787a036a5d816a42f59c8269fb586cb 100644 (file)
--- a/src/test/kerberos/t/001_auth.pl
+++ b/src/test/kerberos/t/001_auth.pl
@@ -16,10 +16,11 @@ use warnings;
 use TestLib;
 use PostgresNode;
 use Test::More;
+use Time::HiRes qw(usleep);
 
 if ($ENV{with_gssapi} eq 'yes')
 {
-   plan tests => 18;
+   plan tests => 34;
 }
 else
 {
@@ -74,6 +75,10 @@ my $kdc_datadir = "${TestLib::tmp_check}/krb5kdc";
 my $kdc_pidfile = "${TestLib::tmp_check}/krb5kdc.pid";
 my $keytab      = "${TestLib::tmp_check}/krb5.keytab";
 
+my $dbname = 'postgres';
+my $username = 'test1';
+my $application = '001_auth.pl';
+
 note "setting up Kerberos";
 
 my ($stdout, $krb5_version);
@@ -160,6 +165,8 @@ my $node = get_new_node('node');
 $node->init;
 $node->append_conf('postgresql.conf', "listen_addresses = '$hostaddr'");
 $node->append_conf('postgresql.conf', "krb_server_keyfile = '$keytab'");
+$node->append_conf('postgresql.conf', "logging_collector = on");
+$node->append_conf('postgresql.conf', "log_connections = on");
 $node->start;
 
 $node->safe_psql('postgres', 'CREATE USER test1;');
@@ -169,7 +176,7 @@ note "running tests";
 # Test connection success or failure, and if success, that query returns true.
 sub test_access
 {
-   my ($node, $role, $query, $expected_res, $gssencmode, $test_name) = @_;
+   my ($node, $role, $query, $expected_res, $gssencmode, $test_name, $expect_log_msg) = @_;
 
    # need to connect over TCP/IP for Kerberos
    my ($res, $stdoutres, $stderrres) = $node->psql(
@@ -192,6 +199,33 @@ sub test_access
    {
        is($res, $expected_res, $test_name);
    }
+
+   # Verify specified log message is logged in the log file.
+   if ($expect_log_msg ne '')
+   {
+       my $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+       note "current_logfiles = $current_logfiles";
+       like($current_logfiles, qr|^stderr log/postgresql-.*log$|,
+            'current_logfiles is sane');
+
+       my $lfname = $current_logfiles;
+       $lfname =~ s/^stderr //;
+       chomp $lfname;
+
+       # might need to retry if logging collector process is slow...
+       my $max_attempts = 180 * 10;
+       my $first_logfile;
+       for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
+       {
+           $first_logfile = slurp_file($node->data_dir . '/' . $lfname);
+           last if $first_logfile =~ m/\Q$expect_log_msg\E/;
+           usleep(100_000);
+       }
+
+       like($first_logfile, qr/\Q$expect_log_msg\E/,
+            'found expected log file content');
+   }
+
    return;
 }
 
@@ -223,11 +257,11 @@ $node->append_conf('pg_hba.conf',
    qq{host all all $hostaddr/32 gss map=mymap});
 $node->restart;
 
-test_access($node, 'test1', 'SELECT true', 2, '', 'fails without ticket');
+test_access($node, 'test1', 'SELECT true', 2, '', 'fails without ticket', '');
 
 run_log [ $kinit, 'test1' ], \$test1_password or BAIL_OUT($?);
 
-test_access($node, 'test1', 'SELECT true', 2, '', 'fails without mapping');
+test_access($node, 'test1', 'SELECT true', 2, '', 'fails without mapping', '');
 
 $node->append_conf('pg_ident.conf', qq{mymap  /^(.*)\@$realm\$  \\1});
 $node->restart;
@@ -238,42 +272,49 @@ test_access(
    'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
    0,
    '',
-   'succeeds with mapping with default gssencmode and host hba');
+   'succeeds with mapping with default gssencmode and host hba',
+   "connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
+
 test_access(
    $node,
-   "test1",
+   'test1',
    'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
    0,
-   "gssencmode=prefer",
-   "succeeds with GSS-encrypted access preferred with host hba");
+   'gssencmode=prefer',
+   'succeeds with GSS-encrypted access preferred with host hba',
+   "connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
 test_access(
    $node,
-   "test1",
+   'test1',
    'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
    0,
-   "gssencmode=require",
-   "succeeds with GSS-encrypted access required with host hba");
+   'gssencmode=require',
+   'succeeds with GSS-encrypted access required with host hba',
+   "connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
 
 # Test that we can transport a reasonable amount of data.
 test_query(
    $node,
-   "test1",
+   'test1',
    'SELECT * FROM generate_series(1, 100000);',
    qr/^1\n.*\n1024\n.*\n9999\n.*\n100000$/s,
-   "gssencmode=require",
-   "receiving 100K lines works");
+   'gssencmode=require',
+   'receiving 100K lines works');
 
 test_query(
    $node,
-   "test1",
+   'test1',
    "CREATE TABLE mytab (f1 int primary key);\n"
      . "COPY mytab FROM STDIN;\n"
      . join("\n", (1 .. 100000))
      . "\n\\.\n"
      . "SELECT COUNT(*) FROM mytab;",
    qr/^100000$/s,
-   "gssencmode=require",
-   "sending 100K lines works");
+   'gssencmode=require',
+   'sending 100K lines works');
 
 unlink($node->data_dir . '/pg_hba.conf');
 $node->append_conf('pg_hba.conf',
@@ -282,20 +323,24 @@ $node->restart;
 
 test_access(
    $node,
-   "test1",
+   'test1',
    'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
    0,
-   "gssencmode=prefer",
-   "succeeds with GSS-encrypted access preferred and hostgssenc hba");
+   'gssencmode=prefer',
+   'succeeds with GSS-encrypted access preferred and hostgssenc hba',
+   "connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
 test_access(
    $node,
-   "test1",
+   'test1',
    'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
    0,
-   "gssencmode=require",
-   "succeeds with GSS-encrypted access required and hostgssenc hba");
-test_access($node, "test1", 'SELECT true', 2, "gssencmode=disable",
-   "fails with GSS encryption disabled and hostgssenc hba");
+   'gssencmode=require',
+   'succeeds with GSS-encrypted access required and hostgssenc hba',
+   "connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
+test_access($node, 'test1', 'SELECT true', 2, 'gssencmode=disable',
+   'fails with GSS encryption disabled and hostgssenc hba', '');
 
 unlink($node->data_dir . '/pg_hba.conf');
 $node->append_conf('pg_hba.conf',
@@ -304,21 +349,24 @@ $node->restart;
 
 test_access(
    $node,
-   "test1",
+   'test1',
    'SELECT gss_authenticated and not encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
    0,
-   "gssencmode=prefer",
-   "succeeds with GSS-encrypted access preferred and hostnogssenc hba, but no encryption"
+   'gssencmode=prefer',
+   'succeeds with GSS-encrypted access preferred and hostnogssenc hba, but no encryption',
+   "connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=no, principal=test1\@$realm)"
 );
-test_access($node, "test1", 'SELECT true', 2, "gssencmode=require",
-   "fails with GSS-encrypted access required and hostnogssenc hba");
+test_access($node, 'test1', 'SELECT true', 2, 'gssencmode=require',
+   'fails with GSS-encrypted access required and hostnogssenc hba', '');
 test_access(
    $node,
-   "test1",
+   'test1',
    'SELECT gss_authenticated and not encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
    0,
-   "gssencmode=disable",
-   "succeeds with GSS encryption disabled and hostnogssenc hba");
+   'gssencmode=disable',
+   'succeeds with GSS encryption disabled and hostnogssenc hba',
+   "connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=no, principal=test1\@$realm)"
+);
 
 truncate($node->data_dir . '/pg_ident.conf', 0);
 unlink($node->data_dir . '/pg_hba.conf');
@@ -332,4 +380,6 @@ test_access(
    'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
    0,
    '',
-   'succeeds with include_realm=0 and defaults');
+   'succeeds with include_realm=0 and defaults',
+   "connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);