WIP-log-authenticated-identity-from-multiple-auth-ba.patch

From 3f6e87a744be339748fc707cd071896e81e0323c Mon Sep 17 00:00:00 2001
From: Jacob Champion <pchampion@vmware.com>
Date: Fri, 22 Jan 2021 14:03:14 -0800
Subject: [PATCH] WIP: log authenticated identity from multiple auth backends

This is stored into port->authn_id according to the auth method:

  ldap: the final bind DN
  gss: the user principal
  cert: the client's Subject DN
  scram-sha-256: the Postgres username

It can be logged with the %Z specifier in log_line_prefix.
---
 src/backend/libpq/auth.c              | 21 ++++++++++-
 src/backend/libpq/be-secure-openssl.c | 22 +++++++++++
 src/backend/utils/error/elog.c        | 18 +++++++++
 src/include/libpq/libpq-be.h          | 12 ++++++
 src/test/kerberos/t/001_auth.pl       | 15 +++++++-
 src/test/ldap/t/001_auth.pl           | 22 ++++++++++-
 src/test/ssl/t/001_ssltests.pl        | 43 ++++++++++++++++++++-
 src/test/ssl/t/002_scram.pl           | 54 ++++++++++++++++++++++++++-
 8 files changed, 200 insertions(+), 7 deletions(-)

diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 545635f41a..2bff140d3c 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -1021,6 +1021,10 @@ CheckSCRAMAuth(Port *port, char *shadow_pass, char **logdetail)
 		return STATUS_ERROR;
 	}
 
+	/* TODO: move this up the stack so that it's shared by other password
+	 * authentication methods, once tests are written. */
+	port->authn_id = port->user_name;
+
 	return STATUS_OK;
 }
 
@@ -1208,9 +1212,10 @@ pg_GSS_checkauth(Port *port)
 
 	/*
 	 * Copy the original name of the authenticated principal into our backend
-	 * memory for display later.
+	 * memory for display later. This is also our authenticated identity.
 	 */
-	port->gss->princ = MemoryContextStrdup(TopMemoryContext, gbuf.value);
+	port->authn_id = port->gss->princ = MemoryContextStrdup(TopMemoryContext, gbuf.value);
+
 
 	/*
 	 * Split the username at the realm separator
@@ -2809,6 +2814,9 @@ CheckLDAPAuth(Port *port)
 		return STATUS_ERROR;
 	}
 
+	/* Save the original bind DN as the authenticated identity. */
+	port->authn_id = MemoryContextStrdup(TopMemoryContext, fulluser);
+
 	ldap_unbind(ldap);
 	pfree(passwd);
 	pfree(fulluser);
@@ -2861,6 +2869,15 @@ CheckCertAuth(Port *port)
 		return STATUS_ERROR;
 	}
 
+	if (port->hba->auth_method == uaCert)
+	{
+		/*
+		 * The client's Subject DN is our authenticated identity. Unfortunately
+		 * there is no canonical string representation; do the best we can.
+		 */
+		port->authn_id = be_tls_get_peer_full_subject_name(port);
+	}
+
 	/* Just pass the certificate cn to the usermap check */
 	status_check_usermap = check_usermap(port->hba->usermap, port->user_name, port->peer_cn, false);
 	if (status_check_usermap != STATUS_OK)
diff --git a/src/backend/libpq/be-secure-openssl.c b/src/backend/libpq/be-secure-openssl.c
index 1e2ecc6e7a..1c7f74dc22 100644
--- a/src/backend/libpq/be-secure-openssl.c
+++ b/src/backend/libpq/be-secure-openssl.c
@@ -562,12 +562,34 @@ aloop:
 
 			port->peer_cn = peer_cn;
 		}
+
 		port->peer_cert_valid = true;
 	}
 
 	return 0;
 }
 
