Date: Thu, 18 Mar 2021 17:14:24 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Jacob Champion <pchampion@vmware.com>
Cc: "magnus@hagander.net" <magnus@hagander.net>,
	"stark@mit.edu" <stark@mit.edu>,
	"pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>,
	"sfrost@snowman.net" <sfrost@snowman.net>,
	"tgl@sss.pgh.pa.us" <tgl@sss.pgh.pa.us>
Subject: Re: Proposal: Save user's original authenticated identity for logging
Message-ID: <YFML4MDZVWWuIBTF@paquier.xyz>
References: <c55788dd1773c521c862e8e0dddb367df51222be.camel@vmware.com>
 <a9ee5e4e8e844d06c2bcf70c6ed3306ccb4897f1.camel@vmware.com>
 <5d8b74e64fe4a610b23624277e497cc0a925db4b.camel@vmware.com>
 <2870147caa759155c5c8a232bbd2399f41f76491.camel@vmware.com>
 <4b2ca51542fa84e6fa37ab678624d5b400c092c0.camel@vmware.com>
 <CABUevExVHryTasKmtJW5RtU-dBesYj4bV7ggpeVMfiPCHCvLNA@mail.gmail.com>
 <a2fab8e350c86aa4fe245d1af521b0bbc807f11e.camel@vmware.com>
 <fc536fc557a664ad7b9dc0bf46ea335039044905.camel@vmware.com>
 <679382aaff23627a2e53541322c7a3158d402394.camel@vmware.com>
 <e3f7433d3e2bf31e8f67a9fb3790f660b7af586e.camel@vmware.com>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="RjmICSHfvdlTFxGo"
Content-Disposition: inline
In-Reply-To: <e3f7433d3e2bf31e8f67a9fb3790f660b7af586e.camel@vmware.com>
Archived-At: 
 <https://www.postgresql.org/message-id/YFML4MDZVWWuIBTF%40paquier.xyz>
Precedence: bulk


--RjmICSHfvdlTFxGo
Content-Type: multipart/mixed; boundary="TQIH4/AXD+HH+iQ9"
Content-Disposition: inline


--TQIH4/AXD+HH+iQ9
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Mon, Mar 15, 2021 at 03:50:48PM +0000, Jacob Champion wrote:
>  		# 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/;
> +
> +			# Don't include previously matched text in the search.
> +			$first_logfile = substr $first_logfile, $current_log_position;
> +			if ($first_logfile =~ m/\Q$expect_log_msg\E/g)
> +			{
> +				$current_log_position += pos($first_logfile);
> +				last;
> +			}
> +
>  			usleep(100_000);

Looking at 0001, I am not much a fan of relying on the position of the
matching pattern in the log file.  Instead of relying on the logging
collector and one single file, why not just changing the generation of
the logfile and rely on the output of stderr by restarting the server?
That means less tests, no need to wait for the logging collector to do
its business, and it solves your problem.  Please see the idea with
the patch attached.  Thoughts?
--
Michael

--TQIH4/AXD+HH+iQ9
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="krb5-tap-simplify.patch"
Content-Transfer-Encoding: quoted-printable

diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth=
=2Epl
index 079321bbfc..aca673e97a 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);
=20
 if ($ENV{with_gssapi} eq 'yes')
 {
-	plan tests =3D> 34;
+	plan tests =3D> 26;
 }
 else
 {
@@ -170,7 +170,6 @@ $node->append_conf(
 	'postgresql.conf', qq{
 listen_addresses =3D '$hostaddr'
 krb_server_keyfile =3D '$keytab'
-logging_collector =3D on
 log_connections =3D on
 # these ensure stability of test results:
 log_rotation_age =3D 0
@@ -212,27 +211,13 @@ sub test_access
 	# Verify specified log message is logged in the log file.
 	if ($expect_log_msg ne '')
 	{
-		my $current_logfiles =3D slurp_file($node->data_dir . '/current_logfiles=
');
-		note "current_logfiles =3D $current_logfiles";
-		like($current_logfiles, qr|^stderr log/postgresql-.*log$|,
-			 'current_logfiles is sane');
-
-		my $lfname =3D $current_logfiles;
-		$lfname =3D~ s/^stderr //;
-		chomp $lfname;
-
-		# might need to retry if logging collector process is slow...
-		my $max_attempts =3D 180 * 10;
-		my $first_logfile;
-		for (my $attempts =3D 0; $attempts < $max_attempts; $attempts++)
-		{
-			$first_logfile =3D slurp_file($node->data_dir . '/' . $lfname);
-			last if $first_logfile =3D~ m/\Q$expect_log_msg\E/;
-			usleep(100_000);
-		}
-
+		my $first_logfile =3D slurp_file($node->logfile);
 		like($first_logfile, qr/\Q$expect_log_msg\E/,
-			 'found expected log file content');
+		     'found expected log file content');
+
+		# Rotate to a new file, for any follow-up check.
+		$node->rotate_logfile;
+		$node->restart;
 	}
=20
 	return;

--TQIH4/AXD+HH+iQ9--

--RjmICSHfvdlTFxGo
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmBTC+AACgkQnvQgOdby
QH3zWg/+IOm0uE6Y8q60c2K/q3iXfU8QAIlUK7wbqdl2S0z/4BtaMfctETnETCMf
lbk1C3Yccfu4crp8arvKrLUibv5nNWfmsKVXbMUA/g0eOD5/0/fxL1fdxmzKtrSW
hzYYMyPyTRyhQlQrOrKdYes0YRDFb+MPEqp4Av/Le/82to1L28Lz8S9J6oABlPCZ
1JHRhCtHR0ShteNs+EaDQwedujE4U41RwvGJ91DPNlkcNf0lU2FJVvbAHqhAWkGp
14mwQRLalRytAHkBU5iX8ght8Q4SeO5pV3QFbaEYV1ehExSfNWY7oaQ9CrOOq18Z
OFn7pRL3qA8FaG3GKh6bhPnRkpgINHoMN2ZgcRIUXcWRS1H3p+AKQCJY8O9syEmu
GchB2Q4IdoPK4rCSZWD6YrHh/k03ttqNie8lc6WnDMlaTSo0+X8eWvOGOgV7Nuyw
TcNGwIcFk9OhHsJk78cCLt35T1sx7OYfTqGD0dg9NvwhZ68rTWIAuI1VY8bONNs+
SwQCE02iooVBSPjROIS4Ofk9/pLQuYqI+bunBMzIxFYNqD/q1VHJWy8ku3Bfowqi
7K9Rbn2aZMZRmDF+RNaaAO1f5HE4o+iT49Wli/nPNtPfj3r9eVk3LYZLi/+egcLg
VPYxUD4qzZDFClljk0pC5tMjjU7iUwIkXfp4ctT1RXEt7Hxg7mU=
=HBH2
-----END PGP SIGNATURE-----

--RjmICSHfvdlTFxGo--