On Tue, 2021-03-30 at 09:55 +0900, Michael Paquier wrote:
> On Mon, Mar 29, 2021 at 11:53:03PM +0000, Jacob Champion wrote:
> > It's not a matter of the tests being stable, but of the tests needing
> > to change and evolve as the implementation changes. A big part of that
> > is visibility into what the tests are doing, so that you can debug
> > them.
> 
> Sure, but I still don't quite see why this applies here?  At the point
> of any test, like() or unlink() print the contents of the comparison
> if there is a failure, so there is no actual loss of data.  That's
> what issues_sql_like() does, for one.

The key there is "if there is a failure" -- false positives need to be
debugged too. Tests I've worked with recently for the NSS work were
succeeding for the wrong reasons. Overly generic logfile matches ("SSL
error"), for example.

> > Keep in mind that the rotate-restart-slurp method comes from an
> > existing test. I assume Andrew chose that method for the same reasons I
> > did -- it works with what we currently have.
> 
> PostgresNode::rotate_logfile got introduced in c098509, and it is just
> used in t/017_shm.pl on HEAD.  There could be more simplifications
> with 019_replslot_limit.pl, I certainly agree with that.

modules/ssl_passphrase_callback/t/001_testfunc.pl is where I pulled
this pattern from.

> > Is the additional effort to create (and maintain) that new system worth
> > two seconds per run? I feel like it's not -- but if you feel strongly
> > then I can definitely look into it.
> 
> I fear that heavily parallelized runs could feel the difference.  Ask
> Andres about that, he has been able to trigger in parallel a failure
> with pg_upgrade wiping out testtablespace while the main regression
> test suite just began :) 

Does unilateral log truncation play any nicer with parallel test runs?
I understand not wanting to make an existing problem worse, but it
doesn't seem like the existing tests were written for general
parallelism.

Would it be acceptable to adjust the tests for live rotation using the
logging collector, rather than a full restart? It would unfortunately
mean that we have to somehow wait for the rotation to complete, since
that's asynchronous.

(Speaking of asynchronous: how does the existing check-and-truncate
code make sure that the log entries it's looking for have been flushed
to disk? Shutting down the server guarantees it.)

> > Which parts would you consider confusing/in need of change? I'm happy
> > to expand where needed. Would an inline sample be more helpful than a
> > textual explanation?
> 
> That's with the use of "authentication and authorization".  How can
> users make the difference between what one or this other is without
> some explanation with the name maps?  It seems that there is no place
> in the existing docs where this difference is explained.  I am
> wondering if it would be better to not change this paragraph, or
> reword it slightly to outline that this may cause more than one log
> entry, say:
> "Causes each attempted connection to the server, and each
> authentication activity to be logged."

I took a stab at this in v13: "Causes each attempted connection to the
server to be logged, as well as successful completion of both client
authentication (if necessary) and authorization." (IMO any further in-
depth explanation of authn/z and user mapping probably belongs in the
auth method documentation, and this patch doesn't change any authn/z
behavior.)

v13 also incorporates the latest SSL cert changes, so it's just a
single patch now. Tests now cover the CN and DN clientname modes. I
have not changed the log capture method yet; I'll take a look at it
next.

--Jacob
From 48cfecfb71ac276bede9abe3e374ebee8f428117 Mon Sep 17 00:00:00 2001
From: Jacob Champion <pchamp...@vmware.com>
Date: Wed, 3 Feb 2021 11:42:05 -0800
Subject: [PATCH v13] Log authenticated identity from all auth backends

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

