Location via proxy:   [ UP ]  
[Report a bug]   [Manage cookies]                
Skip to content

Commit 22a9c06

Browse files
author
Commitfest Bot
committed
[CF 4974] v11 - pg_stat_activity: make slow/hanging authentication more visible
This branch was automatically generated by a robot using patches from an email thread registered at: https://commitfest.postgresql.org/patch/4974 The branch will be overwritten each time a new patch version is posted to the thread, and also periodically to check for bitrot caused by changes on the master branch. Patch(es): https://www.postgresql.org/message-id/CAOYmi+kHY8HZ5RdXGT1bVZzkAq7ta=--YSGehLr35HRjF4Fyug@mail.gmail.com Author(s): Jacob Champion
2 parents 1d617a2 + 23c13ca commit 22a9c06

File tree

6 files changed

+127
-6
lines changed

6 files changed

+127
-6
lines changed

‎doc/src/sgml/monitoring.sgml

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1045,6 +1045,14 @@ postgres 27093 0.0 0.0 30096 2752 ? Ss 11:34 0:00 postgres: ser
10451045
see <xref linkend="wait-event-activity-table"/>.
10461046
</entry>
10471047
</row>
1048+
<row>
1049+
<entry><literal>Auth</literal></entry>
1050+
<entry>The server process is waiting for an external system to
1051+
authenticate and/or authorize the client connection.
1052+
<literal>wait_event</literal> will identify the specific wait point;
1053+
see <xref linkend="wait-event-auth-table"/>.
1054+
</entry>
1055+
</row>
10481056
<row>
10491057
<entry><literal>BufferPin</literal></entry>
10501058
<entry>The server process is waiting for exclusive access to

‎src/backend/libpq/auth.c

Lines changed: 69 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,7 @@
4040
#include "storage/ipc.h"
4141
#include "tcop/backend_startup.h"
4242
#include "utils/memutils.h"
43+
#include "utils/wait_event.h"
4344

4445
/*----------------------------------------------------------------
4546
* Global authentication functions
@@ -993,6 +994,7 @@ pg_GSS_recvauth(Port *port)
993994
elog(DEBUG4, "processing received GSS token of length %u",
994995
(unsigned int) gbuf.length);
995996

997+
pgstat_report_wait_start(WAIT_EVENT_GSSAPI_ACCEPT_SEC_CONTEXT);
996998
maj_stat = gss_accept_sec_context(&min_stat,
997999
&port->gss->ctx,
9981000
port->gss->cred,
@@ -1004,6 +1006,7 @@ pg_GSS_recvauth(Port *port)
10041006
&gflags,
10051007
NULL,
10061008
pg_gss_accept_delegation ? &delegated_creds : NULL);
1009+
pgstat_report_wait_end();
10071010

10081011
/* gbuf no longer used */
10091012
pfree(buf.data);
@@ -1215,6 +1218,7 @@ pg_SSPI_recvauth(Port *port)
12151218
/*
12161219
* Acquire a handle to the server credentials.
12171220
*/
1221+
pgstat_report_wait_start(WAIT_EVENT_SSPI_ACQUIRE_CREDENTIALS_HANDLE);
12181222
r = AcquireCredentialsHandle(NULL,
12191223
"negotiate",
12201224
SECPKG_CRED_INBOUND,
@@ -1224,6 +1228,8 @@ pg_SSPI_recvauth(Port *port)
12241228
NULL,
12251229
&sspicred,
12261230
&expiry);
1231+
pgstat_report_wait_end();
1232+
12271233
if (r != SEC_E_OK)
12281234
pg_SSPI_error(ERROR, _("could not acquire SSPI credentials"), r);
12291235

@@ -1289,6 +1295,7 @@ pg_SSPI_recvauth(Port *port)
12891295
elog(DEBUG4, "processing received SSPI token of length %u",
12901296
(unsigned int) buf.len);
12911297

1298+
pgstat_report_wait_start(WAIT_EVENT_SSPI_ACCEPT_SECURITY_CONTEXT);
12921299
r = AcceptSecurityContext(&sspicred,
12931300
sspictx,
12941301
&inbuf,
@@ -1298,6 +1305,7 @@ pg_SSPI_recvauth(Port *port)
12981305
&outbuf,
12991306
&contextattr,
13001307
NULL);
1308+
pgstat_report_wait_end();
13011309