+const char *
+be_tls_get_peer_full_subject_name(Port *port)
+{
+	if (!port->peer)
+		return NULL;
+
+	/*
+	 * TODO: decide on the format for the name, and perform sanity checks to
+	 * prohibit nasty edge cases (e.g. embedded NULLs) if the format doesn't
+	 * perform escaping itself.
+	 *
+	 * See also
+	 *     https://www.postgresql.org/message-id/daf119af-60a3-54d9-978e-8c97a602ca28%40dunslane.net
+	 *
+	 * TODO: allocate this string in an explicit context
+	 * TODO: reconcile this with be_tls_get_peer_subject_name, which silently
+	 *       truncates if your buffer isn't big enough
+	 */
+	return X509_NAME_oneline(X509_get_subject_name(port->peer), NULL, 0);
+}
+
 void
 be_tls_close(Port *port)
 {
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 80c2672461..f74f7571ac 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -2717,6 +2717,24 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 				else
 					appendStringInfoString(buf, unpack_sql_state(edata->sqlerrcode));
 				break;
+			case 'Z':
+				if (MyProcPort)
+				{
+					const char *authn_id = MyProcPort->authn_id;
+
+					/* TODO: should we consider the empty ID as unknown too? */
+					if (authn_id == NULL)
+						authn_id = _("[unknown]");
+					if (padding != 0)
+						appendStringInfo(buf, "%*s", padding, authn_id);
+					else
+						appendStringInfoString(buf, authn_id);
+
+				}
+				else if (padding != 0)
+					appendStringInfoSpaces(buf,
+										   padding > 0 ? padding : -padding);
+				break;
 			default:
 				/* format error - ignore it */
 				break;
diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 66a8673d93..69ea0d5dfb 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -154,6 +154,17 @@ 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
+	 * the "left side" of a pg_ident usermap.)
+	 *
+	 * 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.
 	 *
@@ -270,6 +281,7 @@ extern bool be_tls_get_compression(Port *port);
 extern const char *be_tls_get_version(Port *port);
 extern const char *be_tls_get_cipher(Port *port);
 extern void be_tls_get_peer_subject_name(Port *port, char *ptr, size_t len);
+extern const char *be_tls_get_peer_full_subject_name(Port *port);
 extern void be_tls_get_peer_issuer_name(Port *port, char *ptr, size_t len);
 extern void be_tls_get_peer_serial(Port *port, char *ptr, size_t len);
 
diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index 079321bbfc..8685d19487 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 => 34;
+	plan tests => 43;
 }
 else
 {
@@ -170,6 +170,7 @@ $node->append_conf(
 	'postgresql.conf', qq{
 listen_addresses = '$hostaddr'
 krb_server_keyfile = '$keytab'
+log_line_prefix = '%m [%p] %q%a (%u:%Z) '
 logging_collector = on
 log_connections = on
 # these ensure stability of test results:
@@ -268,10 +269,18 @@ $node->restart;
 
 test_access($node, 'test1', 'SELECT true', 2, '', 'fails without ticket', '');
 
+test_access($node, 'test1', 'SELECT true', 2, '',
+	'does not log unauthenticated principal',
+	"(test1:[unknown]) FATAL:  GSSAPI authentication failed");
+
 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, '',
+	'logs authenticated principal even without authorized mapping',
+	"(test1:test1\@$realm) LOG:  no match in usermap");
+
 $node->append_conf('pg_ident.conf', qq{mymap  /^(.*)\@$realm\$  \\1});
 $node->restart;
 
@@ -304,6 +313,10 @@ test_access(
 	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
 );
 
+test_access($node, 'test1', 'SELECT true', 0, 'gssencmode=require',
+	'logs authenticated principal for authorized connection',
+	"(test1:test1\@$realm) LOG:  connection authorized:");
+
 # Test that we can transport a reasonable amount of data.
 test_query(
 	$node,
diff --git a/src/test/ldap/t/001_auth.pl b/src/test/ldap/t/001_auth.pl
index 3bc7672451..34a1e9a10d 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_line_prefix = '%m [%p] %q%a (%u:%Z) '\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"}
@@ -187,6 +191,22 @@ test_access($node, 'test1', 2,
 $ENV{"PGPASSWORD"} = 'secret1';
 test_access($node, 'test1', 0, 'simple bind authentication succeeds');
 
+# make sure LDAP DNs are logged correctly
+$node->stop('fast');
+my $log_contents = slurp_file($log);
+
+like(
+	$log_contents,
+	qr/\(test1:uid=test1,dc=example,dc=net\).*SELECT 1/,
+	"authenticated DNs are logged");
+
+unlike(
+	$log_contents,
+	qr/\(test.:uid=test.,dc=example,dc=net\).*FATAL:.*LDAP authentication failed/,
+	"unauthenticated DNs are not 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 fd2727b568..58f371a306 100644
--- a/src/test/ssl/t/001_ssltests.pl
+++ b/src/test/ssl/t/001_ssltests.pl
@@ -13,7 +13,7 @@ use SSLServer;
 
 if ($ENV{with_openssl} eq 'yes')
 {
-	plan tests => 93;
+	plan tests => 96;
 }
 else
 {
@@ -74,6 +74,10 @@ $node->start;
 my $result = $node->safe_psql('postgres', "SHOW ssl_library");
 is($result, 'OpenSSL', 'ssl_library parameter');
 
+$node->append_conf(
+	'postgresql.conf',
+	"log_line_prefix = '%m [%p] %q%a (%u:%Z) '\n");
+
 configure_test_server_for_ssl($node, $SERVERHOSTADDR, $SERVERHOSTCIDR,
 	'trust');
 
@@ -399,6 +403,9 @@ test_connect_fails(
 	qr/connection requires a valid client certificate/,
 	"certificate authorization fails without client cert");
 
+my $log = $node->rotate_logfile();
+$node->restart;
+
 # correct client cert in unencrypted PEM
 test_connect_ok(
 	$common_connstr,
@@ -406,6 +413,16 @@ test_connect_ok(
 	"certificate authorization succeeds with correct client cert in PEM format"
 );
 
+# make sure certificate DNs are logged correctly
+$node->stop('fast');
+my $log_contents = slurp_file($log);
+$node->start;
+
+like(
+	$log_contents,
+	qr/\(ssltestuser:\/CN=ssltestuser\).*SELECT \$\$connected/,
+	"authenticated DNs are logged");
+
 # correct client cert in unencrypted DER
 test_connect_ok(
 	$common_connstr,
@@ -499,6 +516,9 @@ test_connect_fails(
 	"certificate authorization fails with client cert belonging to another user"
 );
 
+$log = $node->rotate_logfile();
+$node->restart;
+
 # revoked client cert
 test_connect_fails(
 	$common_connstr,
@@ -506,12 +526,24 @@ test_connect_fails(
 	qr/SSL error/,
 	"certificate authorization fails with revoked client cert");
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+$node->start;
+
+like(
+	$log_contents,
+	qr/\(\[unknown\]:\[unknown\]\).*could not accept SSL connection: certificate verify failed/,
+	"unauthenticated DNs are not logged");
+
 # 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",
@@ -533,6 +565,15 @@ test_connect_ok(
 	"auth_option clientcert=verify-ca succeeds with mismatching username and Common Name"
 );
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+$node->start;
+
+unlike(
+	$log_contents,
+	qr/\(.*:\/CN=ssltestuser\)/,
+	"trust auth method does not set authenticated identity");
+
 # 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 a088f71a1a..d8dd670c7a 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 ? 15 : 16;
 
 # Allocation of base connection string shared among multiple tests.
 my $common_connstr;
@@ -38,6 +38,10 @@ note "setting up data directory";
 my $node = get_new_node('primary');
 $node->init;
 
+$node->append_conf(
+	'postgresql.conf',
+	"log_line_prefix = '%m [%p] %q%a (%u:%Z) '\n");
+
 # PGHOST is enforced here to set up the node, subsequent connections
 # will use a dedicated connection string.
 $ENV{PGHOST} = $node->host;
@@ -48,14 +52,42 @@ $node->start;
 configure_test_server_for_ssl($node, $SERVERHOSTADDR, $SERVERHOSTCIDR,
 	"scram-sha-256", "pass", "scram-sha-256");
 switch_server_cert($node, 'server-cn-only');
-$ENV{PGPASSWORD} = "pass";
 $common_connstr =
   "dbname=trustdb sslmode=require sslcert=invalid sslrootcert=invalid hostaddr=$SERVERHOSTADDR";
 
+my $log = $node->rotate_logfile();
+$node->restart;
+
+# Bad password
+$ENV{PGPASSWORD} = "badpass";
+test_connect_fails($common_connstr, "user=ssltestuser",
+	qr/password authentication failed/,
+	"Basic SCRAM authentication with bad password");
+
+$node->stop('fast');
+my $log_contents = slurp_file($log);
+$log = $node->rotate_logfile();
+$node->start;
+
+unlike(
+	$log_contents,
+	qr/\(ssltestuser:ssltestuser\)/,
+	"SCRAM does not set authenticated identity with bad password");
+
 # Default settings
+$ENV{PGPASSWORD} = "pass";
 test_connect_ok($common_connstr, "user=ssltestuser",
 	"Basic SCRAM authentication with SSL");
 
+$node->stop('fast');
+$log_contents = slurp_file($log);
+$node->start;
+
+like(
+	$log_contents,
+	qr/\(ssltestuser:ssltestuser\)/,
+	"Basic SCRAM sets the username as the authenticated identity");
+
 # Test channel_binding
 test_connect_fails(
 	$common_connstr,
@@ -102,6 +134,24 @@ test_connect_fails(
 	qr/channel binding required, but server authenticated client without channel binding/,
 	"Cert authentication and channel_binding=require");
 
+$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');
+$log_contents = slurp_file($log);
+$node->start;
+
+like(
+	$log_contents,
+	qr/\(ssltestuser:ssltestuser\)/,
+	"SCRAM with clientcert=verify-full sets the username as the authenticated identity");
+
 # clean up
 unlink($client_tmp_key);
 
-- 
2.25.1