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

From: Jacob Champion <[email-masked]>
Date: Thu, 6 Mar 2025 14:25:07 -0800

On Wed, Mar 5, 2025 at 8:08 PM Michael Paquier <[email-masked]> wrote:
> Honestly, I don't see a reason not to introduce that, like in the
> attached.

This new code races against the session timeout. I see this on timer expiration:

    [14:19:55.224](0.000s) # issuing query 34 via background psql:
SELECT state FROM pg_stat_activity WHERE pid = ;
    [14:19:55.228](0.004s) # pump_until: process terminated
unexpectedly when searching for "(?^:(^|\n)background_psql:
QUERY_SEPARATOR 34:\r?\n)" with stream: ""
    process ended prematurely at
/home/jacob/src/postgres/src/test/perl/PostgreSQL/Test/Utils.pm line
439.

Which makes it seem like some sort of crash, IMO. I don't find that as
easily debuggable as the previous log message, which was

    [14:21:33.104](0.001s) # issuing query 32 via background psql:
SELECT pid FROM pg_stat_activity
    #   WHERE state = 'starting' and wait_event = 'init-pre-auth';
    IPC::Run: timeout on timer #1 at
/home/jacob/perl5/lib/perl5/IPC/Run.pm line 3007.

> +  WHERE state = 'starting' and wait_event = 'init-pre-auth';});

Did you have thoughts on expanding the check to backend_type [1]?

> + # Give up.  The output of the last attempt is logged by query(),
> + # so no need to do anything here.
> + return 0;

One of my primary complaints about the poll_query_until()
implementation is that "giving up" in this case means continuing to
run pieces of the test that have no business running after a timeout,
and increasing the log noise after a failure. I'm not sure how loudly
to complain in this particular case, since I know we use it
elsewhere...

Thanks!
--Jacob

[1] https://postgr.es/m/CAOYmi%2BnxNCQcTQE-tQ7Lwpe4cYc1u-yxwEe5kt2AVN%2BDXXVVbQ%40mail.gmail.com

---

From: Michael Paquier <[email-masked]>
Date: Fri, 7 Mar 2025 08:15:38 +0900

> to complain in this particular case, since I know we use it

Indeed.  The existing poll_query_until() is a bit more reliable in
terms of error handling, even with a very low PG_TEST_TIMEOUT_DEFAULT.

A second thing that was bugging me on a second lookup this morning is
how we should handle error cases.  A background psql process depends
on what the caller defines for ON_ERROR_STOP.  In the case of this
test, we're OK to fail immediately because we expect the queries to
always work.  I'm not sure if this is fine by default, especially if
callers of this routine expect to have the same properties as
poll_query_until() in Cluster.pm.  They would not, because a
BackgroundPsql is an entire different object, except if given options
when staring psql to act like that.

I have applied the simplest patch for now, to silence the failures in
the CI, and included your suggestion to add a check on the
backend_type for the extra safety it offers.

I'd like the addition of the poll_query_until() in the long-term, but
I'm really not sure if the semantics would be right this way under a
background psql.  In the auth 007 test, they would be OK, but it could
be surprising if we have other callers that begin relying on it.
--
Michael

---

From: Jacob Champion <[email-masked]>
Date: Thu, 6 Mar 2025 15:39:44 -0800

> backend_type for the extra safety it offers.

Thanks! Initial CI run looks green, so that's a good start.

I've reattached the wait event patches, to get the cfbot back to where it was.

> be surprising if we have other callers that begin relying on it.

Yeah, that API is definitely subtle.

--Jacob

---

From: Andres Freund <[email-masked]>
Date: Fri, 7 Mar 2025 11:38:13 -0500

Hi,

> I've reattached the wait event patches, to get the cfbot back to where it was.

FWIW, I continue to think that this is a misuse of wait events. We shouldn't
use them as a poor man's general purpose tracing framework.

Greetings,

Andres Freund

---

From: Jacob Champion <[email-masked]>
Date: Fri, 7 Mar 2025 09:03:18 -0800

> use them as a poor man's general purpose tracing framework.

Well, okay. That's frustrating.