13021310
/* input buffer no longer used */
13031311
pfree(buf.data);
@@ -1395,11 +1403,13 @@ pg_SSPI_recvauth(Port *port)
13951403

13961404
CloseHandle(token);
13971405

1406+
pgstat_report_wait_start(WAIT_EVENT_SSPI_LOOKUP_ACCOUNT_SID);
13981407
if (!LookupAccountSid(NULL, tokenuser->User.Sid, accountname, &accountnamesize,
13991408
domainname, &domainnamesize, &accountnameuse))
14001409
ereport(ERROR,
14011410
(errmsg_internal("could not look up account SID: error code %lu",
14021411
GetLastError())));
1412+
pgstat_report_wait_end();
14031413

14041414
free(tokenuser);
14051415

@@ -1496,8 +1506,11 @@ pg_SSPI_make_upn(char *accountname,
14961506
*/
14971507

14981508
samname = psprintf("%s\\%s", domainname, accountname);
1509+
1510+
pgstat_report_wait_start(WAIT_EVENT_SSPI_TRANSLATE_NAME);
14991511
res = TranslateName(samname, NameSamCompatible, NameUserPrincipal,
15001512
NULL, &upnamesize);
1513+
pgstat_report_wait_end();
15011514

15021515
if ((!res && GetLastError() != ERROR_INSUFFICIENT_BUFFER)
15031516
|| upnamesize == 0)
@@ -1512,8 +1525,10 @@ pg_SSPI_make_upn(char *accountname,
15121525
/* upnamesize includes the terminating NUL. */
15131526
upname = palloc(upnamesize);
15141527

1528+
pgstat_report_wait_start(WAIT_EVENT_SSPI_TRANSLATE_NAME);
15151529
res = TranslateName(samname, NameSamCompatible, NameUserPrincipal,
15161530
upname, &upnamesize);
1531+
pgstat_report_wait_end();
15171532

15181533
pfree(samname);
15191534
if (res)
@@ -2112,7 +2127,9 @@ CheckPAMAuth(Port *port, const char *user, const char *password)
21122127
return STATUS_ERROR;
21132128
}
21142129

2130+
pgstat_report_wait_start(WAIT_EVENT_PAM_AUTHENTICATE);
21152131
retval = pam_authenticate(pamh, 0);
2132+
pgstat_report_wait_end();
21162133

21172134
if (retval != PAM_SUCCESS)
21182135
{
@@ -2125,7 +2142,9 @@ CheckPAMAuth(Port *port, const char *user, const char *password)
21252142
return pam_no_password ? STATUS_EOF : STATUS_ERROR;
21262143
}
21272144

2145+
pgstat_report_wait_start(WAIT_EVENT_PAM_ACCT_MGMT);
21282146
retval = pam_acct_mgmt(pamh, 0);
2147+
pgstat_report_wait_end();
21292148

21302149
if (retval != PAM_SUCCESS)
21312150
{
@@ -2265,7 +2284,11 @@ InitializeLDAPConnection(Port *port, LDAP **ldap)
22652284
}
22662285

22672286
/* Look up a list of LDAP server hosts and port numbers */
2268-
if (ldap_domain2hostlist(domain, &hostlist))
2287+
pgstat_report_wait_start(WAIT_EVENT_LDAP_HOST_LOOKUP);
2288+
r = ldap_domain2hostlist(domain, &hostlist);
2289+
pgstat_report_wait_end();
2290+
2291+
if (r)
22692292
{
22702293
ereport(LOG,
22712294
(errmsg("LDAP authentication could not find DNS SRV records for \"%s\"",
@@ -2353,23 +2376,31 @@ InitializeLDAPConnection(Port *port, LDAP **ldap)
23532376
(errmsg("could not set LDAP protocol version: %s",
23542377
ldap_err2string(r)),
23552378
errdetail_for_ldap(*ldap)));
2379+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_SET_OPTION);
23562380
ldap_unbind(*ldap);
2381+
pgstat_report_wait_end();
23572382
return STATUS_ERROR;
23582383
}
23592384

23602385
if (port->hba->ldaptls)
23612386
{
2387+
pgstat_report_wait_start(WAIT_EVENT_LDAP_START_TLS);
23622388
#ifndef WIN32
2363-
if ((r = ldap_start_tls_s(*ldap, NULL, NULL)) != LDAP_SUCCESS)
2389+
r = ldap_start_tls_s(*ldap, NULL, NULL);
23642390
#else
2365-
if ((r = ldap_start_tls_s(*ldap, NULL, NULL, NULL, NULL)) != LDAP_SUCCESS)
2391+
r = ldap_start_tls_s(*ldap, NULL, NULL, NULL, NULL);
23662392
#endif
2393+
pgstat_report_wait_end();
2394+
2395+
if (r != LDAP_SUCCESS)
23672396
{
23682397
ereport(LOG,
23692398
(errmsg("could not start LDAP TLS session: %s",
23702399
ldap_err2string(r)),
23712400
errdetail_for_ldap(*ldap)));
2401+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_START_TLS);
23722402
ldap_unbind(*ldap);
2403+
pgstat_report_wait_end();
23732404
return STATUS_ERROR;
23742405
}
23752406
}
@@ -2513,7 +2544,9 @@ CheckLDAPAuth(Port *port)
25132544
{
25142545
ereport(LOG,
25152546
(errmsg("invalid character in user name for LDAP authentication")));
2547+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_NAME_CHECK);
25162548
ldap_unbind(ldap);
2549+
pgstat_report_wait_end();
25172550
pfree(passwd);
25182551
return STATUS_ERROR;
25192552
}
@@ -2523,9 +2556,12 @@ CheckLDAPAuth(Port *port)
25232556
* Bind with a pre-defined username/password (if available) for
25242557
* searching. If none is specified, this turns into an anonymous bind.
25252558
*/
2559+
pgstat_report_wait_start(WAIT_EVENT_LDAP_BIND_FOR_SEARCH);
25262560
r = ldap_simple_bind_s(ldap,
25272561
port->hba->ldapbinddn ? port->hba->ldapbinddn : "",
25282562
port->hba->ldapbindpasswd ? ldap_password_hook(port->hba->ldapbindpasswd) : "");
2563+
pgstat_report_wait_end();
2564+
25292565
if (r != LDAP_SUCCESS)
25302566
{
25312567
ereport(LOG,
@@ -2534,7 +2570,9 @@ CheckLDAPAuth(Port *port)
25342570
server_name,
25352571
ldap_err2string(r)),
25362572
errdetail_for_ldap(ldap)));
2573+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_BIND_FOR_SEARCH);
25372574
ldap_unbind(ldap);
2575+
pgstat_report_wait_end();
25382576
pfree(passwd);
25392577
return STATUS_ERROR;
25402578
}
@@ -2548,13 +2586,16 @@ CheckLDAPAuth(Port *port)
25482586
filter = psprintf("(uid=%s)", port->user_name);
25492587