To help DBAs see who has actually interacted with the system, store the
original identity when authentication succeeds, and expose it via the
log_connections setting. The log entries look something like this
example (where a local user named "pchampion" is connecting to the
database as the "admin" user):

    LOG:  connection received: host=[local]
    LOG:  connection authenticated: identity="pchampion" 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 auth method:

    bsd: the Postgres username (which is the local username)
    cert: the client's Subject DN
    gss: the user principal
    ident: the remote username
    ldap: the final bind DN
    pam: the Postgres username (which is the PAM username)
    password (and all pw-challenge methods): the Postgres username
    peer: the peer's pw_name
    radius: the Postgres username (which is 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 using clientcert=verify-full (use the cert auth method instead).

The Kerberos test suite has been modified to let tests match multiple
log lines.
---
 doc/src/sgml/config.sgml                  |   3 +-
 src/backend/libpq/auth.c                  | 137 ++++++++++++++++++++--
 src/backend/libpq/hba.c                   |  24 ++++
 src/include/libpq/hba.h                   |   1 +
 src/include/libpq/libpq-be.h              |  12 ++
 src/test/authentication/t/001_password.pl |  77 +++++++++++-
 src/test/kerberos/t/001_auth.pl           |  36 ++++--
 src/test/ldap/t/001_auth.pl               |  28 ++++-
 src/test/ssl/t/001_ssltests.pl            |  67 ++++++++++-
 src/test/ssl/t/002_scram.pl               |  21 +++-
 10 files changed, 386 insertions(+), 20 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index ddc6d789d8..a322729098 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6678,7 +6678,8 @@ local0.*    /var/log/postgresql
       <listitem>
        <para>
         Causes each attempted connection to the server to be logged,
-        as well as successful completion of client authentication.
+        as well as successful completion of both client authentication (if
+        necessary) and authorization.
         Only superusers can change this parameter at session start,
         and it cannot be changed at all within a session.
         The default is <literal>off</literal>.
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 9dc28e19aa..dcd02a94c3 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -34,8 +34,10 @@
 #include "libpq/scram.h"
 #include "miscadmin.h"
 #include "port/pg_bswap.h"
+#include "postmaster/postmaster.h"
 #include "replication/walsender.h"
 #include "storage/ipc.h"
+#include "utils/guc.h"
 #include "utils/memutils.h"
 #include "utils/timestamp.h"
 
@@ -47,6 +49,7 @@ static void sendAuthRequest(Port *port, AuthRequest areq, const char *extradata,
 							int extralen);
 static void auth_failed(Port *port, int status, char *logdetail);
 static char *recv_password_packet(Port *port);
+static void set_authn_id(Port *port, const char *id);
 
 
 /*----------------------------------------------------------------
@@ -337,6 +340,51 @@ auth_failed(Port *port, int status, char *logdetail)
 }
 
 
+/*
+ * Sets the authenticated identity for the current user. The provided string
+ * will be copied into the TopMemoryContext. The ID will be logged if
+ * log_connections is enabled.
+ *
+ * Auth methods should call this exactly once, as soon as the user is
+ * successfully authenticated, even if they have reason to know that
+ * authorization will fail later.
+ *
+ * The provided string will be copied into the TopMemoryContext, to match the
+ * lifetime of the Port, so it is safe to pass a string that is managed by an
+ * external library.
+ */
+static void
+set_authn_id(Port *port, const char *id)
+{
+	Assert(id);
+
+	if (port->authn_id)
+	{
+		/*
+		 * An existing authn_id should never be overwritten; that means two
+		 * authentication providers are fighting (or one is fighting itself).
+		 * Don't leak any authn details to the client, but don't let the
+		 * connection continue, either.
+		 */
+		ereport(FATAL,
+				(errmsg("connection was re-authenticated"),
+				 errdetail_log("previous ID: \"%s\"; new ID: \"%s\"",
+							   port->authn_id, id)));
+	}
+
+	port->authn_id = MemoryContextStrdup(TopMemoryContext, id);
+
+	if (Log_connections)
+	{
+		ereport(LOG,
+			errmsg("connection authenticated: identity=\"%s\" method=%s "
+				   "(%s:%d)",
+				   port->authn_id, hba_authname(port), HbaFileName,
+				   port->hba->linenumber));
+	}
+}
+
+
 /*
  * Client authentication starts here.  If there is an error, this
  * function does not return and the backend process is terminated.
@@ -757,6 +805,9 @@ CheckPasswordAuth(Port *port, char **logdetail)
 		pfree(shadow_pass);
 	pfree(passwd);
 
+	if (result == STATUS_OK)
+		set_authn_id(port, port->user_name);
+
 	return result;
 }
 
@@ -816,6 +867,10 @@ CheckPWChallengeAuth(Port *port, char **logdetail)
 		Assert(auth_result != STATUS_OK);
 		return STATUS_ERROR;
 	}
+
+	if (auth_result == STATUS_OK)
+		set_authn_id(port, port->user_name);
+
 	return auth_result;
 }
 
@@ -1174,8 +1229,13 @@ pg_GSS_checkauth(Port *port)
 	/*
 	 * Copy the original name of the authenticated principal into our backend
 	 * memory for display later.
+	 *
+	 * This is also our authenticated identity. Set it now, rather than waiting
+	 * for check_usermap below, because authentication has already succeeded and
+	 * we want the log file to reflect that.
 	 */
 	port->gss->princ = MemoryContextStrdup(TopMemoryContext, gbuf.value);
+	set_authn_id(port, gbuf.value);
 
 	/*
 	 * Split the username at the realm separator
@@ -1285,6 +1345,7 @@ pg_SSPI_recvauth(Port *port)
 	DWORD		domainnamesize = sizeof(domainname);
 	SID_NAME_USE accountnameuse;
 	HMODULE		secur32;
+	char	   *authn_id;
 
 	QUERY_SECURITY_CONTEXT_TOKEN_FN _QuerySecurityContextToken;
 
@@ -1514,6 +1575,26 @@ pg_SSPI_recvauth(Port *port)
 			return status;
 	}
 
+	/*
+	 * We have all of the information necessary to construct the authenticated
+	 * identity. Set it now, rather than waiting for check_usermap below,
+	 * because authentication has already succeeded and we want the log file to
+	 * reflect that.
+	 */
+	if (port->hba->compat_realm)
+	{
+		/* SAM-compatible format. */
+		authn_id = psprintf("%s\\%s", domainname, accountname);
+	}
+	else
+	{
+		/* Kerberos principal format. */
+		authn_id = psprintf("%s@%s", accountname, domainname);
+	}
+
+	set_authn_id(port, authn_id);
+	pfree(authn_id);
+
 	/*
 	 * Compare realm/domain if requested. In SSPI, always compare case
 	 * insensitive.
@@ -1901,8 +1982,15 @@ ident_inet_done:
 		pg_freeaddrinfo_all(local_addr.addr.ss_family, la);
 
 	if (ident_return)
-		/* Success! Check the usermap */
+	{
+		/*
+		 * Success! Store the identity and check the usermap. (Setting the
+		 * authenticated identity is done before checking the usermap, because
+		 * at this point, authentication has succeeded.)
+		 */
+		set_authn_id(port, ident_user);
 		return check_usermap(port->hba->usermap, port->user_name, ident_user, false);
+	}
 	return STATUS_ERROR;
 }
 
