diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index aaa6586d3a49..4b1c753f8c56 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -1045,6 +1045,14 @@ postgres 27093 0.0 0.0 30096 2752 ? Ss 11:34 0:00 postgres: ser see . + + Auth + The server process is waiting for an external system to + authenticate and/or authorize the client connection. + wait_event will identify the specific wait point; + see . + + BufferPin The server process is waiting for exclusive access to diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c index e18683c47e72..ffcb77358c09 100644 --- a/src/backend/libpq/auth.c +++ b/src/backend/libpq/auth.c @@ -40,6 +40,7 @@ #include "storage/ipc.h" #include "tcop/backend_startup.h" #include "utils/memutils.h" +#include "utils/wait_event.h" /*---------------------------------------------------------------- * Global authentication functions @@ -993,6 +994,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_GSSAPI_ACCEPT_SEC_CONTEXT); maj_stat = gss_accept_sec_context(&min_stat, &port->gss->ctx, port->gss->cred, @@ -1004,6 +1006,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); @@ -1215,6 +1218,7 @@ pg_SSPI_recvauth(Port *port) /* * Acquire a handle to the server credentials. */ + pgstat_report_wait_start(WAIT_EVENT_SSPI_ACQUIRE_CREDENTIALS_HANDLE); r = AcquireCredentialsHandle(NULL, "negotiate", SECPKG_CRED_INBOUND, @@ -1224,6 +1228,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); @@ -1289,6 +1295,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_SSPI_ACCEPT_SECURITY_CONTEXT); r = AcceptSecurityContext(&sspicred, sspictx, &inbuf, @@ -1298,6 +1305,7 @@ pg_SSPI_recvauth(Port *port) &outbuf, &contextattr, NULL); + pgstat_report_wait_end(); /* input buffer no longer used */ pfree(buf.data); @@ -1395,11 +1403,13 @@ pg_SSPI_recvauth(Port *port) CloseHandle(token); + pgstat_report_wait_start(WAIT_EVENT_SSPI_LOOKUP_ACCOUNT_SID); 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); @@ -1496,8 +1506,11 @@ pg_SSPI_make_upn(char *accountname, */ samname = psprintf("%s\\%s", domainname, accountname); + + pgstat_report_wait_start(WAIT_EVENT_SSPI_TRANSLATE_NAME); res = TranslateName(samname, NameSamCompatible, NameUserPrincipal, NULL, &upnamesize); + pgstat_report_wait_end(); if ((!res && GetLastError() != ERROR_INSUFFICIENT_BUFFER) || upnamesize == 0) @@ -1512,8 +1525,10 @@ pg_SSPI_make_upn(char *accountname, /* upnamesize includes the terminating NUL. */ upname = palloc(upnamesize); + pgstat_report_wait_start(WAIT_EVENT_SSPI_TRANSLATE_NAME); res = TranslateName(samname, NameSamCompatible, NameUserPrincipal, upname, &upnamesize); + pgstat_report_wait_end(); pfree(samname); if (res) @@ -2112,7 +2127,9 @@ CheckPAMAuth(Port *port, const char *user, const char *password) return STATUS_ERROR; } + pgstat_report_wait_start(WAIT_EVENT_PAM_AUTHENTICATE); retval = pam_authenticate(pamh, 0); + pgstat_report_wait_end(); if (retval != PAM_SUCCESS) { @@ -2125,7 +2142,9 @@ CheckPAMAuth(Port *port, const char *user, const char *password) return pam_no_password ? STATUS_EOF : STATUS_ERROR; } + pgstat_report_wait_start(WAIT_EVENT_PAM_ACCT_MGMT); retval = pam_acct_mgmt(pamh, 0); + pgstat_report_wait_end(); if (retval != PAM_SUCCESS) { @@ -2265,7 +2284,11 @@ InitializeLDAPConnection(Port *port, LDAP **ldap) } /* Look up a list of LDAP server hosts and port numbers */ - if (ldap_domain2hostlist(domain, &hostlist)) + pgstat_report_wait_start(WAIT_EVENT_LDAP_HOST_LOOKUP); + r = ldap_domain2hostlist(domain, &hostlist); + pgstat_report_wait_end(); + + if (r) { ereport(LOG, (errmsg("LDAP authentication could not find DNS SRV records for \"%s\"", @@ -2353,23 +2376,31 @@ InitializeLDAPConnection(Port *port, LDAP **ldap) (errmsg("could not set LDAP protocol version: %s", ldap_err2string(r)), errdetail_for_ldap(*ldap))); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_SET_OPTION); ldap_unbind(*ldap); + pgstat_report_wait_end(); return STATUS_ERROR; } if (port->hba->ldaptls) { + pgstat_report_wait_start(WAIT_EVENT_LDAP_START_TLS); #ifndef WIN32 - if ((r = ldap_start_tls_s(*ldap, NULL, NULL)) != LDAP_SUCCESS) + r = ldap_start_tls_s(*ldap, NULL, NULL); #else - if ((r = ldap_start_tls_s(*ldap, NULL, NULL, NULL, NULL)) != LDAP_SUCCESS) + r = ldap_start_tls_s(*ldap, NULL, NULL, NULL, NULL); #endif + pgstat_report_wait_end(); + + if (r != LDAP_SUCCESS) { ereport(LOG, (errmsg("could not start LDAP TLS session: %s", ldap_err2string(r)), errdetail_for_ldap(*ldap))); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_START_TLS); ldap_unbind(*ldap); + pgstat_report_wait_end(); return STATUS_ERROR; } } @@ -2513,7 +2544,9 @@ CheckLDAPAuth(Port *port) { ereport(LOG, (errmsg("invalid character in user name for LDAP authentication"))); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_NAME_CHECK); ldap_unbind(ldap); + pgstat_report_wait_end(); pfree(passwd); return STATUS_ERROR; } @@ -2523,9 +2556,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_LDAP_BIND_FOR_SEARCH); r = ldap_simple_bind_s(ldap, port->hba->ldapbinddn ? port->hba->ldapbinddn : "", port->hba->ldapbindpasswd ? ldap_password_hook(port->hba->ldapbindpasswd) : ""); + pgstat_report_wait_end(); + if (r != LDAP_SUCCESS) { ereport(LOG, @@ -2534,7 +2570,9 @@ CheckLDAPAuth(Port *port) server_name, ldap_err2string(r)), errdetail_for_ldap(ldap))); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_BIND_FOR_SEARCH); ldap_unbind(ldap); + pgstat_report_wait_end(); pfree(passwd); return STATUS_ERROR; } @@ -2548,6 +2586,8 @@ CheckLDAPAuth(Port *port) filter = psprintf("(uid=%s)", port->user_name); search_message = NULL; + + pgstat_report_wait_start(WAIT_EVENT_LDAP_SEARCH); r = ldap_search_s(ldap, port->hba->ldapbasedn, port->hba->ldapscope, @@ -2555,6 +2595,7 @@ CheckLDAPAuth(Port *port) attributes, 0, &search_message); + pgstat_report_wait_end(); if (r != LDAP_SUCCESS) { @@ -2564,7 +2605,9 @@ CheckLDAPAuth(Port *port) errdetail_for_ldap(ldap))); if (search_message != NULL) ldap_msgfree(search_message); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_SEARCH); ldap_unbind(ldap); + pgstat_report_wait_end(); pfree(passwd); pfree(filter); return STATUS_ERROR; @@ -2586,7 +2629,9 @@ CheckLDAPAuth(Port *port) count, filter, server_name, count))); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_COUNT_ENTRIES); ldap_unbind(ldap); + pgstat_report_wait_end(); pfree(passwd); pfree(filter); ldap_msgfree(search_message); @@ -2605,7 +2650,9 @@ CheckLDAPAuth(Port *port) filter, server_name, ldap_err2string(error)), errdetail_for_ldap(ldap))); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_GET_DN); ldap_unbind(ldap); + pgstat_report_wait_end(); pfree(passwd); pfree(filter); ldap_msgfree(search_message); @@ -2623,7 +2670,9 @@ CheckLDAPAuth(Port *port) port->user_name, port->hba->ldapsuffix ? port->hba->ldapsuffix : ""); + pgstat_report_wait_start(WAIT_EVENT_LDAP_BIND); r = ldap_simple_bind_s(ldap, fulluser, passwd); + pgstat_report_wait_end(); if (r != LDAP_SUCCESS) { @@ -2631,7 +2680,9 @@ CheckLDAPAuth(Port *port) (errmsg("LDAP login failed for user \"%s\" on server \"%s\": %s", fulluser, server_name, ldap_err2string(r)), errdetail_for_ldap(ldap))); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_BIND); ldap_unbind(ldap); + pgstat_report_wait_end(); pfree(passwd); pfree(fulluser); return STATUS_ERROR; @@ -2640,7 +2691,9 @@ CheckLDAPAuth(Port *port) /* Save the original bind DN as the authenticated identity. */ set_authn_id(port, fulluser); + pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_SUCCESS); ldap_unbind(ldap); + pgstat_report_wait_end(); pfree(passwd); pfree(fulluser); @@ -3072,8 +3125,12 @@ PerformRadiusTransaction(const char *server, const char *secret, const char *por return STATUS_ERROR; } - if (sendto(sock, radius_buffer, packetlength, 0, - serveraddrs[0].ai_addr, serveraddrs[0].ai_addrlen) < 0) + pgstat_report_wait_start(WAIT_EVENT_RADIUS_SENDTO); + r = sendto(sock, radius_buffer, packetlength, 0, + serveraddrs[0].ai_addr, serveraddrs[0].ai_addrlen); + pgstat_report_wait_end(); + + if (r < 0) { ereport(LOG, (errmsg("could not send RADIUS packet: %m"))); @@ -3121,7 +3178,10 @@ PerformRadiusTransaction(const char *server, const char *secret, const char *por FD_ZERO(&fdset); FD_SET(sock, &fdset); + pgstat_report_wait_start(WAIT_EVENT_RADIUS_WAIT); r = select(sock + 1, &fdset, NULL, NULL, &timeout); + pgstat_report_wait_end(); + if (r < 0) { if (errno == EINTR) @@ -3154,8 +3214,12 @@ PerformRadiusTransaction(const char *server, const char *secret, const char *por */ addrsize = sizeof(remoteaddr); + + pgstat_report_wait_start(WAIT_EVENT_RADIUS_RECVFROM); packetlength = recvfrom(sock, receive_buffer, RADIUS_BUFFER_SIZE, 0, (struct sockaddr *) &remoteaddr, &addrsize); + pgstat_report_wait_end(); + if (packetlength < 0) { ereport(LOG, diff --git a/src/backend/utils/activity/wait_event.c b/src/backend/utils/activity/wait_event.c index d9b8f34a3559..6cc3e1e7c7a0 100644 --- a/src/backend/utils/activity/wait_event.c +++ b/src/backend/utils/activity/wait_event.c @@ -34,6 +34,7 @@ static const char *pgstat_get_wait_client(WaitEventClient w); static const char *pgstat_get_wait_ipc(WaitEventIPC w); static const char *pgstat_get_wait_timeout(WaitEventTimeout w); static const char *pgstat_get_wait_io(WaitEventIO w); +static const char *pgstat_get_wait_auth(WaitEventAuth w); static uint32 local_my_wait_event_info; @@ -413,6 +414,9 @@ pgstat_get_wait_event_type(uint32 wait_event_info) case PG_WAIT_INJECTIONPOINT: event_type = "InjectionPoint"; break; + case PG_WAIT_AUTH: + event_type = "Auth"; + break; default: event_type = "???"; break; @@ -495,6 +499,13 @@ pgstat_get_wait_event(uint32 wait_event_info) event_name = pgstat_get_wait_io(w); break; } + case PG_WAIT_AUTH: + { + WaitEventAuth w = (WaitEventAuth) wait_event_info; + + event_name = pgstat_get_wait_auth(w); + break; + } default: event_name = "unknown wait event"; break; diff --git a/src/backend/utils/activity/wait_event_names.txt b/src/backend/utils/activity/wait_event_names.txt index 9fa12a555e83..223198382a09 100644 --- a/src/backend/utils/activity/wait_event_names.txt +++ b/src/backend/utils/activity/wait_event_names.txt @@ -163,6 +163,42 @@ XACT_GROUP_UPDATE "Waiting for the group leader to update transaction status at ABI_compatibility: +# +# Wait Events - Auth +# +# Use this category when a process is waiting for a third party to +# authenticate/authorize the user. +# + +Section: ClassName - WaitEventAuth + +GSSAPI_ACCEPT_SEC_CONTEXT "Waiting for a response from a Kerberos server via GSSAPI." +LDAP_BIND "Waiting for an LDAP bind operation to authenticate the user." +LDAP_BIND_FOR_SEARCH "Waiting for an LDAP bind operation to search the directory." +LDAP_HOST_LOOKUP "Waiting for DNS lookup of LDAP servers." +LDAP_SEARCH "Waiting for an LDAP search operation to complete." +LDAP_START_TLS "Waiting for an LDAP StartTLS exchange." +LDAP_UNBIND_AFTER_BIND "Waiting for an LDAP connection to be unbound after a simple bind failed." +LDAP_UNBIND_AFTER_BIND_FOR_SEARCH "Waiting for an LDAP connection to be unbound after a bind for search failed." +LDAP_UNBIND_AFTER_COUNT_ENTRIES "Waiting for an LDAP connection to be unbound after an entry count failed." +LDAP_UNBIND_AFTER_GET_DN "Waiting for an LDAP connection to be unbound after ldap_get_dn failed." +LDAP_UNBIND_AFTER_NAME_CHECK "Waiting for an LDAP connection to be unbound after a name check failed." +LDAP_UNBIND_AFTER_SEARCH "Waiting for an LDAP connection to be unbound after a bind+search failed." +LDAP_UNBIND_AFTER_SET_OPTION "Waiting for an LDAP connection to be unbound after ldap_set_option failed." +LDAP_UNBIND_AFTER_START_TLS "Waiting for an LDAP connection to be unbound after ldap_start_tls_s failed." +LDAP_UNBIND_SUCCESS "Waiting for a successful LDAP connection to be unbound." +PAM_ACCT_MGMT "Waiting for the PAM service to validate the user account." +PAM_AUTHENTICATE "Waiting for the PAM service to authenticate the user." +RADIUS_RECVFROM "Waiting for a recvfrom call during a RADIUS transaction." +RADIUS_SENDTO "Waiting for a sendto call during a RADIUS transaction." +RADIUS_WAIT "Waiting for a RADIUS server to respond." +SSPI_ACCEPT_SECURITY_CONTEXT "Waiting for a Windows security provider to accept the client's SSPI token." +SSPI_ACQUIRE_CREDENTIALS_HANDLE "Waiting for a Windows security provider to acquire server credentials for SSPI." +SSPI_LOOKUP_ACCOUNT_SID "Waiting for Windows to find the user's security identifier." +SSPI_TRANSLATE_NAME "Waiting for Windows to translate a Kerberos UPN." + +ABI_compatibility: + # # Wait Events - Timeout # diff --git a/src/include/utils/wait_event.h b/src/include/utils/wait_event.h index b8cb3e5a4309..3d995a9e5be7 100644 --- a/src/include/utils/wait_event.h +++ b/src/include/utils/wait_event.h @@ -25,6 +25,7 @@ #define PG_WAIT_TIMEOUT 0x09000000U #define PG_WAIT_IO 0x0A000000U #define PG_WAIT_INJECTIONPOINT 0x0B000000U +#define PG_WAIT_AUTH 0x0C000000U /* enums for wait events */ #include "utils/wait_event_types.h" diff --git a/src/test/regress/expected/sysviews.out b/src/test/regress/expected/sysviews.out index 83228cfca293..b94930658b0e 100644 --- a/src/test/regress/expected/sysviews.out +++ b/src/test/regress/expected/sysviews.out @@ -181,6 +181,7 @@ select type, count(*) > 0 as ok FROM pg_wait_events type | ok -----------+---- Activity | t + Auth | t BufferPin | t Client | t Extension | t @@ -189,7 +190,7 @@ select type, count(*) > 0 as ok FROM pg_wait_events LWLock | t Lock | t Timeout | t -(9 rows) +(10 rows) -- Test that the pg_timezone_names and pg_timezone_abbrevs views are -- more-or-less working. We can't test their contents in any great detail