25502588
search_message = NULL;
2589+
2590+
pgstat_report_wait_start(WAIT_EVENT_LDAP_SEARCH);
25512591
r = ldap_search_s(ldap,
25522592
port->hba->ldapbasedn,
25532593
port->hba->ldapscope,
25542594
filter,
25552595
attributes,
25562596
0,
25572597
&search_message);
2598+
pgstat_report_wait_end();
25582599

25592600
if (r != LDAP_SUCCESS)
25602601
{
@@ -2564,7 +2605,9 @@ CheckLDAPAuth(Port *port)
25642605
errdetail_for_ldap(ldap)));
25652606
if (search_message != NULL)
25662607
ldap_msgfree(search_message);
2608+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_SEARCH);
25672609
ldap_unbind(ldap);
2610+
pgstat_report_wait_end();
25682611
pfree(passwd);
25692612
pfree(filter);
25702613
return STATUS_ERROR;
@@ -2586,7 +2629,9 @@ CheckLDAPAuth(Port *port)
25862629
count,
25872630
filter, server_name, count)));
25882631

2632+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_COUNT_ENTRIES);
25892633
ldap_unbind(ldap);
2634+
pgstat_report_wait_end();
25902635
pfree(passwd);
25912636
pfree(filter);
25922637
ldap_msgfree(search_message);
@@ -2605,7 +2650,9 @@ CheckLDAPAuth(Port *port)
26052650
filter, server_name,
26062651
ldap_err2string(error)),
26072652
errdetail_for_ldap(ldap)));
2653+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_GET_DN);
26082654
ldap_unbind(ldap);
2655+
pgstat_report_wait_end();
26092656
pfree(passwd);
26102657
pfree(filter);
26112658
ldap_msgfree(search_message);
@@ -2623,15 +2670,19 @@ CheckLDAPAuth(Port *port)
26232670
port->user_name,
26242671
port->hba->ldapsuffix ? port->hba->ldapsuffix : "");
26252672