@@ -1926,7 +2014,6 @@ auth_peer(hbaPort *port)
 	gid_t		gid;
 #ifndef WIN32
 	struct passwd *pw;
-	char	   *peer_user;
 	int			ret;
 #endif
 
@@ -1958,12 +2045,14 @@ auth_peer(hbaPort *port)
 		return STATUS_ERROR;
 	}
 
-	/* Make a copy of static getpw*() result area. */
-	peer_user = pstrdup(pw->pw_name);
-
-	ret = check_usermap(port->hba->usermap, port->user_name, peer_user, false);
+	/*
+	 * Make a copy of static getpw*() result area; this is our authenticated
+	 * identity. Set it before calling check_usermap, because authentication has
+	 * already succeeded and we want the log file to reflect that.
+	 */
+	set_authn_id(port, pw->pw_name);
 
-	pfree(peer_user);
+	ret = check_usermap(port->hba->usermap, port->user_name, port->authn_id, false);
 
 	return ret;
 #else
@@ -2220,6 +2309,9 @@ CheckPAMAuth(Port *port, const char *user, const char *password)
 
 	pam_passwd = NULL;			/* Unset pam_passwd */
 
+	if (retval == PAM_SUCCESS)
+		set_authn_id(port, user);
+
 	return (retval == PAM_SUCCESS ? STATUS_OK : STATUS_ERROR);
 }
 #endif							/* USE_PAM */
@@ -2255,6 +2347,7 @@ CheckBSDAuth(Port *port, char *user)
 	if (!retval)
 		return STATUS_ERROR;
 
