Horton

Thread

Commits

  1. Fix race condition in TAP test 007_pre_auth

  2. Split pgstat_bestart() into three different routines

  3. backport: Extend background_psql() to be able to start asynchronously

  4. backport: Improve handling of empty query results in BackgroundPsql

  5. Improve handling of empty query results in BackgroundPsql::query()

  6. Extend Cluster.pm's background_psql() to be able to start asynchronously

  7. dblink: Replace WAIT_EVENT_EXTENSION with custom wait events

  1. [PATCH] pg_stat_activity: make slow/hanging authentication more visible

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-05-06T21:23:38Z

    Hi all,

Recently I dealt with a server where PAM had hung a connection
indefinitely, suppressing our authentication timeout and preventing a
clean shutdown. Worse, the xmin that was pinned by the opening
transaction cascaded to replicas and started messing things up
downstream.

The DBAs didn't know what was going on, because pg_stat_activity
doesn't report the authenticating connection or its open transaction.
It just looked like a Postgres bug. And while talking about it with
Euler, he mentioned he'd seen similar "invisible" hangs with
misbehaving LDAP deployments. I think we can do better to show DBAs
what's happening.

0001, attached, changes InitPostgres() to report a nearly-complete
pgstat entry before entering client authentication, then fills it in
the rest of the way once we know who the user is. Here's a sample
entry for a client that's hung during a SCRAM exchange:

    =# select * from pg_stat_activity where state = 'authenticating';
    -[ RECORD 1 ]----+------------------------------
    datid            |
    datname          |
    pid              | 745662
    leader_pid       |
    usesysid         |
    usename          |
    application_name |
    client_addr      | 127.0.0.1
    client_hostname  |
    client_port      | 38304
    backend_start    | 2024-05-06 11:25:23.905923-07
    xact_start       |
    query_start      |
    state_change     |
    wait_event_type  | Client
    wait_event       | ClientRead
    state            | authenticating
    backend_xid      |
    backend_xmin     | 784
    query_id         |
    query            |
    backend_type     | client backend

0002 goes even further, and adds wait events for various forms of
external authentication, but it's not fully baked. The intent is for a
DBA to be able to see when a bunch of connections are piling up
waiting for PAM/Kerberos/whatever. (I'm also motivated by my OAuth
patchset, where there's a server-side plugin that we have no control
over, and we'd want to be able to correctly point fingers at it if
things go wrong.)

= Open Issues, Idle Thoughts =

Maybe it's wishful thinking, but it'd be cool if a misbehaving
authentication exchange did not impact replicas in any way. Is there a
way to make that opening transaction lighterweight?

0001 may be a little too much code. There are only two parts of
pgstat_bestart() that need to be modified: omit the user ID, and fill
in the state as 'authenticating' rather than unknown. I could just add
the `pre_auth` boolean to the signature of pgstat_bestart() directly,
if we don't mind adjusting all the call sites. We could also avoid
changing the signature entirely, and just assume that we're
authenticating if SessionUserId isn't set. That felt like a little too
much global magic to me, though.

Would anyone like me to be more aggressive, and create a pgstat entry
as soon as we have the opening transaction? Or... as soon as a
connection is made?

0002 is abusing the "IPC" wait event class. If the general idea seems
okay, maybe we could add an "External" class that encompasses the
general idea of "it's not our fault, it's someone else's"?

I had trouble deciding how granular to make the areas that are covered
by the new wait events. Ideally they would kick in only when we call
out to an external system, but for some authentication types, that's a
lot of calls to wrap. On the other extreme, we don't want to go too
high in the call stack and accidentally nest wait events (such as
those generated during pq_getmessage()). What I have now is not very
principled.

I haven't decided how to test these patches. Seems like a potential
use case for injection points, but I think I'd need to preload an
injection library rather than using the existing extension. Does that
seem like an okay way to go?

Thanks,
--Jacob

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

    Noah Misch <noah@leadboat.com> — 2024-06-30T17:48:12Z

    On Mon, May 06, 2024 at 02:23:38PM -0700, Jacob Champion wrote:
>     =# select * from pg_stat_activity where state = 'authenticating';
>     -[ RECORD 1 ]----+------------------------------
>     datid            |
>     datname          |
>     pid              | 745662
>     leader_pid       |
>     usesysid         |
>     usename          |
>     application_name |
>     client_addr      | 127.0.0.1
>     client_hostname  |
>     client_port      | 38304
>     backend_start    | 2024-05-06 11:25:23.905923-07
>     xact_start       |
>     query_start      |
>     state_change     |
>     wait_event_type  | Client
>     wait_event       | ClientRead
>     state            | authenticating
>     backend_xid      |
>     backend_xmin     | 784
>     query_id         |
>     query            |
>     backend_type     | client backend

That looks like a reasonable user experience.  Is any field newly-nullable?

> = Open Issues, Idle Thoughts =
> 
> Maybe it's wishful thinking, but it'd be cool if a misbehaving
> authentication exchange did not impact replicas in any way. Is there a
> way to make that opening transaction lighterweight?

You could release the xmin before calling PAM or LDAP.  If you've copied all
relevant catalog content to local memory, that's fine to do.  That said, it
may be more fruitful to arrange for authentication timeout to cut through PAM
etc.  Hanging connection slots hurt even if they lack an xmin.  I assume it
takes an immediate shutdown to fix them?

> Would anyone like me to be more aggressive, and create a pgstat entry
> as soon as we have the opening transaction? Or... as soon as a
> connection is made?

All else being equal, I'd like backends to have one before taking any lmgr
lock or snapshot.

> I haven't decided how to test these patches. Seems like a potential
> use case for injection points, but I think I'd need to preload an
> injection library rather than using the existing extension. Does that
> seem like an okay way to go?

Yes.

Thanks,
nm

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-07-08T21:09:21Z

    On Sun, Jun 30, 2024 at 10:48 AM Noah Misch <noah@leadboat.com> wrote:
> That looks like a reasonable user experience.  Is any field newly-nullable?

Technically I think the answer is no, since backends such as walwriter
already have null database and user fields. It's new for a client
backend to have nulls there, though.

> That said, it
> may be more fruitful to arrange for authentication timeout to cut through PAM
> etc.

That seems mostly out of our hands -- the misbehaving modules are free
to ignore our signals (and do). Is there another way to force the
issue?

> Hanging connection slots hurt even if they lack an xmin.

Oh, would releasing the xmin not really move the needle, then?

> I assume it
> takes an immediate shutdown to fix them?

That's my understanding, yeah.

> > Would anyone like me to be more aggressive, and create a pgstat entry
> > as soon as we have the opening transaction? Or... as soon as a
> > connection is made?
>
> All else being equal, I'd like backends to have one before taking any lmgr
> lock or snapshot.

I can look at this for the next patchset version.

> > I haven't decided how to test these patches. Seems like a potential
> > use case for injection points, but I think I'd need to preload an
> > injection library rather than using the existing extension. Does that
> > seem like an okay way to go?
>
> Yes.

I misunderstood how injection points worked. No preload module needed,
so v2 adds a waitpoint and a test along with a couple of needed tweaks
to BackgroundPsql. I think 0001 should probably be applied
independently.

Thanks,
--Jacob

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

    Noah Misch <noah@leadboat.com> — 2024-07-09T00:04:01Z

    On Mon, Jul 08, 2024 at 02:09:21PM -0700, Jacob Champion wrote:
> On Sun, Jun 30, 2024 at 10:48 AM Noah Misch <noah@leadboat.com> wrote:
> > That said, it
> > may be more fruitful to arrange for authentication timeout to cut through PAM
> > etc.
> 
> That seems mostly out of our hands -- the misbehaving modules are free
> to ignore our signals (and do). Is there another way to force the
> issue?

Two ways at least (neither of them cheap):
- Invoke PAM in a subprocess, and SIGKILL that process if needed.
- Modify the module to be interruptible.

