Subject: Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible

From: Noah Misch <[email-masked]>
Date: Tue, 10 Sep 2024 10:27:12 -0700

On Tue, Sep 10, 2024 at 02:29:57PM +0900, Michael Paquier wrote:
> You are adding twelve event points with only 5
> new wait names.  Couldn't it be better to have a one-one mapping
> instead, adding twelve entries in wait_event_names.txt?

No, I think the patch's level of detail is better.  One shouldn't expect the
two ldap_simple_bind_s() calls to have different-enough performance
characteristics to justify exposing that level of detail to the DBA.
ldap_search_s() and InitializeLDAPConnection() differ more, but the DBA mostly
just needs to know the scale of their LDAP responsiveness problem.

(Someday, it might be good to expose the file:line and/or backtrace associated
with a wait, like we do for ereport().  As a way to satisfy rare needs for
more detail, I'd prefer that over giving every pgstat_report_wait_start() a
different name.)

---

From: Robert Haas <[email-masked]>
Date: Tue, 10 Sep 2024 14:51:23 -0400

> more detail, I'd prefer that over giving every pgstat_report_wait_start() a

I think unique names are a good idea. If a user doesn't care about the
difference between sdgjsA and sdjgsB, they can easily ignore the
trailing suffix, and IME, people typically do that without really
stopping to think about it. If on the other hand the two are lumped
together as sdjgs and a user needs to distinguish them, they can't. So
I see unique names as having much more upside than downside.

-- 
Robert Haas
EDB: http://www.enterprisedb.com

---

From: Noah Misch <[email-masked]>
Date: Tue, 10 Sep 2024 13:58:50 -0700

> I see unique names as having much more upside than downside.

I agree a person can ignore the distinction, but that requires the person to
be consuming the raw event list.  It's reasonable to tell your monitoring tool
to give you the top N wait events.  Individual AuthnLdap* events may all miss
the cut even though their aggregate would have made the cut.  Before you know
to teach that monitoring tool to group AuthnLdap* together, it won't show you
any of those names.

I felt commit c789f0f also chose sub-optimally in this respect, particularly
with the DblinkGetConnect/DblinkConnect pair.  I didn't feel strongly enough
to complain at the time, but a rule of "each wait event appears in one
pgstat_report_wait_start()" would be a rule I don't want.  One needs
familiarity with the dblink implementation internals to grasp the
DblinkGetConnect/DblinkConnect distinction, and a plausible refactor of dblink
would make those names cease to fit.  I see this level of fine-grained naming
as making the event name a sort of stable proxy for FILE:LINE.  I'd value
exposing such a proxy, all else being equal, but I don't think wait event
names like AuthLdapBindLdapbinddn/AuthLdapBindUser are the right way.  Wait
event names should be more independent of today's code-level details.

---

From: Michael Paquier <[email-masked]>
Date: Wed, 11 Sep 2024 07:33:31 +0900

> to teach that monitoring tool to group AuthnLdap* together, it won't show you

That's a fair point.  I use a bunch of aggregates with group bys for
any monitoring queries looking for event point patterns.  In my
experience, when dealing with enough connections, patterns show up
anyway even if there is noise because some of the events that I was
looking for are rather short-term, like a sync events interleaving
with locks  storing an average of the events into a secondary table
with some INSERT SELECT.

> event names should be more independent of today's code-level details.

Depends.  I'd rather choose more granularity to know exactly which
part of the code I am dealing with, especially in the case of this
thread where these are embedded around external function calls.  If,
for example, one notices that a stack of pg_stat_activity scans are
complaining about a specific step in the authentication process, it is
going to offer a much better hint than having to guess which part of
the authentication step is slow, like in LDAP.

Wait event additions are also kind of cheap in terms of maintenance in
core, creating a new translation cost.  So I also think there are more
upsides to be wilder here with more points and more granularity.
--
Michael

---

From: Robert Haas <[email-masked]>
Date: Wed, 11 Sep 2024 09:00:33 -0400

On Tue, Sep 10, 2024 at 4:58 PM Noah Misch <[email-masked]> wrote:
> ... a rule of "each wait event appears in one
> pgstat_report_wait_start()" would be a rule I don't want.

As the original committer of the wait event stuff, I intended for the
rule that you do not want to be the actual rule. However, I see that I
didn't spell that out anywhere in the commit message, or the commit
itself.

> I see this level of fine-grained naming

I don't agree with that. One of the most difficult parts of supporting
PostgreSQL, in my experience, is that it's often very difficult to
find out what has gone wrong when a system starts behaving badly. It
is often necessary to ask customers to install a debugger and do stuff
with it, or give them an instrumented build, in order to determine the
root cause of a problem that in some cases is not even particularly
complicated. While needing to refer to specific source code details
may not be a common experience for the typical end user, it is
extremely common for me. This problem commonly arises with error
messages, because we have lots of error messages that are exactly the
same, although thankfully it has become less common due to "could not
find tuple for THINGY %u" no longer being a message that no longer
typically reaches users. But even when someone has a complaint about
an error message and there are multiple instances of that error
message, I know that:

(1) I can ask them to set the error verbosity to verbose. I don't have
that option for wait events.

(2) The primary function of the error message is to be understandable
to the user, which means that it needs to be written in plain English.
The primary function of a wait event is to make it possible to
understand the behavior of the system and troubleshoot problems, and
it becomes much less effective as soon as it starts saying that thing
A and thing B are so similar that nobody will ever care about the
distinction. It is very hard to be certain of that. When somebody
reports that they've got a whole bunch of wait events on some wait
event that nobody has ever complained about before, I want to go look
at the code in that specific place and try to figure out what's
happening. If I have to start imagining possible scenarios based on 2
or more call sites, or if I have to start by getting them to install a
modified build with those properly split apart and trying to reproduce
the problem, it's a lot harder.