If I return to the original design, but replace all of the high-level
wait events with calls to pgstat_report_activity(), does that work?

--Jacob

---

From: Andres Freund <[email-masked]>
Date: Fri, 7 Mar 2025 12:25:22 -0500

Hi,

> Well, okay. That's frustrating.

I should have clarified - there are a few that I think are ok, basically the
places where we wrap syscalls, e.g. around the sendto, select and recvfrom in
PerformRadiusTransaction().

OTOH that code is effectively completely broken. Doing a blocking select() is
just a no-go, the code isn't interruptible, breaking authentication
timeout. And using select() means that we theoretically could crash due to an
fd that's above FD_SETSIZE.

Most of the other places I'm not on board with, that's wrapping large amounts
of code in a wait event, which pretty much means we're not waiting.

I think some of the wrapped calls into library code might actually call back
into our code (to receive/send data), and our code then will use wait events
around lower level operations done as part of that.

Which pretty much explains my main issue with this - either the code can't
wait in those function calls, in which case it's wrong to use wait events, or
the code is flat out broken.

It's also IMO quite wrong to do something that can throw an error inside a
wait event, because that means that the wait event will still be reported
during error recovery. Probably not the only place doing so, but it's still
wrong.

> wait events with calls to pgstat_report_activity(), does that work?

It'd be less wrong.

But I really doubt that it's a good idea to encode all kinds of function calls
happening during authentication into something SQL visible. Why stop with
these functions and not just do that for *all* functions in postgres? I mean
it'd not work and slow everything down, but how do you define that line?

Greetings,

Andres Freund

---

From: Jacob Champion <[email-masked]>
Date: Fri, 7 Mar 2025 10:28:16 -0800

> PerformRadiusTransaction().

Okay.

> fd that's above FD_SETSIZE.

I think we're in agreement here; I'm just trying to improve things
incrementally. If someone actually hits the broken case, I think it'd
be helpful for them to see it.

> around lower level operations done as part of that.

That would be a problem, agreed, but I didn't think I'd wrapped any
callback APIs. (Admittedly I have little experience with the SSPI
stuff.) But looking at the wrapped calls in the patch... which are you
suspicious of?

> during error recovery.

Hm, okay. I can change that for the LookupAccountSid case.

> Probably not the only place doing so, but it's still
> wrong.

It's definitely not the only place. :D

> Why stop with
> it'd not work and slow everything down,

(That seems like a good reason not to do it for all functions in
Postgres, no? I hope the slope is not all that slippery in practice.)

> but how do you define that line?

Cost/benefit. In this case, authentication hanging in an unknown place
in PAM and LDAP has caused tangible support problems. I suspect I'd
have gotten complaints if I only focused on those two places, though,
so I expanded it to the other blocking calls I could see.

Thanks,
--Jacob

---

From: Jacob Champion <[email-masked]>
Date: Wed, 12 Mar 2025 15:16:02 -0700

> stuff.) But looking at the wrapped calls in the patch... which are you

I missed PAM_CONV, sorry. I'm worried about the sendAuthRequest()
being done there; it doesn't seem safe to potentially ereport(ERROR)
and longjmp through a PAM call stack? But I'll switch those over to
something safe or else drop that part of the patch.

Thanks,
--Jacob

---

From: Jacob Champion <[email-masked]>
Date: Thu, 13 Mar 2025 09:23:10 -0700

> something safe or else drop that part of the patch.

PAM aside... Michael, what's your level of enthusiasm for the rest of
this patch? I was confidently, embarrassingly wrong about how
CheckPAMAuth worked, and it makes me think I need to put this down and
take a completely new crack at it in 19.

Thanks,
--Jacob

---

From: Andres Freund <[email-masked]>
Date: Thu, 13 Mar 2025 12:56:09 -0400

Hi,

On 2025-03-13 09:23:10 -0700, Jacob Champion wrote:
> > and longjmp through a PAM call stack?

That indeed doesn't seem safe.

I am wondering if PAM is so fundamentally incompatible with handling
interrupts / a non-blocking interface that we have little choice but to
eventually remove it...