> > Hanging connection slots hurt even if they lack an xmin.
> 
> Oh, would releasing the xmin not really move the needle, then?

It still moves the needle.

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-08-29T20:44:01Z

    On Sun, Jun 30, 2024 at 10:48 AM Noah Misch <noah@leadboat.com> wrote:v
> > Would anyone like me to be more aggressive, and create a pgstat entry
> > as soon as we have the opening transaction? Or... as soon as a
> > connection is made?
>
> All else being equal, I'd like backends to have one before taking any lmgr
> lock or snapshot.

v3-0003 pushes the pgstat creation as far back as I felt comfortable,
right after the PGPROC registration by InitProcessPhase2(). That
function does lock the ProcArray, but if it gets held forever due to
some bug, you won't be able to use pg_stat_activity to debug it
anyway. And with this ordering, pg_stat_get_activity() will be able to
retrieve the proc entry by PID without a race.

This approach ends up registering an early entry for more cases than
the original patchset. For example, autovacuum and other background
workers will now briefly get their own "authenticating" state, which
seems like it could potentially confuse people. Should I rename the
state, or am I overthinking it?

> You could release the xmin before calling PAM or LDAP.  If you've copied all
> relevant catalog content to local memory, that's fine to do.

I played with the xmin problem a little bit, but I've shelved it for
now. There's probably a way to do that safely; I just don't understand
enough about the invariants to do it. For example, there's a comment
later on that says

     * We established a catalog snapshot while reading pg_authid and/or
     * pg_database;

and I'm a little nervous about invalidating the snapshot halfway
through that process. Even if PAM and LDAP don't rely on pg_authid or
other shared catalogs today, shouldn't they be allowed to in the
future, without being coupled to InitPostgres implementation order?
And I don't think we can move the pg_database checks before
authentication.

As for the other patches, I'll ping Andrew about 0001, and 0004
remains in its original WIP state. Anyone excited about that wait
event idea?

Thanks!
--Jacob

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

    Andrew Dunstan <andrew@dunslane.net> — 2024-08-30T20:10:32Z

    On 2024-08-29 Th 4:44 PM, Jacob Champion wrote:
> As for the other patches, I'll ping Andrew about 0001,


Patch 0001 looks sane to me.


cheers


andrew

--
Andrew Dunstan
EDB:https://www.enterprisedb.com

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

    Michael Paquier <michael@paquier.xyz> — 2024-09-02T00:10:26Z

    On Fri, Aug 30, 2024 at 04:10:32PM -0400, Andrew Dunstan wrote:
> 
> On 2024-08-29 Th 4:44 PM, Jacob Champion wrote:
> > As for the other patches, I'll ping Andrew about 0001,
> 
> 
> Patch 0001 looks sane to me.

So does 0002 to me.  I'm not much a fan of the addition of
pgstat_bestart_pre_auth(), which is just a shortcut to set a different
state in the backend entry to tell that it is authenticating.  Is
authenticating the term for this state of the process startups,
actually?  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?

The addition of the new wait event states in 0004 is a good idea,
indeed, and these can be seen in pg_stat_activity once we get out of
PGSTAT_END_WRITE_ACTIVITY() (err.. Right?).
--
Michael

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-09-03T21:47:57Z

    On Sun, Sep 1, 2024 at 5:10 PM Michael Paquier <michael@paquier.xyz> wrote:
> On Fri, Aug 30, 2024 at 04:10:32PM -0400, Andrew Dunstan wrote:
> > Patch 0001 looks sane to me.
> So does 0002 to me.

Thanks both!

> I'm not much a fan of the addition of
> pgstat_bestart_pre_auth(), which is just a shortcut to set a different
> state in the backend entry to tell that it is authenticating.  Is
> authenticating the term for this state of the process startups,
> actually?  Could it be more transparent to use a "startup" or
> "starting"" state instead

Yeah, I think I should rename that. Especially if we adopt new wait
states to make it obvious where we're stuck.

"startup", "starting", "initializing", "connecting"...?

> that gets also used by pgstat_bestart() in
> the case of the patch where !pre_auth?

To clarify, do you want me to just add the new boolean directly to
pgstat_bestart()'s parameter list?

> The addition of the new wait event states in 0004 is a good idea,
> indeed,

Thanks! Any thoughts on the two open questions for it?:
1) Should we add a new wait event class rather than reusing IPC?
2) Is the level at which I've inserted calls to
pgstat_report_wait_start()/_end() sane and maintainable?

> and these can be seen in pg_stat_activity once we get out of
> PGSTAT_END_WRITE_ACTIVITY() (err.. Right?).

It doesn't look like pgstat_report_wait_start() uses that machinery.

--Jacob

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

    Michael Paquier <michael@paquier.xyz> — 2024-09-10T05:29:57Z

    On Tue, Sep 03, 2024 at 02:47:57PM -0700, Jacob Champion wrote:
> On Sun, Sep 1, 2024 at 5:10 PM Michael Paquier <michael@paquier.xyz> wrote:
>> that gets also used by pgstat_bestart() in
>> the case of the patch where !pre_auth?
> 
> To clarify, do you want me to just add the new boolean directly to
> pgstat_bestart()'s parameter list?

No.  My question was about splitting pgstat_bestart() and
pgstat_bestart_pre_auth() in a cleaner way, because authenticated
connections finish by calling both, meaning that we do twice the same
setup for backend entries depending on the authentication path taken.
That seems like a waste.

>> The addition of the new wait event states in 0004 is a good idea,
>> indeed,
> 
> Thanks! Any thoughts on the two open questions for it?:
> 1) Should we add a new wait event class rather than reusing IPC?

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"?

> 2) Is the level at which I've inserted calls to
> pgstat_report_wait_start()/_end() sane and maintainable?

These don't worry me.  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?

I am not really on board with the test based on injection points
proposed, though.  It checks that the "authenticating" flag is set in
pg_stat_activity, but it does nothing else.  That seems limited.  Or
are you planning for more?
--
Michael

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

    Noah Misch <noah@leadboat.com> — 2024-09-10T17:27:12Z

    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.)

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

    Robert Haas <robertmhaas@gmail.com> — 2024-09-10T18:51:23Z

    On Tue, Sep 10, 2024 at 1:27 PM Noah Misch <noah@leadboat.com> wrote:
> 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.)

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

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

    Noah Misch <noah@leadboat.com> — 2024-09-10T20:58:50Z

    On Tue, Sep 10, 2024 at 02:51:23PM -0400, Robert Haas wrote:
> On Tue, Sep 10, 2024 at 1:27 PM Noah Misch <noah@leadboat.com> wrote:
> > 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.)
> 
> 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.

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.

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

    Michael Paquier <michael@paquier.xyz> — 2024-09-10T22:33:31Z

    On Tue, Sep 10, 2024 at 01:58:50PM -0700, Noah Misch wrote:
> On Tue, Sep 10, 2024 at 02:51:23PM -0400, Robert Haas wrote:
>> 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.
> 
> 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.

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.

> 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.

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

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

    Robert Haas <robertmhaas@gmail.com> — 2024-09-11T13:00:33Z

    On Tue, Sep 10, 2024 at 4:58 PM Noah Misch <noah@leadboat.com> 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
> 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.

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.

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-09-11T21:29:49Z

    On Mon, Sep 9, 2024 at 10:30 PM Michael Paquier <michael@paquier.xyz> wrote:
> No.  My question was about splitting pgstat_bestart() and
> pgstat_bestart_pre_auth() in a cleaner way, because authenticated
> connections finish by calling both, meaning that we do twice the same
> setup for backend entries depending on the authentication path taken.
> That seems like a waste.

I can try to separate them out. I'm a little wary of messing with the
CRITICAL_SECTION guarantees, though. I thought the idea was that you
filled in the entire struct to prevent tearing. (If I've misunderstood
that, please let me know :D)

> Perhaps just use a new
> "Authentication" class, as in "The server is waiting for an
> authentication operation to complete"?

Sounds good.

> Couldn't it be better to have a one-one mapping
> instead, adding twelve entries in wait_event_names.txt?

(I have no strong opinions on this myself, but while the debate is
ongoing, I'll work on a version of the patch with more detailed wait
events. It's easy to collapse them again if that gets the most votes.)

> I am not really on board with the test based on injection points
> proposed, though.  It checks that the "authenticating" flag is set in
> pg_stat_activity, but it does nothing else.  That seems limited.  Or
> are you planning for more?

I can test for specific contents of the entry, if you'd like. My
primary goal was to test that an entry shows up if that part of the
code hangs. I think a regression would otherwise go completely
unnoticed.

Thanks!
--Jacob

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

    Michael Paquier <michael@paquier.xyz> — 2024-09-11T23:42:25Z

    On Wed, Sep 11, 2024 at 02:29:49PM -0700, Jacob Champion wrote:
> On Mon, Sep 9, 2024 at 10:30 PM Michael Paquier <michael@paquier.xyz> wrote:
>> No.  My question was about splitting pgstat_bestart() and
>> pgstat_bestart_pre_auth() in a cleaner way, because authenticated
>> connections finish by calling both, meaning that we do twice the same
>> setup for backend entries depending on the authentication path taken.
>> That seems like a waste.
> 
> I can try to separate them out. I'm a little wary of messing with the
> CRITICAL_SECTION guarantees, though. I thought the idea was that you
> filled in the entire struct to prevent tearing. (If I've misunderstood
> that, please let me know :D)

Hm, yeah.  We surely should be careful about the consequences of that.
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.  We are going to do that anyway if
we want to be able to have backend entries earlier in the
authentication phase.

>> Couldn't it be better to have a one-one mapping
>> instead, adding twelve entries in wait_event_names.txt?
> 
> (I have no strong opinions on this myself, but while the debate is
> ongoing, I'll work on a version of the patch with more detailed wait
> events. It's easy to collapse them again if that gets the most votes.)

Thanks.  Robert is arguing upthread about more granularity, which is
also what I understand is the original intention of the wait events.
Noah has a different view.  Let's see where it goes but I've given my
opinion.

> I can test for specific contents of the entry, if you'd like. My
> primary goal was to test that an entry shows up if that part of the
> code hangs. I think a regression would otherwise go completely
> unnoticed.

Perhaps that would be useful, not sure.  Based on my first
impressions, I'd tend to say no to these extra test cycles, but I'm
okay to be proved wrong, as well.
--
Michael

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

    Noah Misch <noah@leadboat.com> — 2024-09-13T14:56:21Z

    On Wed, Sep 11, 2024 at 09:00:33AM -0400, Robert Haas wrote:
> On Tue, Sep 10, 2024 at 4:58 PM Noah Misch <noah@leadboat.com> 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
> > 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.
> 
> 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

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()".

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-11-01T21:47:38Z

    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 <michael@paquier.xyz> 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 <michael@paquier.xyz> 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 <michael@paquier.xyz> 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

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

    Michael Paquier <michael@paquier.xyz> — 2024-11-06T05:48:31Z

    On Fri, Nov 01, 2024 at 02:47:38PM -0700, Jacob Champion wrote:
> On Sun, Sep 1, 2024 at 5:10 PM Michael Paquier <michael@paquier.xyz> 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".)

0003 looks much cleaner this way.

> Added a new "Auth" class (to cover both authn and authz during
> 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.

> 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.)

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..

> So before I commit to this path, I just want to double-check that all
> 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

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

    Michael Paquier <michael@paquier.xyz> — 2024-11-07T03:15:33Z

    On Wed, Nov 06, 2024 at 02:48:31PM +0900, Michael Paquier wrote:
> 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.

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-11-07T17:20:24Z

    On Tue, Nov 5, 2024 at 9:48 PM Michael Paquier <michael@paquier.xyz> wrote:
> +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".

Done in v5.

> +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)".

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 <michael@paquier.xyz> wrote:
> 0002 has been done as ba08edb06545 after adding a bit more
> documentation that was missing.  0001 as well with 70291a3c66ec.

Thanks!

> 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';
> }

Fixed.

> 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?

Renamed.

Thanks!
--Jacob

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

    Andres Freund <andres@anarazel.de> — 2024-11-07T18:12:50Z

    Hi,

On 2024-11-07 09:20:24 -0800, Jacob Champion wrote:
> From e755fdccf16cb4fcd3036e1209291750ffecd261 Mon Sep 17 00:00:00 2001
> From: Jacob Champion <jacob.champion@enterprisedb.com>
> 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
> 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.

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 <jacob.champion@enterprisedb.com>
> 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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-11-07T18:44:25Z

    On Thu, Nov 7, 2024 at 10:12 AM Andres Freund <andres@anarazel.de> wrote:
> 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()?

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).

> 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'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.)

> 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.

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

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

    Andres Freund <andres@anarazel.de> — 2024-11-07T19:41:33Z

    Hi,

On 2024-11-07 10:44:25 -0800, Jacob Champion wrote:
> On Thu, Nov 7, 2024 at 10:12 AM Andres Freund <andres@anarazel.de> wrote:
> > 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()?
> 
> 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).

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


> > 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'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.

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.


> > 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.
> 
> 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.

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-11-07T20:11:46Z

    On Thu, Nov 7, 2024 at 11:41 AM Andres Freund <andres@anarazel.de> wrote:
> 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)

> 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 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"?

> > 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.
>
> Well, with that justification we could end up adding wait events for large
> 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

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

    Andres Freund <andres@anarazel.de> — 2024-11-07T21:36:59Z

    Hi,

On 2024-11-07 12:11:46 -0800, Jacob Champion wrote:
> On Thu, Nov 7, 2024 at 11:41 AM Andres Freund <andres@anarazel.de> wrote:
> > 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

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


> - two-step initialization requires two PGSTAT_BEGIN_WRITE_ACTIVITY()
> 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.


> - two-step initialization requires us to couple against the order that
> authentication information is being filled in (pre-auth, post-auth, or
> both)

Not sure what you mean with this?


> > 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 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"?

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 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.
> >
> > Well, with that justification we could end up adding wait events for large
> > 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.

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-11-07T22:29:18Z

    On Thu, Nov 7, 2024 at 1:37 PM Andres Freund <andres@anarazel.de> wrote:
> > - the pre-auth step must always initialize the entire pgstat struct
>
> Correct. And that has to happen exactly once, not twice.

What goes wrong if it happens twice?

> > - two-step initialization requires two PGSTAT_BEGIN_WRITE_ACTIVITY()
> > 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.

Okay, cool. I'll retract that concern.

> > - two-step initialization requires us to couple against the order that
> > authentication information is being filled in (pre-auth, post-auth, or
> > both)
>
> 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:

  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.)

> 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.

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?

> 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

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

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

    Andres Freund <andres@anarazel.de> — 2024-11-07T22:56:01Z

    Hi,

On 2024-11-07 14:29:18 -0800, Jacob Champion wrote:
> On Thu, Nov 7, 2024 at 1:37 PM Andres Freund <andres@anarazel.de> wrote:
> > > - the pre-auth step must always initialize the entire pgstat struct
> >
> > Correct. And that has to happen exactly once, not twice.
> 
> 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.


> > > - two-step initialization requires two PGSTAT_BEGIN_WRITE_ACTIVITY()
> > > 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.
> 
> Okay, cool. I'll retract that concern.

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


> > > - two-step initialization requires us to couple against the order that
> > > authentication information is being filled in (pre-auth, post-auth, or
> > > both)
> >
> > 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:
> 
>   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.)

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.



> > 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.
> 
> 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?

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.


> > 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
> 
> 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?

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-11-08T00:38:45Z

    On Thu, Nov 7, 2024 at 2:56 PM Andres Freund <andres@anarazel.de> wrote:
> 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.

