On Tue, 2021-03-30 at 17:06 +0000, Jacob Champion wrote:
> 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.
I wasn't able to make live rotation work in a sane way. So, v14 tries
to thread the needle with a riff on your earlier idea:
> If you want to keep this information around
> for debugging, I guess that we could just print the contents of the
> backend logs to regress_log_001_password instead? This could be done
> with a simple wrapper routine that prints the past contents of the log
> file before truncating them.
Rather than putting Postgres log data into the Perl logs, I rotate the
logs exactly once at the beginning -- so that there's an
old 001_ssltests_primary.log, and a new 001_ssltests_primary_1.log --
and then every time we truncate the logfile, I shuffle the bits from
the new logfile into the old one. So no one has to learn to find the
log entries in a new place, we don't get an explosion of rotated logs,
we don't lose the log data, we don't match incorrect portions of the
logs, and we only pay the restart price once. This is wrapped into a
small Perl module, LogCollector.
WDYT?
--Jacob
diff --git a/src/test/ssl/t/001_ssltests.pl b/src/test/ssl/t/001_ssltests.pl
index 9fac0689ee..b5fb15f794 100644
--- a/src/test/ssl/t/001_ssltests.pl
+++ b/src/test/ssl/t/001_ssltests.pl
@@ -10,6 +10,7 @@ use FindBin;
use lib $FindBin::RealBin;
use SSLServer;
+use LogCollector;
if ($ENV{with_ssl} ne 'openssl')
{
@@ -454,8 +455,7 @@ test_connect_fails(
);
-my $log = $node->rotate_logfile();
-$node->restart;
+my $log = LogCollector->new($node);
# correct client cert using whole DN
my $dn_connstr = "$common_connstr dbname=certdb_dn";
@@ -466,16 +466,10 @@ test_connect_ok(
"certificate authorization succeeds with DN mapping"
);
-$node->stop('fast');
-my $log_contents = slurp_file($log);
-
-like(
- $log_contents,
+$log->like(
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";
@@ -485,8 +479,7 @@ test_connect_ok(
"certificate authorization succeeds with DN regex mapping"
);
-$log = $node->rotate_logfile();
-$node->restart;
+$log->rotate;
# same thing but using explicit CN
$dn_connstr = "$common_connstr dbname=certdb_cn";
@@ -497,17 +490,10 @@ test_connect_ok(
"certificate authorization succeeds with CN mapping"
);
-$node->stop('fast');
-$log_contents = slurp_file($log);
-
-like(
- $log_contents,
+$log->like(
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:
{
@@ -565,8 +551,7 @@ SKIP:
"certificate authorization fails because of file permissions");
}
-$log = $node->rotate_logfile();
-$node->restart;
+$log->rotate;
# client cert belonging to another user
test_connect_fails(
@@ -576,17 +561,10 @@ test_connect_fails(
"certificate authorization fails with client cert belonging to another
user"
);
-$node->stop('fast');
-$log_contents = slurp_file($log);
-
-like(
- $log_contents,
+$log->like(
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,
@@ -594,25 +572,16 @@ test_connect_fails(
qr/SSL error/,
"certificate authorization fails with revoked client cert");
-$node->stop('fast');
-$log_contents = slurp_file($log);
-
-unlike(
- $log_contents,
+$log->unlike(
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",
@@ -634,18 +603,12 @@ 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,
+$log->unlike(
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 c15b9c405b..81aaa0b02d 100644
--- a/src/test/ssl/t/002_scram.pl
+++ b/src/test/ssl/t/002_scram.pl
@@ -12,6 +12,7 @@ use FindBin;
use lib $FindBin::RealBin;
use SSLServer;
+use LogCollector;
if ($ENV{with_ssl} ne 'openssl')
{
@@ -102,8 +103,7 @@ 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;
+my $log = LogCollector->new($node);
# Certificate verification at the connection level should still work fine.
test_connect_ok(
@@ -111,16 +111,10 @@ test_connect_ok(
"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,
+$log->like(
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);
diff --git a/src/test/ssl/t/LogCollector.pm b/src/test/ssl/t/LogCollector.pm
new file mode 100644
index 0000000000..ce0c4063f2
--- /dev/null
+++ b/src/test/ssl/t/LogCollector.pm
@@ -0,0 +1,84 @@
+# This module defines a class to help match log entries to specific connections
+# or queries.
+
+package LogCollector;
+
+use strict;
+use warnings;
+use TestLib;
+use Test::More ();
+
+use Exporter 'import';
+our @EXPORT = qw(
+ start_log_capture
+);
+
+# Wrap a new collector around $node.
+#
+# The node's current logfile will be saved, then rotated, so that future log
+# entries are written to a new logfile. Whenever the rotate() method is called
+# on the collector, all entries from the new logfile will be appended to the
old
+# logfile, and then the new logfile will be truncated. This gives a clean slate
+# to the next tests.
+sub new
+{
+ my ($class, $node) = @_;
+
+ my $self = {
+ _node => $node,
+ _orig_log => $node->logfile,
+ _log => $node->rotate_logfile,
+ };
+ bless $self, $class;
+
+ $node->restart; # start writing to the new log
+ return $self;
+}
+
+# Returns the contents of the current (new) logfile. These will be written to
+# the old logfile when rotate() is called.
+sub contents
+{
+ my $self = shift;
+
+ return slurp_file($self->{_log});
+}
+
+# Writes the current contents of the new logfile to the old logfile, then
+# truncates the new logfile.
+sub rotate
+{
+ my $self = shift;
+ my $log_contents = $self->contents;
+
+ append_to_file($self->{_orig_log}, $log_contents);
+ truncate $self->{_log}, 0;
+}
+
+# Calls Test::More::like on the current logfile contents, then rotates the logs
+# so that future calls to like() or unlike() will not match the contents that
+# have already been checked.
+#
+# To avoid the auto-rotation behavior (e.g. if you want to perform multiple
+# checks on the same log contents), use contents() instead and perform a manual
+# rotate() after the checks are complete.
+sub like
+{
+ my ($self, $expected, $name) = @_;
+
+ Test::More::like($self->contents, $expected, $name);
+
+ $self->rotate;
+}
+
+# The opposite of like(), above.
+sub unlike
+{
+ my ($self, $expected, $name) = @_;
+
+ Test::More::unlike($self->contents, $expected, $name);
+
+ $self->rotate;
+}
+
+1;
From 943f0f253cb9cad901e06f4e53d98c7d5db59795 Mon Sep 17 00:00:00 2001
From: Jacob Champion <pchamp...@vmware.com>
Date: Wed, 3 Feb 2021 11:42:05 -0800
Subject: [PATCH v14] 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, and the SSL test suite has a new helper module to let tests
match log entries in isolation.
---
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 | 30 ++++-
src/test/ssl/t/002_scram.pl | 15 ++-
src/test/ssl/t/LogCollector.pm | 84 +++++++++++++
11 files changed, 427 insertions(+), 20 deletions(-)
create mode 100644 src/test/ssl/t/LogCollector.pm
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..b5fb15f794 100644
--- a/src/test/ssl/t/001_ssltests.pl
+++ b/src/test/ssl/t/001_ssltests.pl
@@ -10,6 +10,7 @@ use FindBin;
use lib $FindBin::RealBin;
use SSLServer;
+use LogCollector;
if ($ENV{with_ssl} ne 'openssl')
{
@@ -17,7 +18,7 @@ if ($ENV{with_ssl} ne 'openssl')
}
else
{
- plan tests => 103;
+ plan tests => 108;
}
#### Some configuration
@@ -454,6 +455,8 @@ test_connect_fails(
);
+my $log = LogCollector->new($node);
+
# correct client cert using whole DN
my $dn_connstr = "$common_connstr dbname=certdb_dn";
@@ -463,6 +466,10 @@ test_connect_ok(
"certificate authorization succeeds with DN mapping"
);
+$log->like(
+ qr/connection authenticated: identity="CN=ssltestuser-dn,OU=Testing,OU=Engineering,O=PGDG" method=cert/,
+ "authenticated DNs are logged");
+
# same thing but with a regex
$dn_connstr = "$common_connstr dbname=certdb_dn_re";
@@ -472,6 +479,8 @@ test_connect_ok(
"certificate authorization succeeds with DN regex mapping"
);
+$log->rotate;
+
# same thing but using explicit CN
$dn_connstr = "$common_connstr dbname=certdb_cn";
@@ -481,6 +490,9 @@ test_connect_ok(
"certificate authorization succeeds with CN mapping"
);
+$log->like(
+ 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");
TODO:
@@ -539,6 +551,8 @@ SKIP:
"certificate authorization fails because of file permissions");
}
+$log->rotate;
+
# client cert belonging to another user
test_connect_fails(
$common_connstr,
@@ -547,6 +561,10 @@ test_connect_fails(
"certificate authorization fails with client cert belonging to another user"
);
+$log->like(
+ qr/connection authenticated: identity="CN=ssltestuser" method=cert/,
+ "cert authentication succeeds even if authorization fails");
+
# revoked client cert
test_connect_fails(
$common_connstr,
@@ -554,6 +572,10 @@ test_connect_fails(
qr/SSL error/,
"certificate authorization fails with revoked client cert");
+$log->unlike(
+ qr/connection authenticated:/,
+ "revoked certs do not authenticate users");
+
# 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.
@@ -581,6 +603,12 @@ test_connect_ok(
"auth_option clientcert=verify-ca succeeds with mismatching username and Common Name"
);
+# None of the above connections to verifydb should have resulted in
+# authentication.
+$log->unlike(
+ qr/connection authenticated:/,
+ "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 410b9e910d..81aaa0b02d 100644
--- a/src/test/ssl/t/002_scram.pl
+++ b/src/test/ssl/t/002_scram.pl
@@ -12,6 +12,7 @@ use FindBin;
use lib $FindBin::RealBin;
use SSLServer;
+use LogCollector;
if ($ENV{with_ssl} ne 'openssl')
{
@@ -27,7 +28,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 +103,18 @@ test_connect_fails(
qr/channel binding required, but server authenticated client without channel binding/,
"Cert authentication and channel_binding=require");
+my $log = LogCollector->new($node);
+
+# 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");
+
+$log->like(
+ qr/connection authenticated: identity="ssltestuser" method=scram-sha-256/,
+ "SCRAM with clientcert=verify-full sets the username as the authenticated identity");
+
# clean up
unlink($client_tmp_key);
diff --git a/src/test/ssl/t/LogCollector.pm b/src/test/ssl/t/LogCollector.pm
new file mode 100644
index 0000000000..ce0c4063f2
--- /dev/null
+++ b/src/test/ssl/t/LogCollector.pm
@@ -0,0 +1,84 @@
+# This module defines a class to help match log entries to specific connections
+# or queries.
+
+package LogCollector;
+
+use strict;
+use warnings;
+use TestLib;
+use Test::More ();
+
+use Exporter 'import';
+our @EXPORT = qw(
+ start_log_capture
+);
+
+# Wrap a new collector around $node.
+#
+# The node's current logfile will be saved, then rotated, so that future log
+# entries are written to a new logfile. Whenever the rotate() method is called
+# on the collector, all entries from the new logfile will be appended to the old
+# logfile, and then the new logfile will be truncated. This gives a clean slate
+# to the next tests.
+sub new
+{
+ my ($class, $node) = @_;
+
+ my $self = {
+ _node => $node,
+ _orig_log => $node->logfile,
+ _log => $node->rotate_logfile,
+ };
+ bless $self, $class;
+
+ $node->restart; # start writing to the new log
+ return $self;
+}
+
+# Returns the contents of the current (new) logfile. These will be written to
+# the old logfile when rotate() is called.
+sub contents
+{
+ my $self = shift;
+
+ return slurp_file($self->{_log});
+}
+
+# Writes the current contents of the new logfile to the old logfile, then
+# truncates the new logfile.
+sub rotate
+{
+ my $self = shift;
+ my $log_contents = $self->contents;
+
+ append_to_file($self->{_orig_log}, $log_contents);
+ truncate $self->{_log}, 0;
+}
+
+# Calls Test::More::like on the current logfile contents, then rotates the logs
+# so that future calls to like() or unlike() will not match the contents that
+# have already been checked.
+#
+# To avoid the auto-rotation behavior (e.g. if you want to perform multiple
+# checks on the same log contents), use contents() instead and perform a manual
+# rotate() after the checks are complete.
+sub like
+{
+ my ($self, $expected, $name) = @_;
+
+ Test::More::like($self->contents, $expected, $name);
+
+ $self->rotate;
+}
+
+# The opposite of like(), above.
+sub unlike
+{
+ my ($self, $expected, $name) = @_;
+
+ Test::More::unlike($self->contents, $expected, $name);
+
+ $self->rotate;
+}
+
+1;
--
2.25.1
