Add some information about authenticated identity via log_connections

The "authenticated identity" is the string used by an authentication
method to identify a particular user.  In many common cases, this is the
same as the PostgreSQL username, but for some third-party authentication
methods, the identifier in use may be shortened or otherwise translated
(e.g. through pg_ident user mappings) before the server stores it.

To help administrators see who has actually interacted with the system,
this commit adds the capability to store the original identity when
authentication succeeds within the backend's Port, and generates a log
entry when log_connections is enabled.  The log entries generated look
something like this (where a local user named "foouser" is connecting to
the database as the database user called "admin"):

  LOG:  connection received: host=[local]
  LOG:  connection authenticated: identity="foouser" method=peer (/data/pg_hba.conf:88)
  LOG:  connection authorized: user=admin database=postgres application_name=psql

Port->authn_id is set according to the authentication method:

  bsd: the PostgreSQL username (aka the local username)
  cert: the client's Subject DN
  gss: the user principal
  ident: the remote username
  ldap: the final bind DN
  pam: the PostgreSQL username (aka PAM username)
  password (and all pw-challenge methods): the PostgreSQL username
  peer: the peer's pw_name
  radius: the PostgreSQL username (aka the RADIUS username)
  sspi: either the down-level (SAM-compatible) logon name, if
        compat_realm=1, or the User Principal Name if compat_realm=0

The trust auth method does not set an authenticated identity.  Neither
does clientcert=verify-full.

Port->authn_id could be used for other purposes, like a superuser-only
extra column in pg_stat_activity, but this is left as future work.

PostgresNode::connect_{ok,fails}() have been modified to let tests check
the backend log files for required or prohibited patterns, using the
new log_like and log_unlike parameters.  This uses a method based on a
truncation of the existing server log file, like issues_sql_like().
Tests are added to the ldap, kerberos, authentication and SSL test
suites.

Author: Jacob Champion
Reviewed-by: Stephen Frost, Magnus Hagander, Tom Lane, Michael Paquier
Discussion: https://postgr.es/m/c55788dd1773c521c862e8e0dddb367df51222be.camel@vmware.com

1 files changed, 54 insertions, 25 deletions

diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index 8db1829460..26c2c7077b 100644
--- a/src/test/kerberos/t/001_auth.pl
+++ b/src/test/kerberos/t/001_auth.pl
@@ -20,7 +20,7 @@ use Time::HiRes qw(usleep);
 
 if ($ENV{with_gssapi} eq 'yes')
 {
-	plan tests => 32;
+	plan tests => 44;
 }
 else
 {
@@ -183,39 +183,36 @@ note "running tests";
 sub test_access
 {
 	my ($node, $role, $query, $expected_res, $gssencmode, $test_name,
-		$expect_log_msg)
+		@expect_log_msgs)
 	  = @_;
 
 	# need to connect over TCP/IP for Kerberos
 	my $connstr = $node->connstr('postgres')
 	  . " user=$role host=$host hostaddr=$hostaddr $gssencmode";
 
+	my %params = (
+		sql => $query,
+	);
+
+	if (@expect_log_msgs)
+	{
+		# Match every message literally.
+		my @regexes = map { qr/\Q$_\E/ } @expect_log_msgs;
+
+		$params{log_like} = \@regexes;
+	}
+
 	if ($expected_res eq 0)
 	{
 		# The result is assumed to match "true", or "t", here.
-		$node->connect_ok(
-			$connstr, $test_name,
-			sql             => $query,
-			expected_stdout => qr/^t$/);
+		$params{expected_stdout} = qr/^t$/;
+
+		$node->connect_ok($connstr, $test_name, %params);
 	}
 	else
 	{
-		$node->connect_fails($connstr, $test_name);
+		$node->connect_fails($connstr, $test_name, %params);
 	}
-
-	# Verify specified log message is logged in the log file.
-	if ($expect_log_msg ne '')
-	{
-		my $first_logfile = slurp_file($node->logfile);
-
-		like($first_logfile, qr/\Q$expect_log_msg\E/,
-			 'found expected log file content');
-	}
-
-	# Clean up any existing contents in the node's log file so as
-	# future tests don't step on each other's generated contents.
-	truncate $node->logfile, 0;
-	return;
 }
 
 # As above, but test for an arbitrary query result.
@@ -239,11 +236,19 @@ $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',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
+	"no match in usermap \"mymap\" for user \"test1\"");
 
 $node->append_conf('pg_ident.conf', qq{mymap  /^(.*)\@$realm\$  \\1});
 $node->restart;
@@ -255,6 +260,7 @@ test_access(
 	0,
 	'',
 	'succeeds with mapping with default gssencmode and host hba',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
 	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
 );
 
@@ -265,6 +271,7 @@ test_access(
 	0,
 	'gssencmode=prefer',
 	'succeeds with GSS-encrypted access preferred with host hba',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
 	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
 );
 test_access(
@@ -274,6 +281,7 @@ test_access(
 	0,
 	'gssencmode=require',
 	'succeeds with GSS-encrypted access required with host hba',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
 	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
 );
 
@@ -310,6 +318,7 @@ test_access(
 	0,
 	'gssencmode=prefer',
 	'succeeds with GSS-encrypted access preferred and hostgssenc hba',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
 	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
 );
 test_access(
@@ -319,10 +328,11 @@ test_access(
 	0,
 	'gssencmode=require',
 	'succeeds with GSS-encrypted access required and hostgssenc hba',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
 	"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', '');
+	'fails with GSS encryption disabled and hostgssenc hba');
 
 unlink($node->data_dir . '/pg_hba.conf');
 $node->append_conf('pg_hba.conf',
@@ -336,10 +346,11 @@ test_access(
 	0,
 	'gssencmode=prefer',
 	'succeeds with GSS-encrypted access preferred and hostnogssenc hba, but no encryption',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
 	"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', '');
+	'fails with GSS-encrypted access required and hostnogssenc hba');
 test_access(
 	$node,
 	'test1',
@@ -347,6 +358,7 @@ test_access(
 	0,
 	'gssencmode=disable',
 	'succeeds with GSS encryption disabled and hostnogssenc hba',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
 	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=no, principal=test1\@$realm)"
 );
 
@@ -363,5 +375,22 @@ test_access(
 	0,
 	'',
 	'succeeds with include_realm=0 and defaults',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss",
 	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
 );
+
+# Reset pg_hba.conf, and cause a usermap failure with an authentication
+# that has passed.
+unlink($node->data_dir . '/pg_hba.conf');
+$node->append_conf('pg_hba.conf',
+	qq{host all all $hostaddr/32 gss include_realm=0 krb_realm=EXAMPLE.ORG});
+$node->restart;
+
+test_access(
+	$node,
+	'test1',
+	'SELECT true',
+	2,
+	'',
+	'fails with wrong krb_realm, but still authenticates',
+	"connection authenticated: identity=\"test1\@$realm\" method=gss");