Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1u5rf2-0078RY-D4 for pgsql-hackers@arkaria.postgresql.org; Fri, 18 Apr 2025 19:46:04 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1u5rf0-001Fxo-JV for pgsql-hackers@arkaria.postgresql.org; Fri, 18 Apr 2025 19:46:03 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1u5rf0-001Frf-1X for pgsql-hackers@lists.postgresql.org; Fri, 18 Apr 2025 19:46:03 +0000 Received: from sss.pgh.pa.us ([68.162.161.243]) by makus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.96) (envelope-from ) id 1u5rey-000ksA-0J for pgsql-hackers@postgresql.org; Fri, 18 Apr 2025 19:46:01 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.15.2/8.15.2) with ESMTP id 53IJjwK22814409; Fri, 18 Apr 2025 15:45:58 -0400 From: Tom Lane To: Andrew Dunstan cc: PostgreSQL-development Subject: Re: disabled SSL log_like tests In-reply-to: <1ce11d3f-624c-4003-a032-1b10cc138305@dunslane.net> References: <984fca80-85a8-4c6f-a5cc-bb860950b435@dunslane.net> <2199758.1744901785@sss.pgh.pa.us> <1ce11d3f-624c-4003-a032-1b10cc138305@dunslane.net> Comments: In-reply-to Andrew Dunstan message dated "Thu, 17 Apr 2025 14:37:55 -0400" MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0" Content-ID: <2814238.1745005423.0@sss.pgh.pa.us> Date: Fri, 18 Apr 2025 15:45:58 -0400 Message-ID: <2814408.1745005558@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk ------- =_aaaaaaaaaa0 Content-Type: text/plain; charset="us-ascii" Content-ID: <2814238.1745005423.1@sss.pgh.pa.us> Andrew Dunstan writes: > On 2025-04-17 Th 10:56 AM, Tom Lane wrote: >> However, I wonder whether Andres' work at 8b886a4e3 could be used >> to improve this, either directly or as inspiration? > I don't think so - these tests are about checking log file contents, not > a psql problem. Well, I was mainly leaning on the "inspiration" part: the idea is to wait for something that must come out after the text we want to look for. After digging around a bit I noticed that 002_connection_limits.pl's connect_fails_wait is doing something that's almost what we want: that test cranks log_min_messages up to DEBUG2 and then waits for the postmaster's report of backend exit before believing that it's done. Awhile later I had the attached patch. Some notes: * The commented-out tests in 001_ssltests.pl contained hard-wired expectations as to certificate serial numbers, which are obsolete now. I just replaced them with "\d+", but if anyone feels like that's not good enough, we could continue to check for exact serial numbers and eat the ensuing maintenance effort. * I was more than slightly surprised to find that there are a bunch of other connect_fails callers that are testing log_like or log_unlike and thereby risking the same type of race condition. Some of those tests are relatively new and perhaps just haven't failed *yet*, but I wonder if we changed something since 2022 that solves this problem in a different way? Anyway, after this change any such caller must set log_min_messages = debug2 or fail. I think I got all the relevant test scripts in the attached. regards, tom lane ------- =_aaaaaaaaaa0 Content-Type: text/x-diff; name="v1-fix-connect_fails-races.patch"; charset="us-ascii" Content-ID: <2814238.1745005423.2@sss.pgh.pa.us> Content-Description: v1-fix-connect_fails-races.patch Content-Transfer-Encoding: quoted-printable diff --git a/src/test/authentication/t/001_password.pl b/src/test/authenti= cation/t/001_password.pl index 756b4146050..37d96d95a1a 100644 --- a/src/test/authentication/t/001_password.pl +++ b/src/test/authentication/t/001_password.pl @@ -66,6 +66,8 @@ sub test_conn my $node =3D PostgreSQL::Test::Cluster->new('primary'); $node->init; $node->append_conf('postgresql.conf', "log_connections =3D on\n"); +# Needed to allow connect_fails to inspect postmaster log: +$node->append_conf('postgresql.conf', "log_min_messages =3D debug2"); $node->start; = # Test behavior of log_connections GUC diff --git a/src/test/authentication/t/003_peer.pl b/src/test/authenticati= on/t/003_peer.pl index 69ba73bd2b9..2879800eacf 100644 --- a/src/test/authentication/t/003_peer.pl +++ b/src/test/authentication/t/003_peer.pl @@ -72,6 +72,8 @@ sub test_role my $node =3D PostgreSQL::Test::Cluster->new('node'); $node->init; $node->append_conf('postgresql.conf', "log_connections =3D on\n"); +# Needed to allow connect_fails to inspect postmaster log: +$node->append_conf('postgresql.conf', "log_min_messages =3D debug2"); $node->start; = # Set pg_hba.conf with the peer authentication. diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_aut= h.pl index 6748b109dec..2dc6bec9b89 100644 --- a/src/test/kerberos/t/001_auth.pl +++ b/src/test/kerberos/t/001_auth.pl @@ -66,6 +66,7 @@ $node->append_conf( listen_addresses =3D '$hostaddr' krb_server_keyfile =3D '$krb->{keytab}' log_connections =3D on +log_min_messages =3D debug2 lc_messages =3D 'C' }); $node->start; diff --git a/src/test/ldap/t/001_auth.pl b/src/test/ldap/t/001_auth.pl index 352b0fc1fa7..d1315ed5351 100644 --- a/src/test/ldap/t/001_auth.pl +++ b/src/test/ldap/t/001_auth.pl @@ -48,6 +48,8 @@ note "setting up PostgreSQL instance"; my $node =3D PostgreSQL::Test::Cluster->new('node'); $node->init; $node->append_conf('postgresql.conf', "log_connections =3D on\n"); +# Needed to allow connect_fails to inspect postmaster log: +$node->append_conf('postgresql.conf', "log_min_messages =3D debug2"); $node->start; = $node->safe_psql('postgres', 'CREATE USER test0;'); diff --git a/src/test/modules/oauth_validator/t/001_server.pl b/src/test/m= odules/oauth_validator/t/001_server.pl index d88994abc24..4f035417a40 100644 --- a/src/test/modules/oauth_validator/t/001_server.pl +++ b/src/test/modules/oauth_validator/t/001_server.pl @@ -48,6 +48,8 @@ $node->init; $node->append_conf('postgresql.conf', "log_connections =3D on\n"); $node->append_conf('postgresql.conf', "oauth_validator_libraries =3D 'validator'\n"); +# Needed to allow connect_fails to inspect postmaster log: +$node->append_conf('postgresql.conf', "log_min_messages =3D debug2"); $node->start; = $node->safe_psql('postgres', 'CREATE USER test;'); diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/Post= greSQL/Test/Cluster.pm index 8759ed2cbba..7877cc8d994 100644 --- a/src/test/perl/PostgreSQL/Test/Cluster.pm +++ b/src/test/perl/PostgreSQL/Test/Cluster.pm @@ -2624,7 +2624,12 @@ If this regular expression is set, matches it with = the output generated. = =3Ditem log_unlike =3D> [ qr/prohibited message/ ] = -See C. +See C. CAUTION: use of either option requires that +the server's log_min_messages be at least DEBUG2, and that no other +client backend is launched concurrently. These requirements allow +C to wait to see the postmaster-log report of backend +exit, without which there is a race condition as to whether we will +see the expected backend log output. = =3Dback = @@ -2652,7 +2657,14 @@ sub connect_fails like($stderr, $params{expected_stderr}, "$test_name: matches"); } = - $self->log_check($test_name, $log_location, %params); + if (defined($params{log_like}) or defined($params{log_unlike})) + { + $self->wait_for_log( + qr/DEBUG: (00000: )?client backend.*exited with exit code \d/, + $log_location); + + $self->log_check($test_name, $log_location, %params); + } } = =3Dpod diff --git a/src/test/ssl/t/001_ssltests.pl b/src/test/ssl/t/001_ssltests.= pl index 086abf3b8b3..8b0de2d8e7e 100644 --- a/src/test/ssl/t/001_ssltests.pl +++ b/src/test/ssl/t/001_ssltests.pl @@ -60,6 +60,8 @@ my $common_connstr; note "setting up data directory"; my $node =3D PostgreSQL::Test::Cluster->new('primary'); $node->init; +# Needed to allow connect_fails to inspect postmaster log: +$node->append_conf('postgresql.conf', "log_min_messages =3D debug2"); = # PGHOST is enforced here to set up the node, subsequent connections # will use a dedicated connection string. @@ -807,10 +809,8 @@ $node->connect_fails( expected_stderr =3D> qr/certificate authentication failed for user "anotheruser"/, # certificate authentication should be logged even on failure - # temporarily(?) skip this check due to timing issue - # log_like =3D> - # [qr/connection authenticated: identity=3D"CN=3Dssltestuser" method=3D= cert/], -); + log_like =3D> + [qr/connection authenticated: identity=3D"CN=3Dssltestuser" method=3Dc= ert/],); = # revoked client cert $node->connect_fails( @@ -818,11 +818,10 @@ $node->connect_fails( . sslkey('client-revoked.key'), "certificate authorization fails with revoked client cert", expected_stderr =3D> qr|SSL error: ssl[a-z0-9/]* alert certificate revok= ed|, - # temporarily(?) skip this check due to timing issue - # log_like =3D> [ - # qr{Client certificate verification failed at depth 0: certificate rev= oked}, - # qr{Failed certificate data \(unverified\): subject "/CN=3Dssltestuser= ", serial number 2315134995201656577, issuer "/CN=3DTest CA for PostgreSQL= SSL regression test client certs"}, - # ], + log_like =3D> [ + qr{Client certificate verification failed at depth 0: certificate revok= ed}, + qr{Failed certificate data \(unverified\): subject "/CN=3Dssltestuser",= serial number \d+, issuer "/CN=3DTest CA for PostgreSQL SSL regression te= st client certs"}, + ], # revoked certificates should not authenticate the user log_unlike =3D> [qr/connection authenticated:/],); = @@ -872,24 +871,20 @@ $node->connect_fails( $common_connstr . " " . "sslmode=3Drequire sslcert=3Dssl/client.crt", "intermediate client certificate is missing", expected_stderr =3D> qr/SSL error: tlsv1 alert unknown ca/, - # temporarily(?) skip this check due to timing issue - # log_like =3D> [ - # qr{Client certificate verification failed at depth 0: unable to get l= ocal issuer certificate}, - # qr{Failed certificate data \(unverified\): subject "/CN=3Dssltestuser= ", serial number 2315134995201656576, issuer "/CN=3DTest CA for PostgreSQL= SSL regression test client certs"}, - # ] -); + log_like =3D> [ + qr{Client certificate verification failed at depth 0: unable to get loc= al issuer certificate}, + qr{Failed certificate data \(unverified\): subject "/CN=3Dssltestuser",= serial number \d+, issuer "/CN=3DTest CA for PostgreSQL SSL regression te= st client certs"}, + ]); = $node->connect_fails( "$common_connstr sslmode=3Drequire sslcert=3Dssl/client-long.crt " . sslkey('client-long.key'), "logged client certificate Subjects are truncated if they're too long", expected_stderr =3D> qr/SSL error: tlsv1 alert unknown ca/, - # temporarily(?) skip this check due to timing issue - # log_like =3D> [ - # qr{Client certificate verification failed at depth 0: unable to get l= ocal issuer certificate}, - # qr{Failed certificate data \(unverified\): subject "\.\.\./CN=3Dssl-1= 23456789012345678901234567890123456789012345678901234567890", serial numbe= r 2315418733629425152, issuer "/CN=3DTest CA for PostgreSQL SSL regression= test client certs"}, - # ] -); + log_like =3D> [ + qr{Client certificate verification failed at depth 0: unable to get loc= al issuer certificate}, + qr{Failed certificate data \(unverified\): subject "\.\.\./CN=3Dssl-123= 456789012345678901234567890123456789012345678901234567890", serial number = \d+, issuer "/CN=3DTest CA for PostgreSQL SSL regression test client certs= "}, + ]); = # Use an invalid cafile here so that the next test won't be able to verif= y the # client CA. @@ -904,12 +899,10 @@ $node->connect_fails( "$common_connstr sslmode=3Drequire sslcert=3Dssl/client+client_ca.crt", "intermediate client certificate is untrusted", expected_stderr =3D> qr/SSL error: tlsv1 alert unknown ca/, - # temporarily(?) skip this check due to timing issue - # log_like =3D> [ - # qr{Client certificate verification failed at depth 1: unable to get l= ocal issuer certificate}, - # qr{Failed certificate data \(unverified\): subject "/CN=3DTest CA for= PostgreSQL SSL regression test client certs", serial number 2315134995201= 656577, issuer "/CN=3DTest root CA for PostgreSQL SSL regression test suit= e"}, - # ] -); + log_like =3D> [ + qr{Client certificate verification failed at depth 1: unable to get loc= al issuer certificate}, + qr{Failed certificate data \(unverified\): subject "/CN=3DTest CA for P= ostgreSQL SSL regression test client certs", serial number \d+, issuer "/C= N=3DTest root CA for PostgreSQL SSL regression test suite"}, + ]); = # test server-side CRL directory switch_server_cert( @@ -923,12 +916,10 @@ $node->connect_fails( . sslkey('client-revoked.key'), "certificate authorization fails with revoked client cert with server-si= de CRL directory", expected_stderr =3D> qr|SSL error: ssl[a-z0-9/]* alert certificate revok= ed|, - # temporarily(?) skip this check due to timing issue - # log_like =3D> [ - # qr{Client certificate verification failed at depth 0: certificate rev= oked}, - # qr{Failed certificate data \(unverified\): subject "/CN=3Dssltestuser= ", serial number 2315134995201656577, issuer "/CN=3DTest CA for PostgreSQL= SSL regression test client certs"}, - # ] -); + log_like =3D> [ + qr{Client certificate verification failed at depth 0: certificate revok= ed}, + qr{Failed certificate data \(unverified\): subject "/CN=3Dssltestuser",= serial number \d+, issuer "/CN=3DTest CA for PostgreSQL SSL regression te= st client certs"}, + ]); = # revoked client cert, non-ASCII subject $node->connect_fails( @@ -936,11 +927,9 @@ $node->connect_fails( . sslkey('client-revoked-utf8.key'), "certificate authorization fails with revoked UTF-8 client cert with ser= ver-side CRL directory", expected_stderr =3D> qr|SSL error: ssl[a-z0-9/]* alert certificate revok= ed|, - # temporarily(?) skip this check due to timing issue - # log_like =3D> [ - # qr{Client certificate verification failed at depth 0: certificate rev= oked}, - # qr{Failed certificate data \(unverified\): subject "/CN=3D\\xce\\x9f\= \xce\\xb4\\xcf\\x85\\xcf\\x83\\xcf\\x83\\xce\\xad\\xce\\xb1\\xcf\\x82", se= rial number 2315420958437414144, issuer "/CN=3DTest CA for PostgreSQL SSL = regression test client certs"}, - # ] -); + log_like =3D> [ + qr{Client certificate verification failed at depth 0: certificate revok= ed}, + qr{Failed certificate data \(unverified\): subject "/CN=3D\\xce\\x9f\\x= ce\\xb4\\xcf\\x85\\xcf\\x83\\xcf\\x83\\xce\\xad\\xce\\xb1\\xcf\\x82", seri= al number \d+, issuer "/CN=3DTest CA for PostgreSQL SSL regression test cl= ient certs"}, + ]); = done_testing(); ------- =_aaaaaaaaaa0--