Oh... I think that alone is enough to change my mind; I neglected the
effects of that little pgstat_report_appname() stinger...

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

Sure. I was just trying not to introduce that to _all_ backend code
paths, but it sounds like that's not a concern. (Plus, it turns out to
be four calls, due again to the application_name reporting...)

> 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.

I will start work on that then (unless Michael has already beaten me to it?).

> 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.
>
> 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.

Okay, that makes a lot of sense. I will plumb these down as far as I can.

Thanks very much!

--Jacob

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-11-09T00:23:41Z

    On Thu, Nov 7, 2024 at 4:38 PM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
> Oh... I think that alone is enough to change my mind; I neglected the
> effects of that little pgstat_report_appname() stinger...

(Note that application_name is not yet set at the site of the first
call, so I think the set-unset-set can't happen after all -- but I
didn't realize that before a lot of digging, which is further evidence
that I need to simplify...)

> I will plumb these down as far as I can.

While I work on breaking pgstat_bestart() apart, here is a v6 which
pushes down the "coarse" wait events. No changes to 0001 yet.

I violated the "one event name per call site" rule with
TranslateName(). The call pattern there is "call once to figure out
the buffer length, then call again to fill it in", and IMO that didn't
deserve differentiation. But if anyone objects, I'm happy to change it
(and I'd appreciate some name suggestions in that case).

While I was breaking apart the LDAP events, I noticed that
ldap_unbind() does a lot more than just dropping the connection, so
I've refactored things a bit more in order to wrap all those calls.
That is done separately in 0003, which I will fold into 0002 once I
have confirmation that it's not controversial to anyone.

Thanks!
--Jacob

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2024-11-11T23:17:44Z

    On Fri, Nov 8, 2024 at 4:23 PM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
> While I work on breaking pgstat_bestart() apart, here is a v6 which
> pushes down the "coarse" wait events. No changes to 0001 yet.

v7 rewrites 0001 by splitting pgstat_bestart() into three phases.
(0002-3 are unchanged.)

1. pgstat_bestart_initial() reports STATE_STARTING, fills in the early
fields and clears out the rest.
2. pgstat_bestart_security() reports the SSL/GSS status of the
connection. This is only for backends with a valid MyProcPort; they
call it twice.
3. pgstat_bestart_final() fills in the user and database IDs, takes
the entry out of STATE_STARTING, and reports the application_name.

I was wondering if maybe I should fill in application_name before
taking the entry out of STATE_STARTING, in order to establish the rule
that "starting" pgstat entries are always partially filled, and that
DBAs can rely on their full contents once they've proceeded past it.
Thoughts?

I've added machinery to 001_ssltests.pl to make sure we see early
transport security stats prior to user authentication. This overlaps
quite a bit with the new 007_pre_auth.pl, so if we'd rather not have
the latter (as briefly discussed upthread) I can move the rest of it
over.

Thanks,
--Jacob

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

    Michael Paquier <michael@paquier.xyz> — 2025-02-06T08:35:02Z

    On Mon, Nov 11, 2024 at 03:17:44PM -0800, Jacob Champion wrote:
> 1. pgstat_bestart_initial() reports STATE_STARTING, fills in the early
> fields and clears out the rest.
> 2. pgstat_bestart_security() reports the SSL/GSS status of the
> connection. This is only for backends with a valid MyProcPort; they
> call it twice.
> 3. pgstat_bestart_final() fills in the user and database IDs, takes
> the entry out of STATE_STARTING, and reports the application_name.

This split is interesting, neater than the previous approches taken.

> I was wondering if maybe I should fill in application_name before
> taking the entry out of STATE_STARTING, in order to establish the rule
> that "starting" pgstat entries are always partially filled, and that
> DBAs can rely on their full contents once they've proceeded past it.
> Thoughts?

 	/* Update app name to current GUC setting */
+	/* TODO: ask the list: maybe do this before setting STATE_UNDEFINED? */
 	if (application_name)
 		pgstat_report_appname(application_name);

Historically, we've always reported the application name after
STATE_UNDEFINED is set, never the reverse.  There could be potential
security implications if we were to begin reporting the application
name before the connection has fully authenticated because it would be
possible for attempted connections to show malicious data in the
catalogs, and now we're sure that the catalog data is OK to query for
other users.  Let's be careful about that.  I think that we should
still set that as late as possible in pgstat_bestart_final(), never at
an earlier step as this data can come from a connection
string, potentially malicious if not authenticated yet.

> I've added machinery to 001_ssltests.pl to make sure we see early
> transport security stats prior to user authentication. This overlaps
> quite a bit with the new 007_pre_auth.pl, so if we'd rather not have
> the latter (as briefly discussed upthread) I can move the rest of it
> over.

+	if (!bootstrap)
+	{
+		pgstat_bestart_initial();
+		if (MyProcPort)
+			pgstat_bestart_security();	/* fill in any SSL/GSS info too */

This part of patch 0001 is giving me a very long pause.  What's the
merit of filling in twice the backend entry data if we're going to
update it at the end anyway for normal backend connections?  More info
for debugging, is it?  It seems that removing this call does not
influence the tests you are adding, as well (or should the test
"pg_stat_ssl view is updated" be responsible for checking that?).
Perhaps this should be documented as a comment.

Anyway, allowing backends to call this routine multiple times makes me
quite uncomfortable, and it does not prevent looking at the wait event
data that may be reported with 0002, no?  I think that we should only
call it once per backend and once authentication is completed, even
perhaps have a static rule to engrave this policy in stone.

With this patch, the information that we get to be able to debug a
backend entry in pg_stat_activity is st_clientaddr and
remote_hostname.  If we have a backend stuck in a wait event for the
"Auth" class, would these be sufficient to provide a good user
experience?  Still better than nothing as we don't know the database
and user ID used for the connection until authentication is done, I
guess, to be able to grab patterns behind authentication getting
stuck.

In patch 0002, WAIT_EVENT_SSPI_TRANSLATE_NAME is used twice for two
code paths.  Perhaps these should be two separate wait events?
The events attached to ldap_unbind() make that also kind of hard to
debug.  What's the code path actually impacted if we see them in
pg_stat_activity?  We have nine of them with the same wait event
attached to them.

The patch needs some 2024 -> 2025 updates in its copyright notices.

At the end of [1], I've been reminded of this quote from Andres about
0002:
"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()."

Should we do improvements in this area with interruptions before
attempting to tackle the problem of making starting backend entries
visible in pg_stat_activity, before these complete authentication?  We
use wait events for syscalls on I/O already, perhaps that does not
stand as an argument in favor of this patch on its own, but I don't
see why more events associated to external library calls as done in
0002 is a problem?  Feel free to counter-argue, each code path where
an Auth event is added should be more closely looked at, for sure, but
I don't see why we should discard all of them based on this argument
if some are useful for debugging auth issues.

[1]: https://www.postgresql.org/message-id/faesruozcdcg2aksscb3dcojy4gqjqsyaxfajkqzm4kozjowgm@nmjgrrvdax25
--
Michael

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-02-10T16:23:30Z

    On Thu, Feb 6, 2025 at 12:35 AM Michael Paquier <michael@paquier.xyz> wrote:
>         /* Update app name to current GUC setting */
> +       /* TODO: ask the list: maybe do this before setting STATE_UNDEFINED? */
>         if (application_name)
>                 pgstat_report_appname(application_name);
>
> Historically, we've always reported the application name after
> STATE_UNDEFINED is set, never the reverse.  There could be potential
> security implications if we were to begin reporting the application
> name before the connection has fully authenticated because it would be
> possible for attempted connections to show malicious data in the
> catalogs, and now we're sure that the catalog data is OK to query for
> other users.  Let's be careful about that.  I think that we should
> still set that as late as possible in pgstat_bestart_final(), never at
> an earlier step as this data can come from a connection
> string, potentially malicious if not authenticated yet.

I don't want to change the order of authentication and application
name, just move the application name report up above the state change
in pgstat_bestart_final(). I don't feel strongly about it, though.

> +       if (!bootstrap)
> +       {
> +               pgstat_bestart_initial();
> +               if (MyProcPort)
> +                       pgstat_bestart_security();      /* fill in any SSL/GSS info too */
>
> This part of patch 0001 is giving me a very long pause.  What's the
> merit of filling in twice the backend entry data if we're going to
> update it at the end anyway for normal backend connections?  More info
> for debugging, is it?

Correct; if you already know authentication information from the
transport then it seemed nice to fill it in before doing the stuff
that hangs.

> It seems that removing this call does not
> influence the tests you are adding, as well (or should the test
> "pg_stat_ssl view is updated" be responsible for checking that?).

The test is supposed to enforce that, but I see that it's not for some
reason. That's concerning. I'll investigate, thanks for pointing it
out.

> With this patch, the information that we get to be able to debug a
> backend entry in pg_stat_activity is st_clientaddr and
> remote_hostname.  If we have a backend stuck in a wait event for the
> "Auth" class, would these be sufficient to provide a good user
> experience?  Still better than nothing as we don't know the database
> and user ID used for the connection until authentication is done, I
> guess, to be able to grab patterns behind authentication getting
> stuck.

It's better than nothing, but is there a particular reason not to
trust the crypto the first time around? The SSL/GSS details are what
they are; if you don't trust them at either point one or point two
then I think we need to have a more urgent conversation about that?

> In patch 0002, WAIT_EVENT_SSPI_TRANSLATE_NAME is used twice for two
> code paths.  Perhaps these should be two separate wait events?

That was my question from v6:

> I violated the "one event name per call site" rule with
> TranslateName(). The call pattern there is "call once to figure out
> the buffer length, then call again to fill it in", and IMO that didn't
> deserve differentiation. But if anyone objects, I'm happy to change it
> (and I'd appreciate some name suggestions in that case).

So -- any name suggestions? :D (Personally, I viewed this sort of like
an unrolled loop of two. I don't know if it helps to know which call
is hanging as long as you know that TranslateName is hanging.)

> The events attached to ldap_unbind() make that also kind of hard to
> debug.  What's the code path actually impacted if we see them in
> pg_stat_activity?  We have nine of them with the same wait event
> attached to them.

Do we _want_ nine separate flavors of WAIT_EVENT_LDAP_UNBIND? I
figured it was enough to know that you were stuck unbinding.

> The patch needs some 2024 -> 2025 updates in its copyright notices.

Will do.

> At the end of [1], I've been reminded of this quote from Andres about
> 0002:
> "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()."
>
> Should we do improvements in this area with interruptions before
> attempting to tackle the problem of making starting backend entries
> visible in pg_stat_activity, before these complete authentication?  We
> use wait events for syscalls on I/O already, perhaps that does not
> stand as an argument in favor of this patch on its own, but I don't
> see why more events associated to external library calls as done in
> 0002 is a problem?

I had hoped that my v6 addressed Andres' concerns by pushing the
events down as far as possible (that way they can't be nested, which I
took to be the primary problem). Does something else need to be done?

Thanks,
--Jacob

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-02-10T19:05:32Z

    On Mon, Feb 10, 2025 at 8:23 AM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
> The test is supposed to enforce that, but I see that it's not for some
> reason. That's concerning. I'll investigate, thanks for pointing it
> out.

Bad regex escaping on my part; fixed in v8. Thanks for the report!

While debugging, I also noticed that a poorly timed autovacuum could
also show up in my new pg_stat_activity query, so I've increased the
specificity.

> Do we _want_ nine separate flavors of WAIT_EVENT_LDAP_UNBIND? I
> figured it was enough to know that you were stuck unbinding.

v8-0003 shows this approach. For the record, I think it's materially
worse than v7-0003. IMO it increases the cognitive load for very
little benefit and makes it more work for a newcomer to refactor the
cleanup code for those routines. I think it's enough that you can see
a separate LOG message for each failure case, if you want to know why
we're unbinding.

Thanks,
--Jacob

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

    Michael Paquier <michael@paquier.xyz> — 2025-02-12T07:23:39Z

    On Mon, Feb 10, 2025 at 11:05:32AM -0800, Jacob Champion wrote:
> Bad regex escaping on my part; fixed in v8. Thanks for the report!
> 
> While debugging, I also noticed that a poorly timed autovacuum could
> also show up in my new pg_stat_activity query, so I've increased the
> specificity.

Now this test is able to catch the reason why it has been added.
Thanks for the fix.

Allowing pgstat_bestart_security() to be reentrant worries me.

Anyway, when it comes to the fields that would show up in the catalogs
before authentication completes, are we sure that all of them are OK
and that it would not become an open door for pushing data into the
catalogs that other users could scan?

+        lsslstatus.ssl_bits = be_tls_get_cipher_bits(MyProcPort);
+        strlcpy(lsslstatus.ssl_version, be_tls_get_version(MyProcPort), NAMEDATALEN);
+        strlcpy(lsslstatus.ssl_cipher, be_tls_get_cipher(MyProcPort), NAMEDATALEN);

These three for SSL are OK, they rely on a hardcoded set of values.

+        be_tls_get_peer_subject_name(MyProcPort, lsslstatus.ssl_client_dn, NAMEDATALEN);
+        be_tls_get_peer_serial(MyProcPort, lsslstatus.ssl_client_serial, NAMEDATALEN);
+        be_tls_get_peer_issuer_name(MyProcPort, lsslstatus.ssl_issuer_dn, NAMEDATALEN);

But are these three actually OK to have showing up in the catalogs
this early?  This data comes from a peer certificate, that we may know
nothing about, become set at a very early stage with
secure_initialize().

+        lgssstatus.gss_auth = be_gssapi_get_auth(MyProcPort);
+        lgssstatus.gss_enc = be_gssapi_get_enc(MyProcPort);
+        lgssstatus.gss_delegation = be_gssapi_get_delegation(MyProcPort);

These three are booleans, hence OK.  They are set when the connection
opens, before the first call of pgstat_bestart_security(), right?

+        if (princ)
+            strlcpy(lgssstatus.gss_princ, princ, NAMEDATALEN);

This is not going to be set, being part of pg_GSS_checkauth() that
happens later on.

As a whole we still have a gap between what could be OK, what could
not be OK, and the fact that pgstat_bestart_security() is called twice
makes that confusing.  Perhaps it would be OK to document what can be
set by the first call and/or the second call, but at the end it seems
that this is going to require a split, or just to move the fields that
are potentially unsafe into the final step where we know that we're
done with authentication, leaving in the security() call the fields
that we are definitely OK to have.  The boolean states from the Port
copied into the backend entries are fine.  The data coming from the
peer certificate when initializing the secure connection look
problematic.  We should be careful.

Daniel, perhaps you could comment about the fact of showing all these
fields in the catalogs before performing any authentication?  That
worries me.

> v8-0003 shows this approach. For the record, I think it's materially
> worse than v7-0003. IMO it increases the cognitive load for very
> little benefit and makes it more work for a newcomer to refactor the
> cleanup code for those routines. I think it's enough that you can see
> a separate LOG message for each failure case, if you want to know why
> we're unbinding.

That's more verbose, as well.  As Robert said, that makes the output
easier to debug with a 1:1 mapping between the event and a code path.
--
Michael

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-02-13T17:53:52Z

    On Tue, Feb 11, 2025 at 11:23 PM Michael Paquier <michael@paquier.xyz> wrote:
> +        be_tls_get_peer_subject_name(MyProcPort, lsslstatus.ssl_client_dn, NAMEDATALEN);
> +        be_tls_get_peer_serial(MyProcPort, lsslstatus.ssl_client_serial, NAMEDATALEN);
> +        be_tls_get_peer_issuer_name(MyProcPort, lsslstatus.ssl_issuer_dn, NAMEDATALEN);
>
> But are these three actually OK to have showing up in the catalogs
> this early?  This data comes from a peer certificate, that we may know
> nothing about, become set at a very early stage with
> secure_initialize().

I guess I'm going to zero in on your definition of "may know nothing
about". If that is true, something is very wrong IMO.

My understanding of the backend code was that port->peer is only set
after OpenSSL has verified that the certificate has been issued by an
explicitly trusted CA. (Our verify_cb() doesn't override the internal
checks to allow failed certificates through.) That may not be enough
to authorize entry into the server, but it also shouldn't be untrusted
data. If a CA is issuing Subject data that is somehow dangerous to the
operation of the server, I think that's a security problem in and of
itself: there are clientcert HBA modes that don't validate the
Subject, but they're still going to push that data into the catalogs,
aren't they?

So if we're concerned that Subject data is dangerous at this point in
the code, I agree that my patch makes it even more dangerous and I'll
modify it -- but then I'm going to split off another thread to try to
fix that underlying issue. A user should not have to be authorized to
access the server in order for signed authentication data from the
transport layer to be considered trustworthy. Being able to monitor
those separately is important for auditability.

> As a whole we still have a gap between what could be OK, what could
> not be OK, and the fact that pgstat_bestart_security() is called twice
> makes that confusing.

My end goal is that all of this _should_ always be OK, so calling it
once or twice or thirty times should be safe. (But again, if that's
not actually true today, I'll remove it for now.)

> > v8-0003 shows this approach. For the record, I think it's materially
> > worse than v7-0003. IMO it increases the cognitive load for very
> > little benefit and makes it more work for a newcomer to refactor the
> > cleanup code for those routines. I think it's enough that you can see
> > a separate LOG message for each failure case, if you want to know why
> > we're unbinding.
>
> That's more verbose, as well.  As Robert said, that makes the output
> easier to debug with a 1:1 mapping between the event and a code path.

I agree with Robert's goal in general. I just think that following
that rule to *this* extent is counterproductive. But I won't die on
that hill; in the end, I just want to be able to see when LDAP calls
hang.

Thanks!
--Jacob

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

    Michael Paquier <michael@paquier.xyz> — 2025-02-14T00:03:08Z

    On Thu, Feb 13, 2025 at 09:53:52AM -0800, Jacob Champion wrote:
> I guess I'm going to zero in on your definition of "may know nothing
> about". If that is true, something is very wrong IMO.
> 
> My understanding of the backend code was that port->peer is only set
> after OpenSSL has verified that the certificate has been issued by an
> explicitly trusted CA. (Our verify_cb() doesn't override the internal
> checks to allow failed certificates through.) That may not be enough
> to authorize entry into the server, but it also shouldn't be untrusted
> data. If a CA is issuing Subject data that is somehow dangerous to the
> operation of the server, I think that's a security problem in and of
> itself: there are clientcert HBA modes that don't validate the
> Subject, but they're still going to push that data into the catalogs,
> aren't they?

Is that the case before we finish authentication now?  I was not sure
how much of this data is set before and after finishing
authentication, tracking that this was part of the init phase of the
connection, something we do earlier than the actual authentication.
It feels like this should be documented more clearly in the patch if
pgstat_bestart_security() is allowed to be called multiple times (I
think we should not allow that).  That's quite unclear now in the
patch; on HEAD everything is set after authentication completes.

> So if we're concerned that Subject data is dangerous at this point in
> the code, I agree that my patch makes it even more dangerous and I'll
> modify it -- but then I'm going to split off another thread to try to
> fix that underlying issue. A user should not have to be authorized to
> access the server in order for signed authentication data from the
> transport layer to be considered trustworthy. Being able to monitor
> those separately is important for auditability.

Making this information visible in the catalogs for already logged in
users increases the potential of problems, and this is a sensitive
area of the code, so..

>> As a whole we still have a gap between what could be OK, what could
>> not be OK, and the fact that pgstat_bestart_security() is called twice
>> makes that confusing.
> 
> My end goal is that all of this _should_ always be OK, so calling it
> once or twice or thirty times should be safe. (But again, if that's
> not actually true today, I'll remove it for now.)

The concept of making pgstat_bestart_security() callable multiple
times relates also to the issue pointed upthread by Andres, somewhat:
allowing this pattern may lead to errors in the future regarding this
that should or should not be set this early in the authentication
process.  Sounds just saner to me to do pgstat_bestart_security()
once for now once we're OK with authentication, and it does not
prevent to address your initial point of being able to know if
backends with a given PID are stuck at a certain point.  At least
that's a step towards more debuggability as the backend entries are
available earlier than they are now.

Getting ready for tomatoes now, please aim freely.

> I agree with Robert's goal in general. I just think that following
> that rule to *this* extent is counterproductive. But I won't die on
> that hill; in the end, I just want to be able to see when LDAP calls
> hang.

Understood.
--
Michael

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-02-15T01:34:59Z

    On Thu, Feb 13, 2025 at 4:03 PM Michael Paquier <michael@paquier.xyz> wrote:
> > If a CA is issuing Subject data that is somehow dangerous to the
> > operation of the server, I think that's a security problem in and of
> > itself: there are clientcert HBA modes that don't validate the
> > Subject, but they're still going to push that data into the catalogs,
> > aren't they?
>
> Is that the case before we finish authentication now?

No, but I still don't understand why that's relevant. My point is that
transport authentication data should be neither less trustworthy prior
to ClientAuthentication, nor more trustworthy after it, since it's
signed by the same authentication provider that you're trusting to
make the authentication decisions in the first place. (But it doesn't
seem like we're going to agree on this for now; in the meantime I'll
prepare a version of the patch that only calls
pgstat_bestart_security() once.)

At some point in the future, I would really like to clarify what
potential problems there are if we put verified Subject data into the
catalogs before ClientAuthentication completes. I think that any such
problems would continue to be problems after ClientAuthentication
completes, too.

Thanks,
--Jacob

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-02-28T20:40:13Z

    On Fri, Feb 14, 2025 at 5:34 PM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
> (But it doesn't
> seem like we're going to agree on this for now; in the meantime I'll
> prepare a version of the patch that only calls
> pgstat_bestart_security() once.)

v9 removes the first call, and moves the second (now only) call up and
out of the if/else chain, just past client authentication. The SSL
pre-auth tests have been removed.

Thanks!
--Jacob

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

    Michael Paquier <michael@paquier.xyz> — 2025-03-03T05:23:51Z

    On Fri, Feb 28, 2025 at 12:40:13PM -0800, Jacob Champion wrote:
> v9 removes the first call, and moves the second (now only) call up and
> out of the if/else chain, just past client authentication. The SSL
> pre-auth tests have been removed.

I have put my eyes on 0001, and this version looks sensible here, just
tweaked a bit the comments after a closer lookup and adjusted a few
things, nothing huge..

 	/* Update app name to current GUC setting */
+	/* TODO: ask the list: maybe do this before setting STATE_UNDEFINED? */
 	if (application_name)
 		pgstat_report_appname(application_name);

This has always been set last and it's still the case in the patch, so
let's just remove that.
--
Michael

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

    Michael Paquier <michael@paquier.xyz> — 2025-03-04T08:51:17Z

    On Mon, Mar 03, 2025 at 02:23:51PM +0900, Michael Paquier wrote:
> This has always been set last and it's still the case in the patch, so
> let's just remove that.

This first one has been now applied as c76db55c9085.  Attached is the
rest to add the wait events (still need to have a closer look at this
part).
--
Michael

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-04T16:12:24Z

    On Tue, Mar 4, 2025 at 12:51 AM Michael Paquier <michael@paquier.xyz> wrote:
>
> On Mon, Mar 03, 2025 at 02:23:51PM +0900, Michael Paquier wrote:
> > This has always been set last and it's still the case in the patch, so
> > let's just remove that.
>
> This first one has been now applied as c76db55c9085.

Thanks!

> Attached is the
> rest to add the wait events (still need to have a closer look at this
> part).

Sounds good.

--Jacob

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

    Andres Freund <andres@anarazel.de> — 2025-03-05T00:10:36Z

    Hi,

On 2025-03-04 17:51:17 +0900, Michael Paquier wrote:
> On Mon, Mar 03, 2025 at 02:23:51PM +0900, Michael Paquier wrote:
> > This has always been set last and it's still the case in the patch, so
> > let's just remove that.
>
> This first one has been now applied as c76db55c9085.  Attached is the
> rest to add the wait events (still need to have a closer look at this
> part).

This seems to trigger a bunch of CI failures, e.g.:

https://cirrus-ci.com/task/5350341408980992
https://cirrus-ci.com/task/5537391798124544
https://cirrus-ci.com/task/4657439905153024

https://api.cirrus-ci.com/v1/artifact/task/5350341408980992/testrun/build/testrun/authentication/007_pre_auth/log/regress_log_007_pre_auth

[17:47:59.698](0.000s) ok 1 - authenticating connections are recorded in pg_stat_activity
[17:47:59.698](0.000s) # issuing query 5 via background psql: SELECT injection_points_wakeup('init-pre-auth');
[17:47:59.752](0.054s) # pump_until: process terminated unexpectedly when searching for "(?^:(^|\n)background_psql: QUERY_SEPARATOR 5:\r?\n)" with stream: ""
process ended prematurely at C:/cirrus/src/test/perl/PostgreSQL/Test/Utils.pm line 439.
# Postmaster PID for node "primary" is 6084

https://api.cirrus-ci.com/v1/artifact/task/5350341408980992/testrun/build/testrun/authentication/007_pre_auth/log/007_pre_auth_primary.log
2025-03-04 17:47:59.705 GMT [7624][client backend] [007_pre_auth.pl][2/9:0] LOG:  statement: SELECT injection_points_wakeup('init-pre-auth');
2025-03-04 17:47:59.705 GMT [7624][client backend] [007_pre_auth.pl][2/9:0] ERROR:  could not find injection point init-pre-auth to wake up
2025-03-04 17:47:59.705 GMT [7624][client backend] [007_pre_auth.pl][2/9:0] STATEMENT:  SELECT injection_points_wakeup('init-pre-auth');
2025-03-04 17:47:59.706 GMT [7624][client backend] [007_pre_auth.pl][:0] LOG:  disconnection: session time: 0:00:00.333 user=SYSTEM database=postgres host=[local]

Greetings,

Andres Freund

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-05T00:26:57Z

    On Tue, Mar 4, 2025 at 4:10 PM Andres Freund <andres@anarazel.de> wrote:
> This seems to trigger a bunch of CI failures, e.g.:
>
> https://cirrus-ci.com/task/5350341408980992
> https://cirrus-ci.com/task/5537391798124544
> https://cirrus-ci.com/task/4657439905153024

Hm. All Windows.

> https://api.cirrus-ci.com/v1/artifact/task/5350341408980992/testrun/build/testrun/authentication/007_pre_auth/log/007_pre_auth_primary.log
> 2025-03-04 17:47:59.705 GMT [7624][client backend] [007_pre_auth.pl][2/9:0] LOG:  statement: SELECT injection_points_wakeup('init-pre-auth');
> 2025-03-04 17:47:59.705 GMT [7624][client backend] [007_pre_auth.pl][2/9:0] ERROR:  could not find injection point init-pre-auth to wake up

But attaching to that injection point succeeded above, for us to have
gotten to this point... Does that error message indicate that the
point itself doesn't exist, or that nothing is currently waiting?

--Jacob

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-05T00:53:14Z

    On Tue, Mar 4, 2025 at 4:26 PM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
> But attaching to that injection point succeeded above, for us to have
> gotten to this point... Does that error message indicate that the
> point itself doesn't exist, or that nothing is currently waiting?

Looks like the latter. With the following diff I can reproduce locally:

    --- a/src/backend/utils/init/postinit.c
    +++ b/src/backend/utils/init/postinit.c
    @@ -730,6 +730,7 @@ InitPostgres(const char *in_dbname, Oid dboid,
            if (!bootstrap)
            {
                    pgstat_bestart_initial();
    +               pg_usleep(1000000);
                    INJECTION_POINT("init-pre-auth");
            }

So I've misunderstood the API. I should have added a background
version of $node->wait_for_event(), or similar.

I'll work on a fix, but it probably won't be fast since I need to
learn more about the injection points architecture. The test may need
to be disabled, or the patch backed out, depending on how painful the
flake is for everybody.

Thanks, and sorry,
--Jacob

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

    Michael Paquier <michael@paquier.xyz> — 2025-03-05T04:45:12Z

    On Tue, Mar 04, 2025 at 04:53:14PM -0800, Jacob Champion wrote:
> I'll work on a fix, but it probably won't be fast since I need to
> learn more about the injection points architecture. The test may need
> to be disabled, or the patch backed out, depending on how painful the
> flake is for everybody.

Oops, missed these failures..  So we have a race condition where we
are trying to wake up a point that's not waiting yet, because there is
a small window between the moment when the backend entry is marked as
"starting" and the injection point wait.

What this is telling us is that we should change the query scanning
pg_stat_activity for a PID of a backend in 'starting' state so as we
also check the wait_event init-pre-auth, as this is reported when
using injection point waits.  The attached should be enough to take
care of this race condition.
--
Michael

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-05T13:47:08Z

    On Tue, Mar 4, 2025 at 8:45 PM Michael Paquier <michael@paquier.xyz> wrote:
> What this is telling us is that we should change the query scanning
> pg_stat_activity for a PID of a backend in 'starting' state so as we
> also check the wait_event init-pre-auth, as this is reported when
> using injection point waits.  The attached should be enough to take
> care of this race condition.

That's a lot easier than the rabbit hole I was running down; thank you.

> - "SELECT pid FROM pg_stat_activity WHERE state = 'starting';");
> + qq{SELECT pid FROM pg_stat_activity
> +  WHERE state = 'starting' and wait_event = 'init-pre-auth';});

I had intended for this part of the patch to also wait for client
backends only (see v8-0001, 001_ssltests.pl), but I must have
misapplied it. (The ssltests change was lost completely when that file
was dropped from the set.) So while we're at it, should we add a
`backend_type = 'client backend'` filter to stop that from flaking in
the future? That would further align this query with the
wait_for_event() implementation.

Thanks,
--Jacob

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-05T16:16:45Z

    On Wed, Mar 5, 2025 at 5:47 AM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
>
> So while we're at it, should we add a
> `backend_type = 'client backend'` filter to stop that from flaking in
> the future? That would further align this query with the
> wait_for_event() implementation.

More concretely: here's a squashable patchset with that suggestion,
for the CI to chew on.

--Jacob

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

    Andres Freund <andres@anarazel.de> — 2025-03-05T17:28:33Z

    Hi,

On 2025-03-05 08:16:45 -0800, Jacob Champion wrote:
> From efc9fc3b3993601e9611131f229fbcaf4daa46f1 Mon Sep 17 00:00:00 2001
> From: Michael Paquier <michael@paquier.xyz>
> Date: Wed, 5 Mar 2025 13:30:43 +0900
> Subject: [PATCH 1/2] Fix race condition in pre-auth test
> 
> ---
>  src/test/authentication/t/007_pre_auth.pl | 6 ++++--
>  1 file changed, 4 insertions(+), 2 deletions(-)
> 
> diff --git a/src/test/authentication/t/007_pre_auth.pl b/src/test/authentication/t/007_pre_auth.pl
> index a638226dbaf..90aaea4b5a6 100644
> --- a/src/test/authentication/t/007_pre_auth.pl
> +++ b/src/test/authentication/t/007_pre_auth.pl
> @@ -43,12 +43,14 @@ $psql->query_safe("SELECT injection_points_attach('init-pre-auth', 'wait')");
>  # authentication. Use the $psql connection handle for server interaction.
>  my $conn = $node->background_psql('postgres', wait => 0);
>  
> -# Wait for the connection to show up.
> +# Wait for the connection to show up in pg_stat_activity, with the wait_event
> +# of the injection point.
>  my $pid;
>  while (1)
>  {
>  	$pid = $psql->query(
> -		"SELECT pid FROM pg_stat_activity WHERE state = 'starting';");
> +		qq{SELECT pid FROM pg_stat_activity
> +  WHERE state = 'starting' and wait_event = 'init-pre-auth';});
>  	last if $pid ne "";

Unrelated to the change in this patch, but tests really shouldn't use while(1)
loops without a termination condition. If something is wrong, the test will
hang indefinitely, instead of timing out.  On the buildfarm that can take out
an animal if it hasn't configured a timeout (with autoconf at least, meson
terminates tests after a timeout).

I guess you can't use poll_query_until() here, but in that case you should
copy some of the timeout logic. Or, perhaps better, add a poll_query_until()
to BackgroundPsql.pm.

Greetings,

Andres Freund

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-06T00:19:04Z

    On Wed, Mar 5, 2025 at 9:28 AM Andres Freund <andres@anarazel.de> wrote:
> Unrelated to the change in this patch, but tests really shouldn't use while(1)
> loops without a termination condition. If something is wrong, the test will
> hang indefinitely, instead of timing out.  On the buildfarm that can take out
> an animal if it hasn't configured a timeout (with autoconf at least, meson
> terminates tests after a timeout).

With the current patchset, if I pull the PG_TEST_TIMEOUT_DEFAULT down
low, and modify the backend so that either one of the two conditions
never completes, the tests still stop due to BackgroundPsql's session
timeout. This is true for Meson and Autoconf. Is there a different
situation where I can't rely on that?

Thanks!
--Jacob

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

    Andres Freund <andres@anarazel.de> — 2025-03-06T01:55:55Z

    Hi,

On 2025-03-05 16:19:04 -0800, Jacob Champion wrote:
> On Wed, Mar 5, 2025 at 9:28 AM Andres Freund <andres@anarazel.de> wrote:
> > Unrelated to the change in this patch, but tests really shouldn't use while(1)
> > loops without a termination condition. If something is wrong, the test will
> > hang indefinitely, instead of timing out.  On the buildfarm that can take out
> > an animal if it hasn't configured a timeout (with autoconf at least, meson
> > terminates tests after a timeout).
>
> With the current patchset, if I pull the PG_TEST_TIMEOUT_DEFAULT down
> low, and modify the backend so that either one of the two conditions
> never completes, the tests still stop due to BackgroundPsql's session
> timeout. This is true for Meson and Autoconf. Is there a different
> situation where I can't rely on that?

Oh, I see. I missed that it's relying on the timeout and that the timeout
isn't reset in the loop.  Sorry for the noise.


FWIW, I still don't like open-coded poll loops, as I'd really like our tests
to use some smarter retry/backoff logic than a single hardcoded
usleep(100_000).

The first few iterations that's too long, commonly the state isn't reached
in the first iteration, but will be within a millisecond or two. Waiting
100ms is obviously way too long.

Once we've slept for 10+ seconds without reaching the target, sleeping for
100us is way too short a sleep and just wastes CPU cycles. A decent portion
of the CPU time when running under valgrind is wasted just due to way too
tight retry loops.

That's harder to do if we have many places polling.

But anyway, I digress, that's really not related to your change.

Greetings,

Andres Freund

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

    Michael Paquier <michael@paquier.xyz> — 2025-03-06T04:07:54Z

    On Wed, Mar 05, 2025 at 08:55:55PM -0500, Andres Freund wrote:
> Once we've slept for 10+ seconds without reaching the target, sleeping for
> 100us is way too short a sleep and just wastes CPU cycles. A decent portion
> of the CPU time when running under valgrind is wasted just due to way too
> tight retry loops.
> 
> That's harder to do if we have many places polling.
> 
> But anyway, I digress, that's really not related to your change.

Please let me agree with your previous argument, then.  While looking
at the test when reviewing the patch a couple of days ago, I was also
wondering why we could not have a poll_query_until() in BackgroundPsql
and gave up on the idea.

Honestly, I don't see a reason not to introduce that, like in the
attached.  BackgroundPsql->query() does all the job already, and it is
possible to rely on $PostgreSQL::Test::Utils::timeout_default in the
loops, so that's simple, and it makes the test a bit easier to parse.
--
Michael

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-06T22:25:07Z

    On Wed, Mar 5, 2025 at 8:08 PM Michael Paquier <michael@paquier.xyz> 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

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

    Michael Paquier <michael@paquier.xyz> — 2025-03-06T23:15:38Z

    On Thu, Mar 06, 2025 at 02:25:07PM -0800, Jacob Champion wrote:
> On Wed, Mar 5, 2025 at 8:08 PM Michael Paquier <michael@paquier.xyz> wrote:
>> +  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...

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-06T23:39:44Z

    On Thu, Mar 6, 2025 at 3:15 PM Michael Paquier <michael@paquier.xyz> wrote:
> 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.

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.

> 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.

Yeah, that API is definitely subtle.

--Jacob

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

    Andres Freund <andres@anarazel.de> — 2025-03-07T16:38:13Z

    Hi,

On 2025-03-06 15:39:44 -0800, Jacob Champion wrote:
> 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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-07T17:03:18Z

    On Fri, Mar 7, 2025 at 8:38 AM Andres Freund <andres@anarazel.de> wrote:
> 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.

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

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

    Andres Freund <andres@anarazel.de> — 2025-03-07T17:25:22Z

    Hi,

On 2025-03-07 09:03:18 -0800, Jacob Champion wrote:
> On Fri, Mar 7, 2025 at 8:38 AM Andres Freund <andres@anarazel.de> wrote:
> > 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.
>
> 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.


> 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?

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-07T18:28:16Z

    On Fri, Mar 7, 2025 at 9:25 AM Andres Freund <andres@anarazel.de> wrote:
> 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().

Okay.

> 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.

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.

> 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.

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?

> 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.

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
> these functions and not just do that for *all* functions in postgres? I mean
> 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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-12T22:16:02Z

    On Fri, Mar 7, 2025 at 10:28 AM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
> > 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.
>
> 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?

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-13T16:23:10Z

    On Wed, Mar 12, 2025 at 3:16 PM Jacob Champion
<jacob.champion@enterprisedb.com> wrote:
> 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.

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

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

    Andres Freund <andres@anarazel.de> — 2025-03-13T16:56:09Z

    Hi,

On 2025-03-13 09:23:10 -0700, Jacob Champion wrote:
> On Wed, Mar 12, 2025 at 3:16 PM Jacob Champion
> <jacob.champion@enterprisedb.com> wrote:
> > 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?

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

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-13T17:29:49Z

    On Thu, Mar 13, 2025 at 9:56 AM Andres Freund <andres@anarazel.de> wrote:
> 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...

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.

> 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.

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

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

    Andres Freund <andres@anarazel.de> — 2025-03-13T17:56:42Z

    On 2025-03-13 10:29:49 -0700, Jacob Champion wrote:
> On Thu, Mar 13, 2025 at 9:56 AM Andres Freund <andres@anarazel.de> wrote:
> > 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...
>
> 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.

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.


> > 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.
>
> 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.

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
> the overall result...)

Also fair enough :)

Greetings,

Andres Freund

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

    Jacob Champion <jacob.champion@enterprisedb.com> — 2025-03-17T17:22:47Z

    On Thu, Mar 13, 2025 at 10:56 AM Andres Freund <andres@anarazel.de> wrote:
> > 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.
>
> 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.

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

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

    Michael Paquier <michael@paquier.xyz> — 2025-03-21T05:53:12Z

    On Mon, Mar 17, 2025 at 10:22:47AM -0700, Jacob Champion wrote:
> 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.

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