In my experience, the number of distinct wait events that a particular
installation experiences is rarely very large. It is probably measured
in dozens. A user who wishes to disregard the distinction between
similarly-named wait events won't find it prohibitively difficult to
look over the list of all the wait events they ever see and decide
which ones they'd like to merge for reporting purposes. But a user who
really needs things separated out and finds that they aren't is simply
out of luck.

---

From: Noah Misch <[email-masked]>
Date: Fri, 13 Sep 2024 07:56:21 -0700

On Wed, Sep 11, 2024 at 09:00:33AM -0400, Robert Haas wrote:
> messages

That is a problem.  Half the time, error verbosity doesn't disambiguate enough
for me, and I need backtrace_functions.  I now find it hard to believe how
long we coped without backtrace_functions.

I withdraw the objection to "each wait event appears in one
pgstat_report_wait_start()".

---

From: Jacob Champion <[email-masked]>
Date: Fri, 1 Nov 2024 14:47:38 -0700

Hi all,

Here's a v4, with a separate wait event for each location. (I could
use some eyes on the specific phrasing I've chosen for each one.)

On Sun, Sep 1, 2024 at 5:10 PM Michael Paquier <[email-masked]> wrote:
> Could it be more transparent to use a "startup" or
> "starting"" state instead that gets also used by pgstat_bestart() in
> the case of the patch where !pre_auth?

Done. (I've used "starting".)

On Mon, Sep 9, 2024 at 10:30 PM Michael Paquier <[email-masked]> wrote:
> A new category would be more adapted.  IPC is not adapted because are
> not waiting for another server process.  Perhaps just use a new
> "Authentication" class, as in "The server is waiting for an
> authentication operation to complete"?

Added a new "Auth" class (to cover both authn and authz during
startup), plus documentation.

On Wed, Sep 11, 2024 at 4:42 PM Michael Paquier <[email-masked]> wrote:
> Setting up twice the structure as the patch proposes is kind of
> a weird concept, but it feels to me that we should split that and set
> the fields in the pre-auth step and ignore the irrelevant ones, then
> complete the rest in a second step.

The more I look at this, the more uneasy I feel about the goal. Best I
can tell, the pre-auth step can't ignore irrelevant fields, because
they may contain junk from the previous owner of the shared memory. So
if we want to optimize, we can only change the second step to skip
fields that were already filled in by the pre-auth step.

That has its own problems: not every backend type uses the pre-auth
step in the current patch. Which means a bunch of backends that don't
benefit from the two-step initialization nevertheless have to either
do two PGSTAT_BEGIN_WRITE_ACTIVITY() dances in a row, or else we
duplicate a bunch of the logic to make sure they maintain the same
efficient code path as before.

Finally, if we're okay with all of that, future maintainers need to be
careful about which fields get copied in the first (preauth) step, the
second step, or both. GSS, for example, can be set up during transport
negotiation (first step) or authentication (second step), so we have
to duplicate the logic there. SSL is currently first-step-only, I
think -- but are we sure we want to hardcode the assumption that cert
auth can't change any of those parameters after the transport has been
established? (I've been brainstorming ways we might use TLS 1.3's
post-handshake CertificateRequest, for example.)

So before I commit to this path, I just want to double-check that all
of the above sounds good and non-controversial. :)

--

In the meantime, is anyone willing and able to commit 0001 and/or 0002?

Thanks!
--Jacob
1:  8f9315949e = 1:  64289b97e5 BackgroundPsql: handle empty query results
2:  7f404f5ee8 ! 2:  18a9531a25 Test::Cluster: let background_psql() work asynchronously
    @@ src/test/perl/PostgreSQL/Test/Cluster.pm: connection.
      
      =cut
     @@ src/test/perl/PostgreSQL/Test/Cluster.pm: sub background_psql
    - 		'-');
    + 		'-XAtq', '-d', $psql_connstr, '-f', '-');
      
      	$params{on_error_stop} = 1 unless defined $params{on_error_stop};
     +	$params{wait} = 1 unless defined $params{wait};