+	set_authn_id(port, user);
 	return STATUS_OK;
 }
 #endif							/* USE_BSD_AUTH */
@@ -2761,6 +2854,9 @@ CheckLDAPAuth(Port *port)
 		return STATUS_ERROR;
 	}
 
+	/* Save the original bind DN as the authenticated identity. */
+	set_authn_id(port, fulluser);
+
 	ldap_unbind(ldap);
 	pfree(passwd);
 	pfree(fulluser);
@@ -2824,6 +2920,31 @@ CheckCertAuth(Port *port)
 		return STATUS_ERROR;
 	}
 
+	if (port->hba->auth_method == uaCert)
+	{
+		/*
+		 * For cert auth, the client's Subject DN is always our authenticated
+		 * identity, even if we're only using its CN for authorization. Set it
+		 * now, rather than waiting for check_usermap below, because
+		 * authentication has already succeeded and we want the log file to
+		 * reflect that.
+		 */
+		if (!port->peer_dn)
+		{
+			/*
+			 * Unlikely to happen (this would mean that peer_cn is being used
+			 * but somehow we couldn't fill in peer_dn at the same time). This
+			 * probably indicates problems with the TLS backend.
+			 */
+			ereport(LOG,
+					(errmsg("certificate authentication failed for user \"%s\": unable to retrieve subject DN",
+							port->user_name)));
+			return STATUS_ERROR;
+		}
+
+		set_authn_id(port, port->peer_dn);
+	}
+
 	/* Just pass the certificate cn/dn to the usermap check */
 	status_check_usermap = check_usermap(port->hba->usermap, port->user_name, peer_username, false);
 	if (status_check_usermap != STATUS_OK)
@@ -2995,6 +3116,8 @@ CheckRADIUSAuth(Port *port)
 		 */
 		if (ret == STATUS_OK)
 		{
+			set_authn_id(port, port->user_name);
+
 			pfree(passwd);
 			return STATUS_OK;
 		}
diff --git a/src/backend/libpq/hba.c b/src/backend/libpq/hba.c
index feb711a6ef..b720b03e9a 100644
--- a/src/backend/libpq/hba.c
+++ b/src/backend/libpq/hba.c
@@ -3141,3 +3141,27 @@ hba_getauthmethod(hbaPort *port)
 {
 	check_hba(port);
 }
+
+
+/*
+ * Return the name of the auth method in use ("gss", "md5", "trust", etc.).
+ *
+ * The return value is statically allocated (see the UserAuthName array) and
+ * should not be freed.
+ */
+const char *
+hba_authname(hbaPort *port)
+{
+	UserAuth	auth_method;
+
+	Assert(port->hba);
+	auth_method = port->hba->auth_method;
+
+	if (auth_method < 0 || USER_AUTH_LAST < auth_method)
+	{
+		/* Should never happen. */
+		elog(FATAL, "port has out-of-bounds UserAuth: %d", auth_method);
+	}
+
+	return UserAuthName[auth_method];
+}
diff --git a/src/include/libpq/hba.h b/src/include/libpq/hba.h
index 1ec8603da7..63f2962139 100644
--- a/src/include/libpq/hba.h
+++ b/src/include/libpq/hba.h
@@ -137,6 +137,7 @@ typedef struct Port hbaPort;
 
 extern bool load_hba(void);
 extern bool load_ident(void);
+extern const char *hba_authname(hbaPort *port);
 extern void hba_getauthmethod(hbaPort *port);
 extern int	check_usermap(const char *usermap_name,
 						  const char *pg_role, const char *auth_user,
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 713c34fedd..312edd7fd0 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -159,6 +159,18 @@ typedef struct Port
 	 */
 	HbaLine    *hba;
 
+	/*
+	 * Authenticated identity. The meaning of this identifier is dependent on
+	 * hba->auth_method; it's the identity (if any) that the user presented
+	 * during the authentication cycle, before they were assigned a role. (It's
+	 * effectively the "SYSTEM-USERNAME" of a pg_ident usermap -- though the
+	 * exact string in use may be different, depending on pg_hba options.)
+	 *
+	 * authn_id is NULL if the user has not actually been authenticated, for
+	 * example if the "trust" auth method is in use.
+	 */
+	const char   *authn_id;
+
 	/*
 	 * TCP keepalive and user timeout settings.
 	 *
diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 36a616d7c7..adeb3bce33 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -17,7 +17,7 @@ if (!$use_unix_sockets)
 }
 else
 {
-	plan tests => 13;
+	plan tests => 21;
 }
 
 
@@ -57,6 +57,7 @@ sub test_role
 # Initialize primary node
 my $node = get_new_node('primary');
 $node->init;
+$node->append_conf('postgresql.conf', "log_connections = on\n");
 $node->start;
 
 # Create 3 roles with different password methods for each one. The same
@@ -69,27 +70,101 @@ $node->safe_psql('postgres',
 );
 $ENV{"PGPASSWORD"} = 'pass';
 
+my $log = $node->rotate_logfile();
+$node->restart;
+
 # For "trust" method, all users should be able to connect.
 reset_pg_hba($node, 'trust');
 test_role($node, 'scram_role', 'trust', 0);
 test_role($node, 'md5_role',   'trust', 0);
 
+$node->stop('fast');
+my $log_contents = slurp_file($log);
+
+unlike(
+	$log_contents,
+	qr/connection authenticated:/,
+	"trust method does not authenticate users");
+
+$log = $node->rotate_logfile();
+$node->start;
+
 # For plain "password" method, all users should also be able to connect.
 reset_pg_hba($node, 'password');
 test_role($node, 'scram_role', 'password', 0);
 test_role($node, 'md5_role',   'password', 0);
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="scram_role" method=password/,
+	"password method logs authenticated identity");
+
+$log = $node->rotate_logfile();
+$node->start;
+
 # For "scram-sha-256" method, user "scram_role" should be able to connect.
 reset_pg_hba($node, 'scram-sha-256');
 test_role($node, 'scram_role', 'scram-sha-256', 0);
 test_role($node, 'md5_role',   'scram-sha-256', 2);
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="scram_role" method=scram-sha-256/,
+	"scram-sha-256 method logs authenticated identity");
+
+unlike(
+	$log_contents,
+	qr/connection authenticated: identity="md5_role"/,
+	"mismatched crypt methods do not result in authentication");
+
+$log = $node->rotate_logfile();
+$node->start;
+
+# Test that bad passwords are rejected.
+$ENV{"PGPASSWORD"} = 'badpass';
+test_role($node, 'scram_role', 'scram-sha-256', 2);
+$ENV{"PGPASSWORD"} = 'pass';
+
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+# Make sure authenticated identity isn't set if the password is wrong.
+unlike(
+	$log_contents,
+	qr/connection authenticated:/,
+	"SCRAM does not set authenticated identity with bad password");
+
+$log = $node->rotate_logfile();
+$node->start;
+
 # For "md5" method, all users should be able to connect (SCRAM
 # authentication will be performed for the user with a SCRAM secret.)
 reset_pg_hba($node, 'md5');
 test_role($node, 'scram_role', 'md5', 0);
 test_role($node, 'md5_role',   'md5', 0);
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="md5_role" method=md5/,
+	"md5 method logs authenticated identity");
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="scram_role" method=md5/,
+	"md5 method logs authenticated identity for SCRAM users too");
+
+$log = $node->rotate_logfile();
+$node->start;
+
 # Tests for channel binding without SSL.
 # Using the password authentication method; channel binding can't work
 reset_pg_hba($node, 'password');
diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index 38e9ef7b1f..271e56824b 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 => 26;
+	plan tests => 38;
 }
 else
 {
@@ -182,7 +182,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, $expect_log_msg) = @_;
+	my ($node, $role, $query, $expected_res, $gssencmode, $test_name, @expect_log_msgs) = @_;
 
 	# need to connect over TCP/IP for Kerberos
 	my ($res, $stdoutres, $stderrres) = $node->psql(
@@ -206,8 +206,8 @@ sub test_access
 		is($res, $expected_res, $test_name);
 	}
 
-	# Verify specified log message is logged in the log file.
-	if ($expect_log_msg ne '')
+	# Verify specified log messages are logged in the log file.
+	while (my $expect_log_msg = shift @expect_log_msgs)
 	{
 		my $first_logfile = slurp_file($node->logfile);
 
@@ -249,11 +249,13 @@ $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;
@@ -265,6 +267,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)"
 );
 
@@ -275,6 +278,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(
@@ -284,6 +288,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)"
 );
 
@@ -320,6 +325,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(
@@ -329,10 +335,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',
@@ -346,10 +353,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',
@@ -357,6 +365,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)"
 );
 
@@ -373,5 +382,16 @@ 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)"
 );
+
+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"
+);
diff --git a/src/test/ldap/t/001_auth.pl b/src/test/ldap/t/001_auth.pl
index 3bc7672451..94f8850ca8 100644
--- a/src/test/ldap/t/001_auth.pl
+++ b/src/test/ldap/t/001_auth.pl
@@ -6,7 +6,7 @@ use Test::More;
 
 if ($ENV{with_ldap} eq 'yes')
 {
-	plan tests => 22;
+	plan tests => 24;
 }
 else
 {
@@ -152,6 +152,7 @@ note "setting up PostgreSQL instance";
 
 my $node = get_new_node('node');
 $node->init;
+$node->append_conf('postgresql.conf', "log_connections = on\n");
 $node->start;
 
 $node->safe_psql('postgres', 'CREATE USER test0;');
@@ -173,6 +174,9 @@ sub test_access
 
 note "simple bind";
 
+# save log location for later tests
+my $log = $node->rotate_logfile();
+
 unlink($node->data_dir . '/pg_hba.conf');
 $node->append_conf('pg_hba.conf',
 	qq{local all all ldap ldapserver=$ldap_server ldapport=$ldap_port ldapprefix="uid=" ldapsuffix=",dc=example,dc=net"}
@@ -184,9 +188,31 @@ test_access($node, 'test0', 2,
 	'simple bind authentication fails if user not found in LDAP');
 test_access($node, 'test1', 2,
 	'simple bind authentication fails with wrong password');
+
+$node->stop('fast');
+my $log_contents = slurp_file($log);
+
+unlike(
+	$log_contents,
+	qr/connection authenticated:/,
+	"unauthenticated DNs are not logged");
+
+$log = $node->rotate_logfile();
+$node->start;
+
 $ENV{"PGPASSWORD"} = 'secret1';
 test_access($node, 'test1', 0, 'simple bind authentication succeeds');
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="uid=test1,dc=example,dc=net" method=ldap/,
+	"authenticated DNs are logged");
+
+$node->start;
+
 note "search+bind";
 
 unlink($node->data_dir . '/pg_hba.conf');
diff --git a/src/test/ssl/t/001_ssltests.pl b/src/test/ssl/t/001_ssltests.pl
index adaa1b4e9b..9fac0689ee 100644
--- a/src/test/ssl/t/001_ssltests.pl
+++ b/src/test/ssl/t/001_ssltests.pl
@@ -17,7 +17,7 @@ if ($ENV{with_ssl} ne 'openssl')
 }
 else
 {
-	plan tests => 103;
+	plan tests => 108;
 }
 
 #### Some configuration
@@ -454,6 +454,9 @@ test_connect_fails(
 );
 
 
+my $log = $node->rotate_logfile();
+$node->restart;
+
 # correct client cert using whole DN
 my $dn_connstr = "$common_connstr dbname=certdb_dn";
 
@@ -463,6 +466,16 @@ test_connect_ok(
 	"certificate authorization succeeds with DN mapping"
 );
 
+$node->stop('fast');
+my $log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="CN=ssltestuser-dn,OU=Testing,OU=Engineering,O=PGDG" method=cert/,
+	"authenticated DNs are logged");
+
+$node->start;
+
 # same thing but with a regex
 $dn_connstr = "$common_connstr dbname=certdb_dn_re";
 
@@ -472,6 +485,9 @@ test_connect_ok(
 	"certificate authorization succeeds with DN regex mapping"
 );
 
+$log = $node->rotate_logfile();
+$node->restart;
+
 # same thing but using explicit CN
 $dn_connstr = "$common_connstr dbname=certdb_cn";
 
@@ -481,6 +497,16 @@ test_connect_ok(
 	"certificate authorization succeeds with CN mapping"
 );
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="CN=ssltestuser-dn,OU=Testing,OU=Engineering,O=PGDG" method=cert/,
+	"full authenticated DNs are logged even in CN mapping mode");
+
+$node->start;
+
 
 
 TODO:
@@ -539,6 +565,9 @@ SKIP:
 		"certificate authorization fails because of file permissions");
 }
 
+$log = $node->rotate_logfile();
+$node->restart;
+
 # client cert belonging to another user
 test_connect_fails(
 	$common_connstr,
@@ -547,6 +576,17 @@ test_connect_fails(
 	"certificate authorization fails with client cert belonging to another user"
 );
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="CN=ssltestuser" method=cert/,
+	"cert authentication succeeds even if authorization fails");
+
+$log = $node->rotate_logfile();
+$node->restart;
+
 # revoked client cert
 test_connect_fails(
 	$common_connstr,
@@ -554,12 +594,25 @@ test_connect_fails(
 	qr/SSL error/,
 	"certificate authorization fails with revoked client cert");
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+unlike(
+	$log_contents,
+	qr/connection authenticated:/,
+	"revoked certs do not authenticate users");
+
+$node->start;
+
 # Check that connecting with auth-option verify-full in pg_hba:
 # works, iff username matches Common Name
 # fails, iff username doesn't match Common Name.
 $common_connstr =
   "sslrootcert=ssl/root+server_ca.crt sslmode=require dbname=verifydb hostaddr=$SERVERHOSTADDR";
 
+$log = $node->rotate_logfile();
+$node->restart;
+
 test_connect_ok(
 	$common_connstr,
 	"user=ssltestuser sslcert=ssl/client.crt sslkey=ssl/client_tmp.key",
@@ -581,6 +634,18 @@ test_connect_ok(
 	"auth_option clientcert=verify-ca succeeds with mismatching username and Common Name"
 );
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+
+# None of the above connections to verifydb should have resulted in
+# authentication.
+unlike(
+	$log_contents,
+	qr/connection authenticated:/,
+	"trust auth method does not set authenticated identity");
+
+$node->start;
+
 # intermediate client_ca.crt is provided by client, and isn't in server's ssl_ca_file
 switch_server_cert($node, 'server-cn-only', 'root_ca');
 $common_connstr =
diff --git a/src/test/ssl/t/002_scram.pl b/src/test/ssl/t/002_scram.pl
index 410b9e910d..c15b9c405b 100644
--- a/src/test/ssl/t/002_scram.pl
+++ b/src/test/ssl/t/002_scram.pl
@@ -27,7 +27,7 @@ my $SERVERHOSTCIDR = '127.0.0.1/32';
 my $supports_tls_server_end_point =
   check_pg_config("#define HAVE_X509_GET_SIGNATURE_NID 1");
 
-my $number_of_tests = $supports_tls_server_end_point ? 9 : 10;
+my $number_of_tests = $supports_tls_server_end_point ? 11 : 12;
 
 # Allocation of base connection string shared among multiple tests.
 my $common_connstr;
@@ -102,6 +102,25 @@ test_connect_fails(
 	qr/channel binding required, but server authenticated client without channel binding/,
 	"Cert authentication and channel_binding=require");
 
+my $log = $node->rotate_logfile();
+$node->restart;
+
+# Certificate verification at the connection level should still work fine.
+test_connect_ok(
+	"sslcert=ssl/client.crt sslkey=$client_tmp_key sslrootcert=invalid hostaddr=$SERVERHOSTADDR",
+	"dbname=verifydb user=ssltestuser channel_binding=require",
+	"SCRAM with clientcert=verify-full and channel_binding=require");
+
+$node->stop('fast');
+my $log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/connection authenticated: identity="ssltestuser" method=scram-sha-256/,
+	"SCRAM with clientcert=verify-full sets the username as the authenticated identity");
+
+$node->start;
+
 # clean up
 unlink($client_tmp_key);
 
-- 
2.25.1

Reply via email to