Hello all,

First, the context: recently I've been digging into the use of third-
party authentication systems with Postgres. One sticking point is the
need to have a Postgres role corresponding to the third-party user
identity, which becomes less manageable at scale. I've been trying to
come up with ways to make that less painful, and to start peeling off
smaller feature requests.

= Problem =

For auth methods that allow pg_ident mapping, there's a way around the
one-role-per-user problem, which is to have all users that match some
pattern map to a single role. For Kerberos, you might specify that all
user principals under @EXAMPLE.COM are allowed to connect as some
generic user role, and that everyone matching */ad...@example.com is
additionally allowed to connect as an admin role.

Unfortunately, once you've been assigned a role, Postgres either makes
the original identity difficult to retrieve, or forgets who you were
entirely:

- for GSS, the original principal is saved in the Port struct, and you
need to either pull it out of pg_stat_gssapi, or enable log_connections
and piece the log line together with later log entries;
- for LDAP, the bind DN is discarded entirely;
- for TLS client certs, the DN has to be pulled from pg_stat_ssl or the
sslinfo extension (and it's truncated to 64 characters, so good luck if
you have a particularly verbose PKI tree);
- for peer auth, the username of the peereid is discarded;
- etc.

= Proposal =

I propose that every auth method should store the string it uses to
identify a user -- what I'll call an "authenticated identity" -- into
one central location in Port, after authentication succeeds but before
any pg_ident authorization occurs. This field can then be exposed in
log_line_prefix. (It could additionally be exposed through a catalog
table or SQL function, if that were deemed useful.) This would let a
DBA more easily audit user activity when using more complicated
pg_ident setups.

Attached is a proof of concept that implements this for a handful of
auth methods:

- ldap uses the final bind DN as its authenticated identity
- gss uses the user principal
- cert uses the client's Subject DN
- scram-sha-256 just uses the Postgres username

With this patch, the authenticated identity can be inserted into
log_line_prefix using the placeholder %Z.

= Implementation Notes =

- Client certificates can be combined with other authentication methods
using the clientcert option, but that doesn't provide an authenticated
identity in my proposal. *Only* the cert auth method populates the
authenticated identity from a client certificate. This keeps the patch
from having to deal with two simultaneous identity sources.

- The trust auth method has an authenticated identity of NULL, logged
as [unknown]. I kept this property even when clientcert=verify-full is
in use (which would otherwise be identical to the cert auth method), to
hammer home that 1) trust is not an authentication method and 2) the
clientcert option does not provide an authenticated identity. Whether
this is a useful property, or just overly pedantic, is probably
something that could be debated.

- The cert method's Subject DN string formatting needs the same
considerations that are currently under discussion in Andrew's DN patch
[1].

- I'm not crazy about the testing method -- it leads to a lot of log
file proliferation in the tests -- but I wanted to make sure that we
had test coverage for the log lines themselves. The ability to
correctly audit user behavior depends on us logging the correct
identity after authentication, but not a moment before.

Would this be generally useful for those of you using pg_ident in
production? Have I missed something that already provides this
functionality?

Thanks,
--Jacob

[1] 
https://www.postgresql.org/message-id/flat/92e70110-9273-d93c-5913-0bccb6562...@dunslane.net



From 3f6e87a744be339748fc707cd071896e81e0323c Mon Sep 17 00:00:00 2001
From: Jacob Champion <pchamp...@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

Reply via email to