3:  a7a7551d09 ! 3:  c8071f91d8 pgstat: report in earlier with STATE_AUTHENTICATING
    @@ Metadata
     Author: Jacob Champion <[email-masked]>
     
      ## Commit message ##
    -    pgstat: report in earlier with STATE_AUTHENTICATING
    +    pgstat: report in earlier with STATE_STARTING
     
    -    Add pgstat_bestart_pre_auth(), which reports an 'authenticating' state
    -    while waiting for backend initialization and client authentication to
    +    Add pgstat_bestart_pre_auth(), which reports a 'starting' state while
    +    waiting for backend initialization and client authentication to
         complete. Since we hold a transaction open for a good amount of that,
         and some authentication methods call out to external systems, having a
         pg_stat_activity entry helps DBAs debug when things go badly wrong.
     
    + ## doc/src/sgml/monitoring.sgml ##
    +@@ doc/src/sgml/monitoring.sgml: postgres   27093  0.0  0.0  30096  2752 ?        Ss   11:34   0:00 postgres: ser
    +        Current overall state of this backend.
    +        Possible values are:
    +        <itemizedlist>
    ++        <listitem>
    ++         <para>
    ++          <literal>starting</literal>: The backend is in initial startup. Client
    ++          authentication is performed during this phase.
    ++         </para>
    ++        </listitem>
    +         <listitem>
    +         <para>
    +           <literal>active</literal>: The backend is executing a query.
    +
      ## src/backend/utils/activity/backend_status.c ##
     @@ src/backend/utils/activity/backend_status.c: static int	localNumBackends = 0;
      static MemoryContext backendStatusSnapContext;
    @@ src/backend/utils/activity/backend_status.c: pgstat_bestart(void)
      #endif
      
     -	lbeentry.st_state = STATE_UNDEFINED;
    -+	lbeentry.st_state = pre_auth ? STATE_AUTHENTICATING : STATE_UNDEFINED;
    ++	lbeentry.st_state = pre_auth ? STATE_STARTING : STATE_UNDEFINED;
      	lbeentry.st_progress_command = PROGRESS_COMMAND_INVALID;
      	lbeentry.st_progress_command_target = InvalidOid;
      	lbeentry.st_query_id = UINT64CONST(0);
    @@ src/backend/utils/adt/pgstatfuncs.c: pg_stat_get_activity(PG_FUNCTION_ARGS)
      
      			switch (beentry->st_state)
      			{
    -+				case STATE_AUTHENTICATING:
    -+					values[4] = CStringGetTextDatum("authenticating");
    ++				case STATE_STARTING:
    ++					values[4] = CStringGetTextDatum("starting");
     +					break;
      				case STATE_IDLE:
      					values[4] = CStringGetTextDatum("idle");
    @@ src/backend/utils/init/postinit.c: InitPostgres(const char *in_dbname, Oid dboid
     +	pgstat_beinit();
     +
     +	/*
    -+	 * This is a convenient time to sketch in a partial pgstat entry. That way,
    -+	 * if LWLocks or third-party authentication should happen to hang, the DBA
    -+	 * will still be able to see what's going on. (A later call to
    ++	 * This is a convenient time to sketch in a partial pgstat entry. That
    ++	 * way, if LWLocks or third-party authentication should happen to hang,
    ++	 * the DBA will still be able to see what's going on. (A later call to
     +	 * pgstat_bestart() will fill in the rest of the status.)
     +	 */
     +	if (!bootstrap)
    @@ src/include/utils/backend_status.h
      typedef enum BackendState
      {
      	STATE_UNDEFINED,
    -+	STATE_AUTHENTICATING,
    ++	STATE_STARTING,
      	STATE_IDLE,
      	STATE_RUNNING,
      	STATE_IDLEINTRANSACTION,
    @@ src/test/authentication/t/007_injection_points.pl (new)
     +my $psql = $node->background_psql('postgres');
     +$psql->query_safe("SELECT injection_points_attach('init-pre-auth', 'wait')");
     +
    -+# From this point on, all new connections will hang in authentication. Use the
    -+# $psql connection handle for server interaction.
    ++# From this point on, all new connections will hang during startup, just before
    ++# authentication. Use the $psql connection handle for server interaction.
     +my $conn = $node->background_psql('postgres', wait => 0);
     +
     +# Wait for the connection to show up.
    @@ src/test/authentication/t/007_injection_points.pl (new)
     +while (1)
     +{
     +	$pid = $psql->query(
    -+		"SELECT pid FROM pg_stat_activity WHERE state = 'authenticating';");
    ++		"SELECT pid FROM pg_stat_activity WHERE state = 'starting';");
     +	last if $pid ne "";
     +
     +	usleep(500_000);
    @@ src/test/authentication/t/007_injection_points.pl (new)
     +# Make sure the pgstat entry is updated eventually.
     +while (1)
     +{
    -+	my $state = $psql->query(
    -+		"SELECT state FROM pg_stat_activity WHERE pid = $pid;");
    ++	my $state =
    ++	  $psql->query("SELECT state FROM pg_stat_activity WHERE pid = $pid;");
     +	last if $state eq "idle";
     +
     +	note "state for backend $pid is '$state'; waiting for 'idle'...";
4:  5c85c3e0e9 ! 4:  d14b97cb77 WIP: report external auth calls as wait events
    @@ Metadata
     Author: Jacob Champion <[email-masked]>
     
      ## Commit message ##
    -    WIP: report external auth calls as wait events
    +    Report external auth calls as wait events
     
    -    Introduce new WAIT_EVENT_AUTHN_* types for various external
    -    authentication systems, to make it obvious what's going wrong if one of
    -    those systems hangs.
    +    Introduce a new "Auth" wait class for various external authentication
    +    systems, to make it obvious what's going wrong if one of those systems
    +    hangs. Each new wait event is unique in order to more easily pinpoint
    +    problematic locations in the code.
     
    -    TODO:
    -    - don't abuse the IPC wait event group like this
    -    - test
    +    Discussion: https://postgr.es/m/CAOYmi%2B%3D60deN20WDyCoHCiecgivJxr%3D98s7s7-C8SkXwrCfHXg%40mail.gmail.com
    +
    + ## doc/src/sgml/monitoring.sgml ##
    +@@ doc/src/sgml/monitoring.sgml: postgres   27093  0.0  0.0  30096  2752 ?        Ss   11:34   0:00 postgres: ser
    +        see <xref linkend="wait-event-activity-table"/>.
    +       </entry>
    +      </row>
    ++     <row>
    ++      <entry><literal>Auth</literal></entry>
    ++      <entry>The server process is waiting for an external system to
    ++       authenticate and/or authorize the client connection.
    ++       <literal>wait_event</literal> will identify the specific wait point;
    ++       see <xref linkend="wait-event-auth-table"/>.
    ++      </entry>
    ++     </row>
    +      <row>
    +       <entry><literal>BufferPin</literal></entry>
    +       <entry>The server process is waiting for exclusive access to
     
      ## src/backend/libpq/auth.c ##
     @@
    @@ src/backend/libpq/auth.c: pg_GSS_recvauth(Port *port)
      		elog(DEBUG4, "processing received GSS token of length %u",
      			 (unsigned int) gbuf.length);
      
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_GSSAPI);
    ++		pgstat_report_wait_start(WAIT_EVENT_GSSAPI_ACCEPT_SEC_CONTEXT);
      		maj_stat = gss_accept_sec_context(&min_stat,
      										  &port->gss->ctx,
      										  port->gss->cred,
    @@ src/backend/libpq/auth.c: pg_SSPI_recvauth(Port *port)
      	/*
      	 * Acquire a handle to the server credentials.
      	 */
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
    ++	pgstat_report_wait_start(WAIT_EVENT_SSPI_ACQUIRE_CREDENTIALS_HANDLE);
      	r = AcquireCredentialsHandle(NULL,
      								 "negotiate",
      								 SECPKG_CRED_INBOUND,
    @@ src/backend/libpq/auth.c: pg_SSPI_recvauth(Port *port)
      		elog(DEBUG4, "processing received SSPI token of length %u",
      			 (unsigned int) buf.len);
      
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
    ++		pgstat_report_wait_start(WAIT_EVENT_SSPI_ACCEPT_SECURITY_CONTEXT);
      		r = AcceptSecurityContext(&sspicred,
      								  sspictx,
      								  &inbuf,
    @@ src/backend/libpq/auth.c: pg_SSPI_recvauth(Port *port)
      
      	CloseHandle(token);
      
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
    ++	pgstat_report_wait_start(WAIT_EVENT_SSPI_LOOKUP_ACCOUNT_SID);
      	if (!LookupAccountSid(NULL, tokenuser->User.Sid, accountname, &accountnamesize,
      						  domainname, &domainnamesize, &accountnameuse))
      		ereport(ERROR,
    @@ src/backend/libpq/auth.c: pg_SSPI_recvauth(Port *port)
     -											  port->hba->upn_username);
     +		int			status;
     +
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
    ++		pgstat_report_wait_start(WAIT_EVENT_SSPI_MAKE_UPN);
     +		status = pg_SSPI_make_upn(accountname, sizeof(accountname),
     +								  domainname, sizeof(domainname),
     +								  port->hba->upn_username);
    @@ src/backend/libpq/auth.c: CheckPAMAuth(Port *port, const char *user, const char
      		return STATUS_ERROR;
      	}
      
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_PAM);
    ++	pgstat_report_wait_start(WAIT_EVENT_PAM_AUTHENTICATE);
      	retval = pam_authenticate(pamh, 0);
     +	pgstat_report_wait_end();
      
    @@ src/backend/libpq/auth.c: CheckPAMAuth(Port *port, const char *user, const char
      		return pam_no_password ? STATUS_EOF : STATUS_ERROR;
      	}
      
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_PAM);
    ++	pgstat_report_wait_start(WAIT_EVENT_PAM_ACCT_MGMT);
      	retval = pam_acct_mgmt(pamh, 0);
     +	pgstat_report_wait_end();
      
    @@ src/backend/libpq/auth.c: CheckLDAPAuth(Port *port)
      		return STATUS_EOF;		/* client wouldn't send password */
      
     -	if (InitializeLDAPConnection(port, &ldap) == STATUS_ERROR)
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
    ++	pgstat_report_wait_start(WAIT_EVENT_LDAP_INITIALIZE);
     +	r = InitializeLDAPConnection(port, &ldap);
     +	pgstat_report_wait_end();
     +
    @@ src/backend/libpq/auth.c: CheckLDAPAuth(Port *port)
      		 * Bind with a pre-defined username/password (if available) for
      		 * searching. If none is specified, this turns into an anonymous bind.
      		 */
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
    ++		pgstat_report_wait_start(WAIT_EVENT_LDAP_BIND_FOR_SEARCH);
      		r = ldap_simple_bind_s(ldap,
      							   port->hba->ldapbinddn ? port->hba->ldapbinddn : "",
      							   port->hba->ldapbindpasswd ? ldap_password_hook(port->hba->ldapbindpasswd) : "");
    @@ src/backend/libpq/auth.c: CheckLDAPAuth(Port *port)
      
      		search_message = NULL;
     +
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
    ++		pgstat_report_wait_start(WAIT_EVENT_LDAP_SEARCH);
      		r = ldap_search_s(ldap,
      						  port->hba->ldapbasedn,
      						  port->hba->ldapscope,
    @@ src/backend/libpq/auth.c: CheckLDAPAuth(Port *port)
      							port->user_name,
      							port->hba->ldapsuffix ? port->hba->ldapsuffix : "");
      
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
    ++	pgstat_report_wait_start(WAIT_EVENT_LDAP_BIND);
      	r = ldap_simple_bind_s(ldap, fulluser, passwd);
     +	pgstat_report_wait_end();
      
    @@ src/backend/libpq/auth.c: CheckRADIUSAuth(Port *port)
     -												   passwd);
     +		int			ret;
     +
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_RADIUS);
    ++		pgstat_report_wait_start(WAIT_EVENT_RADIUS_TRANSACTION);
     +		ret = PerformRadiusTransaction(lfirst(server),
     +									   lfirst(secrets),
     +									   radiusports ? lfirst(radiusports) : NULL,
    @@ src/backend/libpq/auth.c: CheckRADIUSAuth(Port *port)
      		/*------
      		 * STATUS_OK = Login OK
     
    + ## src/backend/utils/activity/wait_event.c ##
    +@@ src/backend/utils/activity/wait_event.c: static const char *pgstat_get_wait_client(WaitEventClient w);
    + static const char *pgstat_get_wait_ipc(WaitEventIPC w);
    + static const char *pgstat_get_wait_timeout(WaitEventTimeout w);
    + static const char *pgstat_get_wait_io(WaitEventIO w);
    ++static const char *pgstat_get_wait_auth(WaitEventAuth w);
    + 
    + 
    + static uint32 local_my_wait_event_info;
    +@@ src/backend/utils/activity/wait_event.c: pgstat_get_wait_event_type(uint32 wait_event_info)
    + 		case PG_WAIT_INJECTIONPOINT:
    + 			event_type = "InjectionPoint";
    + 			break;
    ++		case PG_WAIT_AUTH:
    ++			event_type = "Auth";
    ++			break;
    + 		default:
    + 			event_type = "???";
    + 			break;
    +@@ src/backend/utils/activity/wait_event.c: pgstat_get_wait_event(uint32 wait_event_info)
    + 				event_name = pgstat_get_wait_io(w);
    + 				break;
    + 			}
    ++		case PG_WAIT_AUTH:
    ++			{
    ++				WaitEventAuth w = (WaitEventAuth) wait_event_info;
    ++
    ++				event_name = pgstat_get_wait_auth(w);
    ++				break;
    ++			}
    + 		default:
    + 			event_name = "unknown wait event";
    + 			break;
    +
      ## src/backend/utils/activity/wait_event_names.txt ##
    -@@ src/backend/utils/activity/wait_event_names.txt: Section: ClassName - WaitEventIPC
    - APPEND_READY	"Waiting for subplan nodes of an <literal>Append</literal> plan node to be ready."
    - ARCHIVE_CLEANUP_COMMAND	"Waiting for <xref linkend="guc-archive-cleanup-command"/> to complete."
    - ARCHIVE_COMMAND	"Waiting for <xref linkend="guc-archive-command"/> to complete."
    -+AUTHN_GSSAPI	"Waiting for a response from a Kerberos server via GSSAPI."
    -+AUTHN_LDAP	"Waiting for a response from an LDAP server."
    -+AUTHN_PAM	"Waiting for a response from the local PAM service."
    -+AUTHN_RADIUS	"Waiting for a response from a RADIUS server."
    -+AUTHN_SSPI	"Waiting for a response from a Windows security provider via SSPI."
    - BACKEND_TERMINATION	"Waiting for the termination of another backend."
    - BACKUP_WAIT_WAL_ARCHIVE	"Waiting for WAL files required for a backup to be successfully archived."
    - BGWORKER_SHUTDOWN	"Waiting for background worker to shut down."
    +@@ src/backend/utils/activity/wait_event_names.txt: XACT_GROUP_UPDATE	"Waiting for the group leader to update transaction status at
    + 
    + ABI_compatibility:
    + 
    ++#
    ++# Wait Events - Auth
    ++#
    ++# Use this category when a process is waiting for a third party to
    ++# authenticate/authorize the user.
    ++#
    ++
    ++Section: ClassName - WaitEventAuth
    ++
    ++GSSAPI_ACCEPT_SEC_CONTEXT	"Waiting for a response from a Kerberos server via GSSAPI."
    ++LDAP_BIND	"Waiting for an LDAP bind operation to authenticate the user."
    ++LDAP_BIND_FOR_SEARCH	"Waiting for an LDAP bind operation to search the directory."
    ++LDAP_INITIALIZE	"Waiting to initialize an LDAP connection."
    ++LDAP_SEARCH	"Waiting for an LDAP search operation to complete."
    ++PAM_ACCT_MGMT	"Waiting for the local PAM service to validate the user account."
    ++PAM_AUTHENTICATE	"Waiting for the local PAM service to authenticate the user."
    ++RADIUS_TRANSACTION	"Waiting for a RADIUS transaction to complete."
    ++SSPI_ACCEPT_SECURITY_CONTEXT	"Waiting for a Windows security provider to accept the client's SSPI token."
    ++SSPI_ACQUIRE_CREDENTIALS_HANDLE	"Waiting for a Windows security provider to acquire server credentials for SSPI."
    ++SSPI_LOOKUP_ACCOUNT_SID	"Waiting for Windows to find the user's account SID."
    ++SSPI_MAKE_UPN	"Waiting for Windows to translate a Kerberos UPN."
    ++
    ++ABI_compatibility:
    ++
    + #
    + # Wait Events - Timeout
    + #
    +
    + ## src/include/utils/wait_event.h ##
    +@@
    + #define PG_WAIT_TIMEOUT				0x09000000U
    + #define PG_WAIT_IO					0x0A000000U
    + #define PG_WAIT_INJECTIONPOINT		0x0B000000U
    ++#define PG_WAIT_AUTH				0x0C000000U
    + 
    + /* enums for wait events */
    + #include "utils/wait_event_types.h"
    +
    + ## src/test/regress/expected/sysviews.out ##
    +@@ src/test/regress/expected/sysviews.out: select type, count(*) > 0 as ok FROM pg_wait_events
    +    type    | ok 
    + -----------+----
    +  Activity  | t
    ++ Auth      | t
    +  BufferPin | t
    +  Client    | t
    +  Extension | t
    +@@ src/test/regress/expected/sysviews.out: select type, count(*) > 0 as ok FROM pg_wait_events
    +  LWLock    | t
    +  Lock      | t
    +  Timeout   | t
    +-(9 rows)
    ++(10 rows)
    + 
    + -- Test that the pg_timezone_names and pg_timezone_abbrevs views are
    + -- more-or-less working.  We can't test their contents in any great detail

---

From: Michael Paquier <[email-masked]>
Date: Wed, 6 Nov 2024 14:48:31 +0900

> Done. (I've used "starting".)

0003 looks much cleaner this way.

> startup), plus documentation.

+PAM_ACCT_MGMT	"Waiting for the local PAM service to validate the user account."
+PAM_AUTHENTICATE	"Waiting for the local PAM service to authenticate the user."

Is "local" required for both?  Perhaps just use "the PAM service".

+SSPI_LOOKUP_ACCOUNT_SID	"Waiting for Windows to find the user's account SID."

We don't document SID in doc/.  So perhaps this should add be "SID
(system identifier)".

+SSPI_MAKE_UPN	"Waiting for Windows to translate a Kerberos UPN."

UPN is mentioned once in doc/ already.  Perhaps this one is OK left
alone..

Except for these tweaks 0004 looks OK.

> post-handshake CertificateRequest, for example.)

The future field maintenance and what one would need to think more
about in the future is a good point.  I still feel slightly uneasy
about the way 0003 is shaped with its new pgstat_bestart_pre_auth(),
but I think that I'm just going to put my hands down on 0003 and see
if I can finish with something I'm a bit more comfortable with.  Let's
see..

> of the above sounds good and non-controversial. :)

The goal of the thread is sound.

I'm OK with 0002 to add the wait parameter to BackgroundPsql and be
able to take some actions until a manual wait_connect().  I'll go do
this one.  Also perhaps 0001 while on it but I am a bit puzzled by the
removal of the three ok() calls in 037_invalid_database.pl.
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Thu, 7 Nov 2024 12:15:33 +0900

> removal of the three ok() calls in 037_invalid_database.pl.

0002 has been done as ba08edb06545 after adding a bit more
documentation that was missing.  0001 as well with 70291a3c66ec.  The
original expectation of 037_invalid_database.pl with the banner data
expected in the output was interesting..

Note that 0003 is lacking an EXTRA_INSTALL in the Makefile of
src/test/authentication/, or the test would fail if doing for example
a `make check` in this path.

The following nit is also required in the script for installcheck, to
skip the test if the module is not installed:
if (!$node->check_extension('injection_points'))
{
    plan skip_all => 'Extension injection_points not installed';
}

See src/test/modules/test_misc/t/005_timeouts.pl as one example.  (I
know, these are tricky to know about..)

007_injection_points.pl is a name too generic as it could apply in a
lot more places, without being linked to injection points.  How about
something like 007_pre_auth.pl?
--
Michael

---

From: Jacob Champion <[email-masked]>
Date: Thu, 7 Nov 2024 09:20:24 -0800

> Is "local" required for both?  Perhaps just use "the PAM service".

Done in v5.

> We don't document SID in doc/.  So perhaps this should add be "SID

I switched to "user's security identifier", which seems to be
search-engine-friendly.

On Wed, Nov 6, 2024 at 7:15 PM Michael Paquier <[email-masked]> wrote:
> documentation that was missing.  0001 as well with 70291a3c66ec.

Thanks!

>     plan skip_all => 'Extension injection_points not installed';

Fixed.

> something like 007_pre_auth.pl?

Renamed.

Thanks!
--Jacob
1:  64289b97e5 < -:  ---------- BackgroundPsql: handle empty query results
2:  18a9531a25 < -:  ---------- Test::Cluster: let background_psql() work asynchronously
3:  c8071f91d8 ! 1:  e755fdccf1 pgstat: report in earlier with STATE_STARTING
    @@ src/test/authentication/Makefile: subdir = src/test/authentication
      top_builddir = ../../..
      include $(top_builddir)/src/Makefile.global
      
    ++EXTRA_INSTALL = src/test/modules/injection_points
    ++
     +export enable_injection_points
     +
      check:
    @@ src/test/authentication/meson.build: tests += {
            't/004_file_inclusion.pl',
            't/005_sspi.pl',
            't/006_login_trigger.pl',
    -+      't/007_injection_points.pl',
    ++      't/007_pre_auth.pl',
          ],
        },
      }
     
    - ## src/test/authentication/t/007_injection_points.pl (new) ##
    + ## src/test/authentication/t/007_pre_auth.pl (new) ##
     @@
     +
     +# Copyright (c) 2021-2024, PostgreSQL Global Development Group
     +
    -+# Tests requiring injection_points functionality, to check on behavior that
    -+# would otherwise race against authentication.
    ++# Tests for connection behavior prior to authentication.
     +
     +use strict;
     +use warnings FATAL => 'all';
    @@ src/test/authentication/t/007_injection_points.pl (new)
     +]);
     +
     +$node->start;
    ++
    ++# Check if the extension injection_points is available, as it may be
    ++# possible that this script is run with installcheck, where the module
    ++# would not be installed by default.
    ++if (!$node->check_extension('injection_points'))
    ++{
    ++	plan skip_all => 'Extension injection_points not installed';
    ++}
    ++
     +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points');
     +
     +# Connect to the server and inject a waitpoint.
