On Thu, Nov 5, 2020 at 9:50 AM Bharath Rupireddy
<bharath.rupireddyforpostg...@gmail.com> wrote:
>
> On Thu, Nov 5, 2020 at 7:55 AM Euler Taveira <euler.tave...@2ndquadrant.com> 
> wrote:
> >
> > No. Don't worry with translations during the development. Make sure to 
> > follow
> > the instructions provided here [1]. Translations are coordinated in a 
> > different
> > mailing list: pgsql-translators [2]. There is a different repository [3] for
> > handling PO files and the updated files are merged by Peter Eisentraut just
> > before each minor/major release. We usually start to update translations 
> > after
> > feature freeze.
> >
>
> Thanks.
>
> On Tue, Nov 3, 2020 at 12:49 PM vignesh C <vignes...@gmail.com> wrote:
> >
> > Thanks for the explanation, I have attached a v5 patch with the
> > changes where the translation should not have any problem.
> >
>
> I have taken a further look at the V5 patch:
>
> 1. We wait 10sec until the syslogger process logs the expected message, what 
> happens if someone intentionally made the syslogger process to wait for a 
> longer duration?  Will the new tests fail?
>     # might need to retry if logging collector process is slow...
>         my $max_attempts = 10 * 10;
>         my $first_logfile;
>         for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
>         {
>             $first_logfile = slurp_file($node->data_dir . '/' . $lfname);
>             last if $first_logfile =~ m/$expect_log_msg /;
>             usleep(100_000);
>         }
>

Yes the test will fail if it takes more than the max_attempts as there
is a like statement immediately after the loop:
                like($first_logfile, qr/\Q$expect_log_msg\E/,
                         'found expected log file content');
I have also increased the attempts to 180 seconds just like other
tests to avoid failure in very slow systems.

> 2. I intentionally altered(for testing purpose only) the expected log message 
> input given to test_access(), expecting the tests to fail, but the test 
> succeeded. Am I missing something here? Is it that the syslogger process not 
> logging the message at all or within the 10sec waiting? Do we need to 
> increase the wait duration? Do we need to do something to fail the test when 
> we don't see the expected log message in test_access()?
>
> "cXNnnection authorized: user=......
> "connecTEion authorized: user=....
> "connection auTThorized:.....
>

Thanks for testing this, I had missed testing this. The expression
matching was not correct. Attached v6 patch which includes the fix for
this.

Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com
From 0d190bbe888127aed0c8db2e061cb8cdc8b99ee5 Mon Sep 17 00:00:00 2001
From: Vignesh C <vignes...@gmail.com>
Date: Fri, 30 Oct 2020 17:58:45 +0530
Subject: [PATCH v6] Improving the connection authorization message for GSS
 authenticated/encrypted connections.

Added log message to include GSS authentication, encryption & principal
information. This message will help the user to know if GSS authentication or
encryption was used and which GSS principal was used.
---
 src/backend/utils/init/postinit.c |  81 ++++++++++----------------
 src/test/kerberos/t/001_auth.pl   | 117 +++++++++++++++++++++++++++-----------
 2 files changed, 112 insertions(+), 86 deletions(-)

diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index d4ab4c7..0e73598 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -246,62 +246,39 @@ PerformAuthentication(Port *port)
 
 	if (Log_connections)
 	{
+		StringInfoData logmsg;
+		initStringInfo(&logmsg);
 		if (am_walsender)
-		{
-#ifdef USE_SSL
-			if (port->ssl_in_use)
-				ereport(LOG,
-						(port->application_name != NULL
-						 ? errmsg("replication connection authorized: user=%s application_name=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-								  port->user_name,
-								  port->application_name,
-								  be_tls_get_version(port),
-								  be_tls_get_cipher(port),
-								  be_tls_get_cipher_bits(port),
-								  be_tls_get_compression(port) ? _("on") : _("off"))
-						 : errmsg("replication connection authorized: user=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-								  port->user_name,
-								  be_tls_get_version(port),
-								  be_tls_get_cipher(port),
-								  be_tls_get_cipher_bits(port),
-								  be_tls_get_compression(port) ? _("on") : _("off"))));
-			else
-#endif
-				ereport(LOG,
-						(port->application_name != NULL
-						 ? errmsg("replication connection authorized: user=%s application_name=%s",
-								  port->user_name,
-								  port->application_name)
-						 : errmsg("replication connection authorized: user=%s",
-								  port->user_name)));
-		}
+			appendStringInfo(&logmsg, _("replication connection authorized: user=%s"),
+							 port->user_name);
 		else
-		{
+			appendStringInfo(&logmsg, _("connection authorized: user=%s"),
+							 port->user_name);
+		if (!am_walsender)
+			appendStringInfo(&logmsg, _(" database=%s"), port->database_name);
+
+		if (port->application_name != NULL)
+			appendStringInfo(&logmsg, _(" application_name=%s"),
+							 port->application_name);
+
 #ifdef USE_SSL
-			if (port->ssl_in_use)
-				ereport(LOG,
-						(port->application_name != NULL
-						 ? errmsg("connection authorized: user=%s database=%s application_name=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-								  port->user_name, port->database_name, port->application_name,
-								  be_tls_get_version(port),
-								  be_tls_get_cipher(port),
-								  be_tls_get_cipher_bits(port),
-								  be_tls_get_compression(port) ? _("on") : _("off"))
-						 : errmsg("connection authorized: user=%s database=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-								  port->user_name, port->database_name,
-								  be_tls_get_version(port),
-								  be_tls_get_cipher(port),
-								  be_tls_get_cipher_bits(port),
-								  be_tls_get_compression(port) ? _("on") : _("off"))));
-			else
+		if (port->ssl_in_use)
+			appendStringInfo(&logmsg, _(" SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)"),
+							 be_tls_get_version(port),
+							 be_tls_get_cipher(port),
+							 be_tls_get_cipher_bits(port),
+							 be_tls_get_compression(port) ? _("on") : _("off"));
 #endif
-				ereport(LOG,
-						(port->application_name != NULL
-						 ? errmsg("connection authorized: user=%s database=%s application_name=%s",
-								  port->user_name, port->database_name, port->application_name)
-						 : errmsg("connection authorized: user=%s database=%s",
-								  port->user_name, port->database_name)));
-		}
+#ifdef ENABLE_GSS
+		if (be_gssapi_get_princ(port))
+			appendStringInfo(&logmsg, _(" GSS (authenticated=%s, encrypted=%s, principal=%s)"),
+							 be_gssapi_get_auth(port) ? _("yes") : _("no"),
+							 be_gssapi_get_enc(port) ? _("yes") : _("no"),
+							 be_gssapi_get_princ(port));
+#endif
+
+		ereport(LOG, errmsg_internal("%s", logmsg.data));
+		pfree(logmsg.data);
 	}
 
 	set_ps_display("startup");
diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl
index b3aeea9..8d79db2 100644
--- a/src/test/kerberos/t/001_auth.pl
+++ b/src/test/kerberos/t/001_auth.pl
@@ -16,10 +16,11 @@ use warnings;
 use TestLib;
 use PostgresNode;
 use Test::More;
+use Time::HiRes qw(usleep);
 
 if ($ENV{with_gssapi} eq 'yes')
 {
-	plan tests => 18;
+	plan tests => 32;
 }
 else
 {
@@ -74,6 +75,10 @@ my $kdc_datadir = "${TestLib::tmp_check}/krb5kdc";
 my $kdc_pidfile = "${TestLib::tmp_check}/krb5kdc.pid";
 my $keytab      = "${TestLib::tmp_check}/krb5.keytab";
 
+my $dbname = 'postgres';
+my $username = 'test1';
+my $application = '001_auth.pl';
+
 note "setting up Kerberos";
 
 my ($stdout, $krb5_version);
@@ -160,6 +165,8 @@ my $node = get_new_node('node');
 $node->init;
 $node->append_conf('postgresql.conf', "listen_addresses = '$hostaddr'");
 $node->append_conf('postgresql.conf', "krb_server_keyfile = '$keytab'");
+$node->append_conf('postgresql.conf', "logging_collector = on");
+$node->append_conf('postgresql.conf', "log_connections = on");
 $node->start;
 
 $node->safe_psql('postgres', 'CREATE USER test1;');
@@ -169,7 +176,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) = @_;
+	my ($node, $role, $query, $expected_res, $gssencmode, $test_name, $expect_log_msg) = @_;
 
 	# need to connect over TCP/IP for Kerberos
 	my ($res, $stdoutres, $stderrres) = $node->psql(
@@ -192,6 +199,33 @@ sub test_access
 	{
 		is($res, $expected_res, $test_name);
 	}
+
+	# Verify specified log message is logged in the log file.
+	if ($expect_log_msg ne '')
+	{
+		my $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+		note "current_logfiles = $current_logfiles";
+		like($current_logfiles, qr|^stderr log/postgresql-.*log$|,
+			 'current_logfiles is sane');
+
+		my $lfname = $current_logfiles;
+		$lfname =~ s/^stderr //;
+		chomp $lfname;
+
+		# might need to retry if logging collector process is slow...
+		my $max_attempts = 180 * 10;
+		my $first_logfile;
+		for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
+		{
+			$first_logfile = slurp_file($node->data_dir . '/' . $lfname);
+			last if $first_logfile =~ m/\Q$expect_log_msg\E/;
+			usleep(100_000);
+		}
+
+		like($first_logfile, qr/\Q$expect_log_msg\E/,
+			 'found expected log file content');
+	}
+
 	return;
 }
 
