MIME-Version: 1.0
References: 
 <CAN4CZFPim7hUiyb7daNKQPSZ8CvQRBGkVhbvED7yZi8VktSn4Q@mail.gmail.com>
 <7DB528BA-C7A0-4B23-890C-5332FB35A16E@yesql.se>
 <CAN4CZFNNfhFCQdFWui5HWbQR60eM-cyndZ7YgSv7b5SKxB9C2A@mail.gmail.com>
 <CAOYmi+mDSmh6RNizHRmMAwg4ZP2W=uai3Fr3-wm186NMypf_Pg@mail.gmail.com>
 <CAN4CZFNJftK8NaREYaLi-wqpEz3=crQ=1+3f_XUVji=aOrDSWA@mail.gmail.com>
 <7094F798-8DD1-4974-9A04-10E147B29581@gmail.com>
 <CAOYmi+kjtmRMBdBU3_bGKGDoRSK2AErXbGtHkAjFRapcQNmjhA@mail.gmail.com>
 <CAN4CZFNWBXtF-ML3yzdOvX3QEuUwVo5VrBzyWU3O=y-7SeDstA@mail.gmail.com>
 <15434512-B3FB-4AB3-B6B3-5D85ED0B4BBE@yandex-team.ru>
 <CAN4CZFNscs=hiOkRJYF39r7AD7ef9+MR+O2BQdEtE_2Ajdo5qw@mail.gmail.com>
 <CAOYmi+nVzkoLjzNk_58e0NnUPi9uVXwmurK2QP6CzC2WOpqwbg@mail.gmail.com>
In-Reply-To: 
 <CAOYmi+nVzkoLjzNk_58e0NnUPi9uVXwmurK2QP6CzC2WOpqwbg@mail.gmail.com>
From: Zsolt Parragi <zsolt.parragi@percona.com>
Date: Wed, 4 Mar 2026 20:40:34 +0000
Message-ID: 
 <CAN4CZFPjiUQbKo2q+ovs--AHkjvaE8OJyncB9xu5b+1gp=HHPQ@mail.gmail.com>
Subject: Re: Improve OAuth discovery logging
To: Jacob Champion <jacob.champion@enterprisedb.com>
Cc: Andrey Borodin <x4mmm@yandex-team.ru>, Chao Li <li.evan.chao@gmail.com>,
	Daniel Gustafsson <daniel@yesql.se>,
 PostgreSQL Hackers <pgsql-hackers@postgresql.org>,
	Michael Paquier <michael@paquier.xyz>
Content-Type: text/plain; charset="UTF-8"
Archived-At: 
 <https://www.postgresql.org/message-id/CAN4CZFPjiUQbKo2q%2Bovs--AHkjvaE8OJyncB9xu5b%2B1gp%3DHHPQ%40mail.gmail.com>
Precedence: bulk

> Cirrus seems to have noticed an intermittent failure [1]; what's that about?

Looks like we have some out of order logging, because of the multiple
backends involved.

DISCOVERY 2026-02-27 20:11:12.104 UTC postmaster[43175] DEBUG:  forked
new client backend, pid=43267 socket=7
DISCOVERY 2026-02-27 20:11:12.118 UTC client backend[43267] [unknown]
LOG:  connection received: host=[local]
2026-02-27 20:11:12.179 UTC postmaster[43175] DEBUG:  assigned pm
child slot 3 for client backend
2026-02-27 20:11:12.179 UTC postmaster[43175] DEBUG:  forked new
client backend, pid=43281 socket=7

LOGIN     2026-02-27 20:11:12.179 UTC client backend[43281] [unknown]
LOG:  connection received: host=[local]
LOGIN     2026-02-27 20:11:12.180 UTC client backend[43281] [unknown]
LOG:  oauth_validator: token="9243959234", role="test"
LOGIN     2026-02-27 20:11:12.180 UTC client backend[43281] [unknown]
LOG:  oauth_validator: issuer="http://127.0.0.1:44122", scope="openid
postgres"
LOGIN     2026-02-27 20:11:12.180 UTC client backend[43281] [unknown]
LOG:  connection authenticated: identity="test" method=oauth
(/tmp/cirrus-ci-build/build/testrun/oauth_validator/001_server/data/t_001_server_primary_data/pgdata/pg_hba.conf:2)
LOGIN     2026-02-27 20:11:12.180 UTC client backend[43281] [unknown]
LOG:  connection authorized: user=test database=postgres
application_name=001_server.pl
LOGIN     2026-02-27 20:11:12.180 UTC client backend[43281]
001_server.pl LOG:  connection ready: setup total=1.804 ms, fork=0.424
ms, authentication=0.287 ms
LOGIN     2026-02-27 20:11:12.181 UTC client backend[43281]
001_server.pl LOG:  statement: SELECT $$connected with user=test
dbname=postgres oauth_issuer=http://127.0.0.1:44122
oauth_client_id=f02c6361-0635$$

... we read the log around this part ...

DISCOVERY 2026-02-27 20:11:12.189 UTC client backend[43267] [unknown]
DEBUG:  OAuth issuer discovery requested
2026-02-27 20:11:12.190 UTC postmaster[43175] DEBUG:  releasing pm child slot 1
DISCOVERY 2026-02-27 20:11:12.190 UTC postmaster[43175] DEBUG:  client
backend (PID 43267) exited with exit code 0

So it's a scheduling issue, since we log the "oauth discovery
requested" after we already sent the issuer info to the client, so the
other connection attempt can already be in progress (at least with
simple setups like this test)

Also related that connect_fails uses wait_for_log, noticing log
messages that appear later, while connect_ok simply checks the logs at
that moment.

I'm not sure which solution is better for this: removing the check for
this message from the test or modifying connect_ok to wait for all
backends that started since the connection attempt to finish?
Modifying it seems the better choice to me, but that is also a separate change.