4:  d14b97cb77 ! 2:  858e95f996 Report external auth calls as wait events
    @@ src/backend/utils/activity/wait_event_names.txt: XACT_GROUP_UPDATE	"Waiting for
     +LDAP_BIND_FOR_SEARCH	"Waiting for an LDAP bind operation to search the directory."
     +LDAP_INITIALIZE	"Waiting to initialize an LDAP connection."
     +LDAP_SEARCH	"Waiting for an LDAP search operation to complete."
    -+PAM_ACCT_MGMT	"Waiting for the local PAM service to validate the user account."
    -+PAM_AUTHENTICATE	"Waiting for the local PAM service to authenticate the user."
    ++PAM_ACCT_MGMT	"Waiting for the PAM service to validate the user account."
    ++PAM_AUTHENTICATE	"Waiting for the PAM service to authenticate the user."
     +RADIUS_TRANSACTION	"Waiting for a RADIUS transaction to complete."
     +SSPI_ACCEPT_SECURITY_CONTEXT	"Waiting for a Windows security provider to accept the client's SSPI token."
     +SSPI_ACQUIRE_CREDENTIALS_HANDLE	"Waiting for a Windows security provider to acquire server credentials for SSPI."
    -+SSPI_LOOKUP_ACCOUNT_SID	"Waiting for Windows to find the user's account SID."
    ++SSPI_LOOKUP_ACCOUNT_SID	"Waiting for Windows to find the user's security identifier."
     +SSPI_MAKE_UPN	"Waiting for Windows to translate a Kerberos UPN."
     +
     +ABI_compatibility:

---

From: Andres Freund <[email-masked]>
Date: Thu, 7 Nov 2024 13:12:50 -0500

Hi,

On 2024-11-07 09:20:24 -0800, Jacob Champion wrote:
> From e755fdccf16cb4fcd3036e1209291750ffecd261 Mon Sep 17 00:00:00 2001
> From: Jacob Champion <[email-masked]>
> Date: Fri, 3 May 2024 15:54:58 -0700
> Subject: [PATCH v5 1/2] pgstat: report in earlier with STATE_STARTING
> 
> Add pgstat_bestart_pre_auth(), which reports a 'starting' state while
> waiting for backend initialization and client authentication to

I don't understand why the pgstat_bestart()/pgstat_bestart_pre_auth() split
makes sense. The latter is going to redo most of the work that the former
did. What's the point of that?

Why not have a new function that initializes just the missing additional
information? Or for that matter, why not move most of what pgstat_bestart()
does into pgstat_beinit()?

As-is I'm -1 on this patch, it makes something complicated and fragile even
more so.

> From 858e95f996589461e2840047fa35675b6f96e46d Mon Sep 17 00:00:00 2001
> From: Jacob Champion <[email-masked]>
> Date: Fri, 3 May 2024 15:58:23 -0700
> Subject: [PATCH v5 2/2] Report external auth calls as wait events
> 
> Introduce a new "Auth" wait class for various external authentication
> systems, to make it obvious what's going wrong if one of those systems
> hangs. Each new wait event is unique in order to more easily pinpoint
> problematic locations in the code.

This doesn't really seem like it's actually using wait events to describe
waits. The new wait events cover stuff like memory allocations etc, see
e.g. pg_SSPI_make_upn().

I have some sympathy for that, it'd be nice if we had some generic way to
describe what code is doing - but it doesn't really seem good to use wait
events for that. Right now a backend reporting a wait allows to conclude that
a backend isn't running postgres code and busy or blocked outside of postgres
- but that's not true anymore if you have wait event cover generic things like
memory allocations (or even various library functions).

This isn't just pedantry - all the relevant code really needs to be rewritten
to allow the blocking to happen in an interruptible way, otherwise
authentication timeout etc can't realiably work. Once that's done you can
actually define useful wait events too.

Greetings,

Andres Freund

---

From: Jacob Champion <[email-masked]>
Date: Thu, 7 Nov 2024 10:44:25 -0800

> does into pgstat_beinit()?

I talk about that up above [1]. I agree that this is all complicated
and fragile, but at the moment, I think splitting things apart is not
going to reduce the complexity in any way. I'm all ears for a
different approach, though (and it sounds like Michael is taking a
stab at it too).

> waits. The new wait events cover stuff like memory allocations etc, see

I've also asked about the "scope" of the waits in the OP [2]. I can
move them downwards in the stack, if you'd prefer.

All of these are intended to cover parts of the code that can actually
hang, but for things like SSPI I'm just working off of inspection and
Win32 documentation. So if it's not actually true that some of these
call points can hang, let me know and I can remove them. (For the
particular example you called out, I'm just trying to cover both calls
to TranslateName() in a maintainable place. The documentation says
"TranslateName fails if it cannot bind to Active Directory on a domain
controller." which seemed pretty wait-worthy to me.)

> actually define useful wait events too.

I agree that would be amazing! I'm not about to tackle reliable
interrupts for all of the current blocking auth code for v18, though.
I'm just trying to make it observable when we do something that
blocks.

--Jacob

[1] https://www.postgresql.org/message-id/CAOYmi%2BkLzSWrDHZbJg8bWZ94oP_K98mkoEvetgupOBVoy5H_ag%40mail.gmail.com
[2] https://www.postgresql.org/message-id/CAOYmi%2B%3D60deN20WDyCoHCiecgivJxr%3D98s7s7-C8SkXwrCfHXg%40mail.gmail.com

---

From: Andres Freund <[email-masked]>
Date: Thu, 7 Nov 2024 14:41:33 -0500

Hi,

> different approach, though (and it sounds like Michael is taking a

I think the patch should not be merged as-is. It's just too ugly and fragile.

> move them downwards in the stack, if you'd prefer.

Well, right now they're just not actually wait events, so yes, they'd need to
be moved down.

I think it might make more sense to use pgstat_report_activity() or such here,
rather than using wait events to describe something that's not a wait.

> I'm just trying to make it observable when we do something that

Well, with that justification we could end up adding wait events for large
swaths of code that might not actually ever wait.

Greetings,

Andres Freund

---

From: Jacob Champion <[email-masked]>
Date: Thu, 7 Nov 2024 12:11:46 -0800

> I think the patch should not be merged as-is. It's just too ugly and fragile.

Understood; I'm trying to find a way forward, and I'm pointing out
that the alternatives I've tried seem to me to be _more_ fragile.

Are there any items in this list that you disagree with/are less
concerned about?

- the pre-auth step must always initialize the entire pgstat struct
- two-step initialization requires two PGSTAT_BEGIN_WRITE_ACTIVITY()
calls for _every_ backend
- two-step initialization requires us to couple against the order that
authentication information is being filled in (pre-auth, post-auth, or
both)

> rather than using wait events to describe something that's not a wait.

I'm not sure why you're saying these aren't waits. If pam_authenticate
is capable of hanging for hours and bringing down a production system,
is that not a "wait"?

> swaths of code that might not actually ever wait.

If it were hypothetically useful to do so, would that be a problem?
I'm trying not to propose things that aren't actually useful.

--Jacob

---

From: Andres Freund <[email-masked]>
Date: Thu, 7 Nov 2024 16:36:59 -0500

Hi,

> - the pre-auth step must always initialize the entire pgstat struct

Correct. And that has to happen exactly once, not twice.

> calls for _every_ backend

That's fine - PGSTAT_BEGIN_WRITE_ACTIVITY() is *extremely* cheap on the write
side. That's the whole point of of the sequence-lock like mechanism.

> authentication information is being filled in (pre-auth, post-auth, or

Not sure what you mean with this?

> is capable of hanging for hours and bringing down a production system,

It may or may not be. If you increase the iteration count for whatever secret
"hashing" method to be very high, it's not a wait, it's just CPU
use. Similarly, if you have a cpu expensive WHERE clause, that's not a
wait. But if you wait for network IO due to pam using ldap underneath or you
need to read toast values from disk, those are waits.

> I'm trying not to propose things that aren't actually useful.

My point is that you're redefining wait events to be "in some region of code"
and that once you start doing that, there's a lot of other places you could
suddenly use wait events.

But wait events aren't actually suitable for that - they're a *single-depth*
mechanism, which means that if you start waiting, the prior wait event is
lost, and
a) the nested region isn't attributed to the parent while active
b) once the nested wait event is over, the parent isn't reset

Greetings,

Andres Freund

---

From: Jacob Champion <[email-masked]>
Date: Thu, 7 Nov 2024 14:29:18 -0800

> Correct. And that has to happen exactly once, not twice.

What goes wrong if it happens twice?

> side. That's the whole point of of the sequence-lock like mechanism.

Okay, cool. I'll retract that concern.

> Not sure what you mean with this?

In other words: if we split it, people who make changes to the order
that authentication information is determined during startup must know
to keep an eye on this code as well. Whereas with the current
patchset, the layers are decoupled and the order doesn't matter.
Quoting from above:

> If you increase the iteration count for whatever secret
> use.

I don't yet understand why this is a useful distinction to make. I
understand that they are different, but what are the bad consequences
if pg_stat_activity records a CPU busy wait in the same way it records
an I/O wait -- as long as they're not nested?

> b) once the nested wait event is over, the parent isn't reset

