public inbox for [email protected]
help / color / mirror / Atom feedFrom: Jacob Champion <[email protected]>
To: PostgreSQL Hackers <[email protected]>
Cc: Euler Taveira <[email protected]>
Subject: [PATCH] pg_stat_activity: make slow/hanging authentication more visible
Date: Mon, 6 May 2024 14:23:38 -0700
Message-ID: <CAOYmi+=60deN20WDyCoHCiecgivJxr=98s7s7-C8SkXwrCfHXg@mail.gmail.com> (raw)
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
Attachments:
[application/octet-stream] 0001-pgstat-report-in-earlier-with-STATE_AUTHENTICATING.patch (4.8K, ../CAOYmi+=60deN20WDyCoHCiecgivJxr=98s7s7-C8SkXwrCfHXg@mail.gmail.com/2-0001-pgstat-report-in-earlier-with-STATE_AUTHENTICATING.patch)
download | inline diff:
From 1535930adde98162152223c1d215c1ccb0f0a9e0 Mon Sep 17 00:00:00 2001
From: Jacob Champion <[email protected]>
Date: Fri, 3 May 2024 15:54:58 -0700
Subject: [PATCH 1/2] pgstat: report in earlier with STATE_AUTHENTICATING
Add pgstat_bestart_pre_auth(), which reports an 'authenticating' state
while waiting for client authentication to complete. Since we hold a
transaction open across that call, and some authentication methods call
out to external systems, having a pg_stat_activity entry helps DBAs
debug when things go badly wrong.
---
src/backend/utils/activity/backend_status.c | 37 ++++++++++++++++++---
src/backend/utils/adt/pgstatfuncs.c | 3 ++
src/backend/utils/init/postinit.c | 9 +++++
src/include/utils/backend_status.h | 2 ++
4 files changed, 47 insertions(+), 4 deletions(-)
diff --git a/src/backend/utils/activity/backend_status.c b/src/backend/utils/activity/backend_status.c
index 1ccf4c6d83..c996049bbe 100644
--- a/src/backend/utils/activity/backend_status.c
+++ b/src/backend/utils/activity/backend_status.c
@@ -71,6 +71,7 @@ static int localNumBackends = 0;
static MemoryContext backendStatusSnapContext;
+static void pgstat_bestart_internal(bool pre_auth);
static void pgstat_beshutdown_hook(int code, Datum arg);
static void pgstat_read_current_status(void);
static void pgstat_setup_backend_status_context(void);
@@ -271,6 +272,34 @@ pgstat_beinit(void)
*/
void
pgstat_bestart(void)
+{
+ pgstat_bestart_internal(false);
+}
+
+
+/* ----------
+ * pgstat_bestart_pre_auth() -
+ *
+ * Like pgstat_beinit(), above, but it's designed to be called before
+ * authentication has been performed (so we have no user or database IDs).
+ * Called from InitPostgres.
+ *----------
+ */
+void
+pgstat_bestart_pre_auth(void)
+{
+ pgstat_bestart_internal(true);
+}
+
+
+/* ----------
+ * pgstat_bestart_internal() -
+ *
+ * Implementation of both flavors of pgstat_bestart().
+ *----------
+ */
+static void
+pgstat_bestart_internal(bool pre_auth)
{
volatile PgBackendStatus *vbeentry = MyBEEntry;
PgBackendStatus lbeentry;
@@ -320,9 +349,9 @@ pgstat_bestart(void)
lbeentry.st_databaseid = MyDatabaseId;
/* We have userid for client-backends, wal-sender and bgworker processes */
- if (lbeentry.st_backendType == B_BACKEND
- || lbeentry.st_backendType == B_WAL_SENDER
- || lbeentry.st_backendType == B_BG_WORKER)
+ if (!pre_auth && (lbeentry.st_backendType == B_BACKEND
+ || lbeentry.st_backendType == B_WAL_SENDER
+ || lbeentry.st_backendType == B_BG_WORKER))
lbeentry.st_userid = GetSessionUserId();
else
lbeentry.st_userid = InvalidOid;
@@ -377,7 +406,7 @@ pgstat_bestart(void)
lbeentry.st_gss = false;
#endif
- lbeentry.st_state = STATE_UNDEFINED;
+ lbeentry.st_state = pre_auth ? STATE_AUTHENTICATING : STATE_UNDEFINED;
lbeentry.st_progress_command = PROGRESS_COMMAND_INVALID;
lbeentry.st_progress_command_target = InvalidOid;
lbeentry.st_query_id = UINT64CONST(0);
diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c
index 3876339ee1..f34e4a1643 100644
--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -366,6 +366,9 @@ pg_stat_get_activity(PG_FUNCTION_ARGS)
switch (beentry->st_state)
{
+ case STATE_AUTHENTICATING:
+ values[4] = CStringGetTextDatum("authenticating");
+ break;
case STATE_IDLE:
values[4] = CStringGetTextDatum("idle");
break;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 0805398e24..4f10e29b3d 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -921,6 +921,15 @@ InitPostgres(const char *in_dbname, Oid dboid,
{
/* normal multiuser case */
Assert(MyProcPort != NULL);
+
+ /*
+ * Authentication can take a while, during which time we're holding a
+ * transaction open. Fill in enough of a backend status so that DBAs can
+ * observe what's going on. (The later call to pgstat_bestart() will
+ * fill in the rest of the status after we've authenticated.)
+ */
+ pgstat_bestart_pre_auth();
+
PerformAuthentication(MyProcPort);
InitializeSessionUserId(username, useroid, false);
/* ensure that auth_method is actually valid, aka authn_id is not NULL */
diff --git a/src/include/utils/backend_status.h b/src/include/utils/backend_status.h
index 7b7f6f59d0..f673c6a6ac 100644
--- a/src/include/utils/backend_status.h
+++ b/src/include/utils/backend_status.h
@@ -24,6 +24,7 @@
typedef enum BackendState
{
STATE_UNDEFINED,
+ STATE_AUTHENTICATING,
STATE_IDLE,
STATE_RUNNING,
STATE_IDLEINTRANSACTION,
@@ -309,6 +310,7 @@ extern void CreateSharedBackendStatus(void);
/* Initialization functions */
extern void pgstat_beinit(void);
+extern void pgstat_bestart_pre_auth(void);
extern void pgstat_bestart(void);
extern void pgstat_clear_backend_activity_snapshot(void);
--
2.34.1
[application/octet-stream] 0002-WIP-report-external-auth-calls-as-wait-events.patch (7.5K, ../CAOYmi+=60deN20WDyCoHCiecgivJxr=98s7s7-C8SkXwrCfHXg@mail.gmail.com/3-0002-WIP-report-external-auth-calls-as-wait-events.patch)
download | inline diff:
From 9faa86a4597227c5837c306c01a7a0e5466e4ea5 Mon Sep 17 00:00:00 2001
From: Jacob Champion <[email protected]>
Date: Fri, 3 May 2024 15:58:23 -0700
Subject: [PATCH 2/2] WIP: report external auth calls as wait events
Introduce new WAIT_EVENT_AUTHN_* types for various external
authentication systems, to make it obvious what's going wrong if one of
those systems hangs.
TODO:
- don't abuse the IPC wait event group like this
- test
---
src/backend/libpq/auth.c | 54 +++++++++++++++----
.../utils/activity/wait_event_names.txt | 5 ++
2 files changed, 49 insertions(+), 10 deletions(-)
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 2b607c5270..bda80e88f9 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -38,6 +38,7 @@
#include "replication/walsender.h"
#include "storage/ipc.h"
#include "utils/memutils.h"
+#include "utils/wait_event.h"
/*----------------------------------------------------------------
* Global authentication functions
@@ -1000,6 +1001,7 @@ pg_GSS_recvauth(Port *port)
elog(DEBUG4, "processing received GSS token of length %u",
(unsigned int) gbuf.length);
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_GSSAPI);
maj_stat = gss_accept_sec_context(&min_stat,
&port->gss->ctx,
port->gss->cred,
@@ -1011,6 +1013,7 @@ pg_GSS_recvauth(Port *port)
&gflags,
NULL,
pg_gss_accept_delegation ? &delegated_creds : NULL);
+ pgstat_report_wait_end();
/* gbuf no longer used */
pfree(buf.data);
@@ -1222,6 +1225,7 @@ pg_SSPI_recvauth(Port *port)
/*
* Acquire a handle to the server credentials.
*/
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
r = AcquireCredentialsHandle(NULL,
"negotiate",
SECPKG_CRED_INBOUND,
@@ -1231,6 +1235,8 @@ pg_SSPI_recvauth(Port *port)
NULL,
&sspicred,
&expiry);
+ pgstat_report_wait_end();
+
if (r != SEC_E_OK)
pg_SSPI_error(ERROR, _("could not acquire SSPI credentials"), r);
@@ -1296,6 +1302,7 @@ pg_SSPI_recvauth(Port *port)
elog(DEBUG4, "processing received SSPI token of length %u",
(unsigned int) buf.len);
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
r = AcceptSecurityContext(&sspicred,
sspictx,
&inbuf,
@@ -1305,6 +1312,7 @@ pg_SSPI_recvauth(Port *port)
&outbuf,
&contextattr,
NULL);
+ pgstat_report_wait_end();
/* input buffer no longer used */
pfree(buf.data);
@@ -1402,19 +1410,25 @@ pg_SSPI_recvauth(Port *port)
CloseHandle(token);
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
if (!LookupAccountSid(NULL, tokenuser->User.Sid, accountname, &accountnamesize,
domainname, &domainnamesize, &accountnameuse))
ereport(ERROR,
(errmsg_internal("could not look up account SID: error code %lu",
GetLastError())));
+ pgstat_report_wait_end();
free(tokenuser);
if (!port->hba->compat_realm)
{
- int status = pg_SSPI_make_upn(accountname, sizeof(accountname),
- domainname, sizeof(domainname),
- port->hba->upn_username);
+ int status;
+
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
+ status = pg_SSPI_make_upn(accountname, sizeof(accountname),
+ domainname, sizeof(domainname),
+ port->hba->upn_username);
+ pgstat_report_wait_end();
if (status != STATUS_OK)
/* Error already reported from pg_SSPI_make_upn */
@@ -2114,7 +2128,9 @@ CheckPAMAuth(Port *port, const char *user, const char *password)
return STATUS_ERROR;
}
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_PAM);
retval = pam_authenticate(pamh, 0);
+ pgstat_report_wait_end();
if (retval != PAM_SUCCESS)
{
@@ -2127,7 +2143,9 @@ CheckPAMAuth(Port *port, const char *user, const char *password)
return pam_no_password ? STATUS_EOF : STATUS_ERROR;
}
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_PAM);
retval = pam_acct_mgmt(pamh, 0);
+ pgstat_report_wait_end();
if (retval != PAM_SUCCESS)
{
@@ -2478,7 +2496,11 @@ CheckLDAPAuth(Port *port)
if (passwd == NULL)
return STATUS_EOF; /* client wouldn't send password */
- if (InitializeLDAPConnection(port, &ldap) == STATUS_ERROR)
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
+ r = InitializeLDAPConnection(port, &ldap);
+ pgstat_report_wait_end();
+
+ if (r == STATUS_ERROR)
{
/* Error message already sent */
pfree(passwd);
@@ -2525,9 +2547,12 @@ CheckLDAPAuth(Port *port)
* Bind with a pre-defined username/password (if available) for
* searching. If none is specified, this turns into an anonymous bind.
*/
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
r = ldap_simple_bind_s(ldap,
port->hba->ldapbinddn ? port->hba->ldapbinddn : "",
port->hba->ldapbindpasswd ? ldap_password_hook(port->hba->ldapbindpasswd) : "");
+ pgstat_report_wait_end();
+
if (r != LDAP_SUCCESS)
{
ereport(LOG,
@@ -2550,6 +2575,8 @@ CheckLDAPAuth(Port *port)
filter = psprintf("(uid=%s)", port->user_name);
search_message = NULL;
+
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
r = ldap_search_s(ldap,
port->hba->ldapbasedn,
port->hba->ldapscope,
@@ -2557,6 +2584,7 @@ CheckLDAPAuth(Port *port)
attributes,
0,
&search_message);
+ pgstat_report_wait_end();
if (r != LDAP_SUCCESS)
{
@@ -2625,7 +2653,9 @@ CheckLDAPAuth(Port *port)
port->user_name,
port->hba->ldapsuffix ? port->hba->ldapsuffix : "");
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
r = ldap_simple_bind_s(ldap, fulluser, passwd);
+ pgstat_report_wait_end();
if (r != LDAP_SUCCESS)
{
@@ -2885,12 +2915,16 @@ CheckRADIUSAuth(Port *port)
identifiers = list_head(port->hba->radiusidentifiers);
foreach(server, port->hba->radiusservers)
{
- int ret = PerformRadiusTransaction(lfirst(server),
- lfirst(secrets),
- radiusports ? lfirst(radiusports) : NULL,
- identifiers ? lfirst(identifiers) : NULL,
- port->user_name,
- passwd);
+ int ret;
+
+ pgstat_report_wait_start(WAIT_EVENT_AUTHN_RADIUS);
+ ret = PerformRadiusTransaction(lfirst(server),
+ lfirst(secrets),
+ radiusports ? lfirst(radiusports) : NULL,
+ identifiers ? lfirst(identifiers) : NULL,
+ port->user_name,
+ passwd);
+ pgstat_report_wait_end();
/*------
* STATUS_OK = Login OK
diff --git a/src/backend/utils/activity/wait_event_names.txt b/src/backend/utils/activity/wait_event_names.txt
index 87cbca2811..7761c2d71d 100644
--- a/src/backend/utils/activity/wait_event_names.txt
+++ b/src/backend/utils/activity/wait_event_names.txt
@@ -104,6 +104,11 @@ Section: ClassName - WaitEventIPC
APPEND_READY "Waiting for subplan nodes of an <literal>Append</literal> plan node to be ready."
ARCHIVE_CLEANUP_COMMAND "Waiting for <xref linkend="guc-archive-cleanup-command"/> to complete."
ARCHIVE_COMMAND "Waiting for <xref linkend="guc-archive-command"/> to complete."
+AUTHN_GSSAPI "Waiting for a response from a Kerberos server via GSSAPI."
+AUTHN_LDAP "Waiting for a response from an LDAP server."
+AUTHN_PAM "Waiting for a response from the local PAM service."
+AUTHN_RADIUS "Waiting for a response from a RADIUS server."
+AUTHN_SSPI "Waiting for a response from a Windows security provider via SSPI."
BACKEND_TERMINATION "Waiting for the termination of another backend."
BACKUP_WAIT_WAL_ARCHIVE "Waiting for WAL files required for a backup to be successfully archived."
BGWORKER_SHUTDOWN "Waiting for background worker to shut down."
--
2.34.1
view thread (2+ messages)
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected]
Subject: Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible
In-Reply-To: <CAOYmi+=60deN20WDyCoHCiecgivJxr=98s7s7-C8SkXwrCfHXg@mail.gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox