On Thu, Oct 29, 2020 at 7:26 PM Stephen Frost <sfr...@snowman.net> wrote:
>
> Greetings,
>
> * vignesh C (vignes...@gmail.com) wrote:
> > I have made a v2 patch based on the changes you have suggested. The
> > patch for the same is attached.
>
> > From b067cf823750f200102be0a0cad9a26a08e29a92 Mon Sep 17 00:00:00 2001
> > From: Vignesh C <vignes...@gmail.com>
> > Date: Wed, 28 Oct 2020 08:19:06 +0530
> > Subject: [PATCH v2] Log message for GSS connection is missing once
> > connection
> > authorization is successful.
> >
> > Log message for GSS connection is missing once connection authorization is
> > successful. We have similar log message for SSL connections once the
> > connection
> > authorization is successful. This message will help the user to identify the
> > connection that was selected from the logfile.
>
> Just to be clear- it's not that the message is 'missing', it's just not
> providing the (certainly useful) information about how the connection
> was authorized. The commit message should make it clear that what we're
> doing here is improving the connection authorization message for GSS
> authenticated or encrypted connections.
>
I have updated the commit message accordingly.
> > diff --git a/src/backend/utils/init/postinit.c
> > b/src/backend/utils/init/postinit.c
> > index d4ab4c7..7980e92 100644
> > --- a/src/backend/utils/init/postinit.c
> > +++ b/src/backend/utils/init/postinit.c
> > @@ -267,6 +267,21 @@ PerformAuthentication(Port *port)
> >
> > be_tls_get_compression(port) ? _("on") : _("off"))));
> > else
> > #endif
> > +#ifdef ENABLE_GSS
> > + if (be_gssapi_get_auth(port) ||
> > be_gssapi_get_princ(port))
> > + ereport(LOG,
> > + (port->application_name !=
> > NULL
> > + ? errmsg("replication
> > connection authorized: user=%s application_name=%s GSS %s (principal=%s)",
> > +
> > port->user_name,
> > +
> > port->application_name,
> > +
> > be_gssapi_get_auth(port) || be_gssapi_get_enc(port) ? _("on") : _("off"),
> > +
> > be_gssapi_get_princ(port))
> > + : errmsg("replication
> > connection authorized: user=%s GSS %s (principal=%s)",
> > +
> > port->user_name,
> > +
> > be_gssapi_get_auth(port) || be_gssapi_get_enc(port) ? _("on") : _("off"),
> > +
> > be_gssapi_get_princ(port))));
> > + else
> > +#endif
>
> No, this isn't what I was suggesting. "on" and "off" really isn't
> communicating the details about the GSS-using connection. What I
> suggested before was something like:
>
> errmsg("replication connection authorized: user=%s application_name=%s GSS %s
> (principal=%s)",
> port->user_name,
> port->application_name,
> (be_gssapi_get_auth(port) && be_gssapi_get_enc(port)) ?
> "authenticated and encrypted" : be_gssapi_get_auth(port) ? "authenticated" :
> "encrypted",
> be_gssapi_get_princ(port))
>
> Though I'll admit that perhaps there's something better which could be
> done here- but just 'on/off' certainly isn't that. Another option might
> be:
>
> errmsg("replication connection authorized: user=%s application_name=%s GSS
> authenticated: %s, encrypted: %s, principal: %s",
> port->user_name,
> port->application_name,
> be_gssapi_get_auth(port) ? "yes" : "no",
> be_gssapi_get_enc(port) ? "yes" : "no",
> be_gssapi_get_princ(port))
>
I like the above method that you suggested, I have changed it based on
the above.
> Also, it would be good to see if there's a way to add to the tests we
> have for GSSAPI authentication/encryption to show that we hit each of
> the possible cases and check that we get the correct messages in the log
> as a result.
>
I have added the log validation to the existing tests that are present
for authentication.
Attached v3 patch has the change for the same.
Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com
From 039a626513cab357070d33ddc872f22e0f4f3e88 Mon Sep 17 00:00:00 2001
From: Vignesh C <vignes...@gmail.com>
Date: Fri, 30 Oct 2020 17:58:45 +0530
Subject: [PATCH v3] Improving the connection authorization message for GSS
authenticated/encrypted connections.
Added log message to include GSS authentication, encryption & principal
information. This message will help the user to know if GSS authentication or
encryption was used and which GSS principal was used.
---
src/backend/utils/init/postinit.c | 80 ++++++++++++++-------------------------
src/test/kerberos/t/001_auth.pl | 73 ++++++++++++++++++++++++++++-------
2 files changed, 87 insertions(+), 66 deletions(-)
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index d4ab4c7..34d3045 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -246,62 +246,38 @@ PerformAuthentication(Port *port)
if (Log_connections)
{
+ StringInfoData logmsg;
+ initStringInfo(&logmsg);
if (am_walsender)
- {
+ appendStringInfo(&logmsg, "replication ");
+
+ 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("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
+ 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("replication connection authorized: user=%s application_name=%s",
- port->user_name,
- port->application_name)
- : errmsg("replication connection authorized: user=%s",
- port->user_name)));
- }
- else
- {
-#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
+#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,
- (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)));
- }
+
+ ereport(LOG, errmsg("%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 b3aeea9..701e6ad 100644
--- 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 => 32;
}
else
{
@@ -160,6 +161,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 +172,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 +195,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 = 10 * 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/$expect_log_msg /;
+ usleep(100_000);
+ }
+
+ like($first_logfile, qr/$expect_log_msg/,
+ 'found expected log file content');
+ }
+
return;
}
@@ -223,11 +253,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,21 +268,28 @@ 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=test1 database=postgres application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes, principal=test1\@EXAMPLE.COM\)'
+);
+
test_access(
$node,
"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");
+ "succeeds with GSS-encrypted access preferred with host hba",
+ 'connection authorized: user=test1 database=postgres application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes, principal=test1\@EXAMPLE.COM\)'
+);
test_access(
$node,
"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");
+ "succeeds with GSS-encrypted access required with host hba",
+ 'connection authorized: user=test1 database=postgres application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes, principal=test1\@EXAMPLE.COM\)'
+);
# Test that we can transport a reasonable amount of data.
test_query(
@@ -286,16 +323,20 @@ test_access(
'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");
+ "succeeds with GSS-encrypted access preferred and hostgssenc hba",
+ 'connection authorized: user=test1 database=postgres application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes, principal=test1\@EXAMPLE.COM\)'
+);
test_access(
$node,
"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");
+ "succeeds with GSS-encrypted access required and hostgssenc hba",
+ 'connection authorized: user=test1 database=postgres application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes, principal=test1\@EXAMPLE.COM\)'
+);
test_access($node, "test1", 'SELECT true', 2, "gssencmode=disable",
- "fails with GSS encryption disabled and hostgssenc hba");
+ "fails with GSS encryption disabled and hostgssenc hba", '');
unlink($node->data_dir . '/pg_hba.conf');
$node->append_conf('pg_hba.conf',
@@ -308,17 +349,20 @@ test_access(
'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"
+ "succeeds with GSS-encrypted access preferred and hostnogssenc hba, but no encryption",
+ 'connection authorized: user=test1 database=postgres application_name=001_auth.pl GSS \(authenticated=yes, encrypted=no, principal=test1\@EXAMPLE.COM\)'
);
test_access($node, "test1", 'SELECT true', 2, "gssencmode=require",
- "fails with GSS-encrypted access required and hostnogssenc hba");
+ "fails with GSS-encrypted access required and hostnogssenc hba", '');
test_access(
$node,
"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");
+ "succeeds with GSS encryption disabled and hostnogssenc hba",
+ 'connection authorized: user=test1 database=postgres application_name=001_auth.pl GSS \(authenticated=yes, encrypted=no, principal=test1\@EXAMPLE.COM\)'
+);
truncate($node->data_dir . '/pg_ident.conf', 0);
unlink($node->data_dir . '/pg_hba.conf');
@@ -332,4 +376,5 @@ 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',
+ '');
--
1.8.3.1