I understand that they shouldn't be nested. But as long as they're
not, isn't that fine? And if the concern is that they'll accidentally
get nested, whether in this patch or in the future, can't we just
programmatically assert that we haven't?

Thanks,
--Jacob

---

From: Andres Freund <[email-masked]>
Date: Thu, 7 Nov 2024 17:56:01 -0500

Hi,

> What goes wrong if it happens twice?

Primarily it's architecturally wrong. For no reason that I can see.

It does actually make things harder - what if somebody added a
pgstat_report_activity() somewhere between the call? It would suddenly get
lost after the second "initialization".  Actually, the proposed patch already
has weird, externally visible, consequences - the application name is set,
then suddenly becomes unset, then is set again.

> Okay, cool. I'll retract that concern.

Additionally PGSTAT_BEGIN_WRITE_ACTIVITY() would already happen twice if you
initialize twice...

>   post-handshake CertificateRequest, for example.)

That doesn't seem like a reason to just initialize twice to me. If you have
one initialization step that properly initializes everything to a minimal
default state, you then can have granular functions that set up the user,
database, SSL, GSS information separately.

> an I/O wait -- as long as they're not nested?

Well, first, because you suddenly can't use wait events anymore to find waits.

But more importantly, because of not having nesting, adding one "coarse" "wait
event" means that anyone adding a wait event at a finer grade suddenly needs
to be aware of all the paths that could lead to the execution of the new
code and change all of them to not use the wait event anymore. It imposes a
tax on measuring actual "out of postgres" wait events.

> programmatically assert that we haven't?

One very useful wait event would be for memory allocations that hit the
kernel. Those can take a fairly long time, because they might need to write
dirty buffers to disk before there is enough free memory. Now imagine that we
redefine the system memory allocator (or just postgres') so that all memory
allocations from the kernel use a wait event.  Now suddenly all that code that
uses "coarse" wait events suddenly has a *rare* path - because most of the time
we can carve memory out of a larger OS level memory allocation - where wait
events would be nested.

Greetings,

Andres Freund