2673+
pgstat_report_wait_start(WAIT_EVENT_LDAP_BIND);
26262674
r = ldap_simple_bind_s(ldap, fulluser, passwd);
2675+
pgstat_report_wait_end();
26272676

26282677
if (r != LDAP_SUCCESS)
26292678
{
26302679
ereport(LOG,
26312680
(errmsg("LDAP login failed for user \"%s\" on server \"%s\": %s",
26322681
fulluser, server_name, ldap_err2string(r)),
26332682
errdetail_for_ldap(ldap)));
2683+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_AFTER_BIND);
26342684
ldap_unbind(ldap);
2685+
pgstat_report_wait_end();
26352686
pfree(passwd);
26362687
pfree(fulluser);
26372688
return STATUS_ERROR;
@@ -2640,7 +2691,9 @@ CheckLDAPAuth(Port *port)
26402691
/* Save the original bind DN as the authenticated identity. */
26412692
set_authn_id(port, fulluser);
26422693

2694+
pgstat_report_wait_start(WAIT_EVENT_LDAP_UNBIND_SUCCESS);
26432695
ldap_unbind(ldap);
2696+
pgstat_report_wait_end();
26442697
pfree(passwd);
26452698
pfree(fulluser);
26462699

@@ -3072,8 +3125,12 @@ PerformRadiusTransaction(const char *server, const char *secret, const char *por
30723125
return STATUS_ERROR;
30733126
}
30743127