@@ -223,11 +257,11 @@ $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', '');
 
 $node->append_conf('pg_ident.conf', qq{mymap  /^(.*)\@$realm\$  \\1});
 $node->restart;
@@ -238,42 +272,49 @@ test_access(
 	'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
 	0,
 	'',
-	'succeeds with mapping with default gssencmode and host hba');
+	'succeeds with mapping with default gssencmode and host hba',
+	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
+
 test_access(
 	$node,
-	"test1",
+	'test1',
 	'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
 	0,
-	"gssencmode=prefer",
-	"succeeds with GSS-encrypted access preferred with host hba");
+	'gssencmode=prefer',
+	'succeeds with GSS-encrypted access preferred with host hba',
+	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
 test_access(
 	$node,
-	"test1",
+	'test1',
 	'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
 	0,
-	"gssencmode=require",
-	"succeeds with GSS-encrypted access required with host hba");
+	'gssencmode=require',
+	'succeeds with GSS-encrypted access required with host hba',
+	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
 
 # Test that we can transport a reasonable amount of data.
 test_query(
 	$node,
-	"test1",
+	'test1',
 	'SELECT * FROM generate_series(1, 100000);',
 	qr/^1\n.*\n1024\n.*\n9999\n.*\n100000$/s,
-	"gssencmode=require",
-	"receiving 100K lines works");
+	'gssencmode=require',
+	'receiving 100K lines works');
 
 test_query(
 	$node,
-	"test1",
+	'test1',
 	"CREATE TABLE mytab (f1 int primary key);\n"
 	  . "COPY mytab FROM STDIN;\n"
 	  . join("\n", (1 .. 100000))
 	  . "\n\\.\n"
 	  . "SELECT COUNT(*) FROM mytab;",
 	qr/^100000$/s,
-	"gssencmode=require",
-	"sending 100K lines works");
+	'gssencmode=require',
+	'sending 100K lines works');
 
 unlink($node->data_dir . '/pg_hba.conf');
 $node->append_conf('pg_hba.conf',
@@ -282,20 +323,24 @@ $node->restart;
 
 test_access(
 	$node,
-	"test1",
+	'test1',
 	'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
 	0,
-	"gssencmode=prefer",
-	"succeeds with GSS-encrypted access preferred and hostgssenc hba");
+	'gssencmode=prefer',
+	'succeeds with GSS-encrypted access preferred and hostgssenc hba',
+	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
+);
 test_access(
 	$node,
-	"test1",
+	'test1',
 	'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
 	0,
-	"gssencmode=require",
-	"succeeds with GSS-encrypted access required and hostgssenc hba");
-test_access($node, "test1", 'SELECT true', 2, "gssencmode=disable",
-	"fails with GSS encryption disabled and hostgssenc hba");
+	'gssencmode=require',
+	'succeeds with GSS-encrypted access required and hostgssenc hba',
+	"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', '');
 
 unlink($node->data_dir . '/pg_hba.conf');
 $node->append_conf('pg_hba.conf',
@@ -304,21 +349,24 @@ $node->restart;
 
 test_access(
 	$node,
-	"test1",
+	'test1',
 	'SELECT gss_authenticated and not encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
 	0,
-	"gssencmode=prefer",
-	"succeeds with GSS-encrypted access preferred and hostnogssenc hba, but no encryption"
+	'gssencmode=prefer',
+	'succeeds with GSS-encrypted access preferred and hostnogssenc hba, but no encryption',
+	"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");
+test_access($node, 'test1', 'SELECT true', 2, 'gssencmode=require',
+	'fails with GSS-encrypted access required and hostnogssenc hba', '');
 test_access(
 	$node,
-	"test1",
+	'test1',
 	'SELECT gss_authenticated and not encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
 	0,
-	"gssencmode=disable",
-	"succeeds with GSS encryption disabled and hostnogssenc hba");
+	'gssencmode=disable',
+	'succeeds with GSS encryption disabled and hostnogssenc hba',
+	"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=no, principal=test1\@$realm)"
+);
 
 truncate($node->data_dir . '/pg_ident.conf', 0);
 unlink($node->data_dir . '/pg_hba.conf');
@@ -332,4 +380,5 @@ test_access(
 	'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
 	0,
 	'',
-	'succeeds with include_realm=0 and defaults');
+	'succeeds with include_realm=0 and defaults',
+	'');
-- 
1.8.3.1

Reply via email to