Skip to content

Commit

Permalink
Add GSS information to connection authorized log message
Browse files Browse the repository at this point in the history 
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
  • Loading branch information
@sfrost
sfrost committed Dec 2, 2020
1 parent 0146924 commit dc11f31
Show file tree
Hide file tree
Showing 2 changed files with 114 additions and 86 deletions.
82 changes: 30 additions & 52 deletions src/backend/utils/init/postinit.c
View file
Expand Up @@ -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");
Expand Down
118 changes: 84 additions & 34 deletions src/test/kerberos/t/001_auth.pl
View file
Expand Up @@ -16,10 +16,11 @@
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
{
Expand Down Expand Up @@ -74,6 +75,10 @@
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);
Expand Down Expand Up @@ -160,6 +165,8 @@ END
$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;');
Expand All @@ -169,7 +176,7 @@ END
# 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(
Expand All @@ -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;
}

Expand Down Expand Up @@ -223,11 +257,11 @@ sub test_query
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;
Expand All @@ -238,42 +272,49 @@ sub test_query
'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',
Expand All @@ -282,20 +323,24 @@ sub test_query

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',
Expand All @@ -304,21 +349,24 @@ sub test_query

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');
Expand All @@ -332,4 +380,6 @@ sub test_query
'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)"
);

0 comments on commit dc11f31

Please sign in to comment.