3075-
if (sendto(sock, radius_buffer, packetlength, 0,
3076-
serveraddrs[0].ai_addr, serveraddrs[0].ai_addrlen) < 0)
3128+
pgstat_report_wait_start(WAIT_EVENT_RADIUS_SENDTO);
3129+
r = sendto(sock, radius_buffer, packetlength, 0,
3130+
serveraddrs[0].ai_addr, serveraddrs[0].ai_addrlen);
3131+
pgstat_report_wait_end();
3132+
3133+
if (r < 0)
30773134
{
30783135
ereport(LOG,
30793136
(errmsg("could not send RADIUS packet: %m")));
@@ -3121,7 +3178,10 @@ PerformRadiusTransaction(const char *server, const char *secret, const char *por
31213178
FD_ZERO(&fdset);
31223179
FD_SET(sock, &fdset);
31233180

3181+
pgstat_report_wait_start(WAIT_EVENT_RADIUS_WAIT);
31243182
r = select(sock + 1, &fdset, NULL, NULL, &timeout);
3183+
pgstat_report_wait_end();
3184+
31253185
if (r < 0)
31263186
{
31273187
if (errno == EINTR)
@@ -3154,8 +3214,12 @@ PerformRadiusTransaction(const char *server, const char *secret, const char *por
31543214
*/
31553215

31563216
addrsize = sizeof(remoteaddr);
3217+
3218+
pgstat_report_wait_start(WAIT_EVENT_RADIUS_RECVFROM);
31573219
packetlength = recvfrom(sock, receive_buffer, RADIUS_BUFFER_SIZE, 0,
31583220
(struct sockaddr *) &remoteaddr, &addrsize);
3221+
pgstat_report_wait_end();
3222+
31593223
if (packetlength < 0)
31603224
{
31613225
ereport(LOG,

‎src/backend/utils/activity/wait_event.c

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@ static const char *pgstat_get_wait_client(WaitEventClient w);
3434
static const char *pgstat_get_wait_ipc(WaitEventIPC w);
3535
static const char *pgstat_get_wait_timeout(WaitEventTimeout w);
3636
static const char *pgstat_get_wait_io(WaitEventIO w);
37+
static const char *pgstat_get_wait_auth(WaitEventAuth w);
3738

3839

3940
static uint32 local_my_wait_event_info;
@@ -413,6 +414,9 @@ pgstat_get_wait_event_type(uint32 wait_event_info)
413414
case PG_WAIT_INJECTIONPOINT:
414415
event_type = "InjectionPoint";
415416
break;
417+
case PG_WAIT_AUTH:
418+
event_type = "Auth";
419+
break;
416420
default:
417421
event_type = "???";
418422
break;
@@ -495,6 +499,13 @@ pgstat_get_wait_event(uint32 wait_event_info)
495499
event_name = pgstat_get_wait_io(w);
496500
break;
497501
}
502+
case PG_WAIT_AUTH:
503+
{
504+
WaitEventAuth w = (WaitEventAuth) wait_event_info;
505+
506+
event_name = pgstat_get_wait_auth(w);
507+
break;
508+
}
498509
default:
499510
event_name = "unknown wait event";
500511
break;

‎src/backend/utils/activity/wait_event_names.txt

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -163,6 +163,42 @@ XACT_GROUP_UPDATE "Waiting for the group leader to update transaction status at
163163

164164
ABI_compatibility:
165165

166+
#
167+
# Wait Events - Auth
168+
#
169+
# Use this category when a process is waiting for a third party to
170+
# authenticate/authorize the user.
171+
#
172+
173+
Section: ClassName - WaitEventAuth
174+
175+
GSSAPI_ACCEPT_SEC_CONTEXT "Waiting for a response from a Kerberos server via GSSAPI."
176+
LDAP_BIND "Waiting for an LDAP bind operation to authenticate the user."
177+
LDAP_BIND_FOR_SEARCH "Waiting for an LDAP bind operation to search the directory."
178+
LDAP_HOST_LOOKUP "Waiting for DNS lookup of LDAP servers."
179+
LDAP_SEARCH "Waiting for an LDAP search operation to complete."
180+
LDAP_START_TLS "Waiting for an LDAP StartTLS exchange."
181+
LDAP_UNBIND_AFTER_BIND "Waiting for an LDAP connection to be unbound after a simple bind failed."
182+
LDAP_UNBIND_AFTER_BIND_FOR_SEARCH "Waiting for an LDAP connection to be unbound after a bind for search failed."
183+
LDAP_UNBIND_AFTER_COUNT_ENTRIES "Waiting for an LDAP connection to be unbound after an entry count failed."
184+
LDAP_UNBIND_AFTER_GET_DN "Waiting for an LDAP connection to be unbound after ldap_get_dn failed."
185+
LDAP_UNBIND_AFTER_NAME_CHECK "Waiting for an LDAP connection to be unbound after a name check failed."
186+
LDAP_UNBIND_AFTER_SEARCH "Waiting for an LDAP connection to be unbound after a bind+search failed."
187+
LDAP_UNBIND_AFTER_SET_OPTION "Waiting for an LDAP connection to be unbound after ldap_set_option failed."
188+
LDAP_UNBIND_AFTER_START_TLS "Waiting for an LDAP connection to be unbound after ldap_start_tls_s failed."
189+
LDAP_UNBIND_SUCCESS "Waiting for a successful LDAP connection to be unbound."
190+
PAM_ACCT_MGMT "Waiting for the PAM service to validate the user account."
191+
PAM_AUTHENTICATE "Waiting for the PAM service to authenticate the user."
192+
RADIUS_RECVFROM "Waiting for a <function>recvfrom</function> call during a RADIUS transaction."
193+
RADIUS_SENDTO "Waiting for a <function>sendto</function> call during a RADIUS transaction."
194+
RADIUS_WAIT "Waiting for a RADIUS server to respond."
195+
SSPI_ACCEPT_SECURITY_CONTEXT "Waiting for a Windows security provider to accept the client's SSPI token."
196+
SSPI_ACQUIRE_CREDENTIALS_HANDLE "Waiting for a Windows security provider to acquire server credentials for SSPI."
197+
SSPI_LOOKUP_ACCOUNT_SID "Waiting for Windows to find the user's security identifier."
198+
SSPI_TRANSLATE_NAME "Waiting for Windows to translate a Kerberos UPN."
199+
200+
ABI_compatibility:
201+
166202
#
167203
# Wait Events - Timeout
168204
#

0 commit comments

Comments
 (0)