> PAM aside... Michael, what's your level of enthusiasm for the rest of this
> patch? I was confidently, embarrassingly wrong about how CheckPAMAuth
> worked, and it makes me think I need to put this down and take a completely
> new crack at it in 19.

FWIW, I continue to think that it's better to invest in making more auth
methods non-blocking, rather than adding wait events for code that could maybe
sometimes wait on different things internally.

Greetings,

Andres Freund

---

From: Jacob Champion <[email-masked]>
Date: Thu, 13 Mar 2025 10:29:49 -0700

> interrupts / a non-blocking interface that we have little choice but to

Given the choice between a usually-working PAM module with known
architectural flaws, and not having PAM at all, I think many users
would rather continue using what's working for them.

> sometimes wait on different things internally.

I think we disagree on the either/or nature of that. If I can get
proof that a certain thing is causing bugs in the wild, then I have
ammunition to fix that thing. Right now there is no visibility, and my
interest in rewriting old authentication methods without bug reports
to motivate that work is pretty low. I'm not willing to sign up for
that at the moment.

(But I do really appreciate the review. I'm just feeling crispy about
the overall result...)

Thanks,
--Jacob

---

From: Andres Freund <[email-masked]>
Date: Thu, 13 Mar 2025 13:56:42 -0400

> would rather continue using what's working for them.

authentication_timeout currently doesn't reliably work while in some auth
methods, nor does pg_terminate_backend() etc. That's IMO is rather bad from a
DOSability perspective.

The fact that some auth methods are broken like that has had a sizable
negative impact on postgres for a long time. Not just when those methods are
used, but also architecturally.

It's e.g. one of the main reasons we need the ugly escalating logic in
postmaster shutdowns to send SIGQUITs and then SIGKILL after a while, because
we don't have a reliable way of terminating backends normally.  This used to
be way worse because historically postgres considered it sane (why, I have no
idea) to ereport() in timeout functions, which then occasionally lead to
backends stuck in malloc locks etc.

> ammunition to fix that thing.

FWIW, I've have repeatedly seen production issues due to authentication
timeout not working for some auth methods.

It's not hard to see why - e.g. a non-resonsive radius server just leaves the
backend hanging in select(). Even though it would get interrupted by signals,
we'll just retry without even checking interrupts / timeouts :(.

> Right now there is no visibility, and my interest in rewriting old
> authentication methods without bug reports to motivate that work is pretty
> low. I'm not willing to sign up for that at the moment.

Fair enough.

> (But I do really appreciate the review. I'm just feeling crispy about

Also fair enough :)

Greetings,

Andres Freund

---

From: Jacob Champion <[email-masked]>
Date: Mon, 17 Mar 2025 10:22:47 -0700

> used, but also architecturally.

Right -- I just don't think end users are going to factor that into
their choice of authentication method. If IT tells you "use this PAM
module", then... that's it.

If we remove PAM, maybe they change authentication methods... or maybe
they just don't ever upgrade Postgres again. My money's on the latter.

--

I looked into switching over to pgstat_report_activity(), but that
wasn't designed to be called in the middle of backend initialization.
It would take more work to make those calls safe/sane when `st_state
== STATE_STARTING`. I plan to mark this patchset as Withdrawn for now.

Thanks all!
--Jacob

---

From: Michael Paquier <[email-masked]>
Date: Fri, 21 Mar 2025 14:53:12 +0900

> == STATE_STARTING`. I plan to mark this patchset as Withdrawn for now.

Okay, fine by me.  I had the impression that it would have been
possible to salvage some of the wait event states, but at least the 
starting state showing up in pg_stat_activity will be able to provide
some information, so it's better than none.  Unfortunately, I don't
have any room until the feature freeze for that.

Outside the stat report activity calls, I've been wondering if we
should add some dynamic tracking of which hba/ident entry a backend
PID is working with.  For example, if we knew the file and the entry
line number, we would know on which auth method this backend is
bumping into.  That maybe of course limited if someone modifies and
reloads the HBA file while a backend is stuck.  Now, these files are
mostly static, and we have system views that provide the contents of
the ident and HBA files as SQL, so with a JOIN..
--
Michael