since-v3.diff.txt

text/plain

Filename: since-v3.diff.txt
Type: text/plain
Part: 0
Message: Re: [PATCH] pg_stat_activity: make slow/hanging authentication more visible
1:  8f9315949e = 1:  64289b97e5 BackgroundPsql: handle empty query results
2:  7f404f5ee8 ! 2:  18a9531a25 Test::Cluster: let background_psql() work asynchronously
    @@ src/test/perl/PostgreSQL/Test/Cluster.pm: connection.
      
      =cut
     @@ src/test/perl/PostgreSQL/Test/Cluster.pm: sub background_psql
    - 		'-');
    + 		'-XAtq', '-d', $psql_connstr, '-f', '-');
      
      	$params{on_error_stop} = 1 unless defined $params{on_error_stop};
     +	$params{wait} = 1 unless defined $params{wait};
3:  a7a7551d09 ! 3:  c8071f91d8 pgstat: report in earlier with STATE_AUTHENTICATING
    @@ Metadata
     Author: Jacob Champion <jacob.champion@enterprisedb.com>
     
      ## Commit message ##
    -    pgstat: report in earlier with STATE_AUTHENTICATING
    +    pgstat: report in earlier with STATE_STARTING
     
    -    Add pgstat_bestart_pre_auth(), which reports an 'authenticating' state
    -    while waiting for backend initialization and client authentication to
    +    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.
     
    + ## doc/src/sgml/monitoring.sgml ##
    +@@ doc/src/sgml/monitoring.sgml: postgres   27093  0.0  0.0  30096  2752 ?        Ss   11:34   0:00 postgres: ser
    +        Current overall state of this backend.
    +        Possible values are:
    +        <itemizedlist>
    ++        <listitem>
    ++         <para>
    ++          <literal>starting</literal>: The backend is in initial startup. Client
    ++          authentication is performed during this phase.
    ++         </para>
    ++        </listitem>
    +         <listitem>
    +         <para>
    +           <literal>active</literal>: The backend is executing a query.
    +
      ## src/backend/utils/activity/backend_status.c ##
     @@ src/backend/utils/activity/backend_status.c: static int	localNumBackends = 0;
      static MemoryContext backendStatusSnapContext;
    @@ src/backend/utils/activity/backend_status.c: pgstat_bestart(void)
      #endif
      
     -	lbeentry.st_state = STATE_UNDEFINED;
    -+	lbeentry.st_state = pre_auth ? STATE_AUTHENTICATING : STATE_UNDEFINED;
    ++	lbeentry.st_state = pre_auth ? STATE_STARTING : STATE_UNDEFINED;
      	lbeentry.st_progress_command = PROGRESS_COMMAND_INVALID;
      	lbeentry.st_progress_command_target = InvalidOid;
      	lbeentry.st_query_id = UINT64CONST(0);
    @@ src/backend/utils/adt/pgstatfuncs.c: pg_stat_get_activity(PG_FUNCTION_ARGS)
      
      			switch (beentry->st_state)
      			{
    -+				case STATE_AUTHENTICATING:
    -+					values[4] = CStringGetTextDatum("authenticating");
    ++				case STATE_STARTING:
    ++					values[4] = CStringGetTextDatum("starting");
     +					break;
      				case STATE_IDLE:
      					values[4] = CStringGetTextDatum("idle");
    @@ src/backend/utils/init/postinit.c: InitPostgres(const char *in_dbname, Oid dboid
     +	pgstat_beinit();
     +
     +	/*
    -+	 * This is a convenient time to sketch in a partial pgstat entry. That way,
    -+	 * if LWLocks or third-party authentication should happen to hang, the DBA
    -+	 * will still be able to see what's going on. (A later call to
    ++	 * This is a convenient time to sketch in a partial pgstat entry. That
    ++	 * way, if LWLocks or third-party authentication should happen to hang,
    ++	 * the DBA will still be able to see what's going on. (A later call to
     +	 * pgstat_bestart() will fill in the rest of the status.)
     +	 */
     +	if (!bootstrap)
    @@ src/include/utils/backend_status.h
      typedef enum BackendState
      {
      	STATE_UNDEFINED,
    -+	STATE_AUTHENTICATING,
    ++	STATE_STARTING,
      	STATE_IDLE,
      	STATE_RUNNING,
      	STATE_IDLEINTRANSACTION,
    @@ src/test/authentication/t/007_injection_points.pl (new)
     +my $psql = $node->background_psql('postgres');
     +$psql->query_safe("SELECT injection_points_attach('init-pre-auth', 'wait')");
     +
    -+# From this point on, all new connections will hang in authentication. Use the
    -+# $psql connection handle for server interaction.
    ++# From this point on, all new connections will hang during startup, just before
    ++# authentication. Use the $psql connection handle for server interaction.
     +my $conn = $node->background_psql('postgres', wait => 0);
     +
     +# Wait for the connection to show up.
    @@ src/test/authentication/t/007_injection_points.pl (new)
     +while (1)
     +{
     +	$pid = $psql->query(
    -+		"SELECT pid FROM pg_stat_activity WHERE state = 'authenticating';");
    ++		"SELECT pid FROM pg_stat_activity WHERE state = 'starting';");
     +	last if $pid ne "";
     +
     +	usleep(500_000);
    @@ src/test/authentication/t/007_injection_points.pl (new)
     +# Make sure the pgstat entry is updated eventually.
     +while (1)
     +{
    -+	my $state = $psql->query(
    -+		"SELECT state FROM pg_stat_activity WHERE pid = $pid;");
    ++	my $state =
    ++	  $psql->query("SELECT state FROM pg_stat_activity WHERE pid = $pid;");
     +	last if $state eq "idle";
     +
     +	note "state for backend $pid is '$state'; waiting for 'idle'...";
4:  5c85c3e0e9 ! 4:  d14b97cb77 WIP: report external auth calls as wait events
    @@ Metadata
     Author: Jacob Champion <jacob.champion@enterprisedb.com>
     
      ## Commit message ##
    -    WIP: report external auth calls as wait events
    +    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.
    +    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.
     
    -    TODO:
    -    - don't abuse the IPC wait event group like this
    -    - test
    +    Discussion: https://postgr.es/m/CAOYmi%2B%3D60deN20WDyCoHCiecgivJxr%3D98s7s7-C8SkXwrCfHXg%40mail.gmail.com
    +
    + ## doc/src/sgml/monitoring.sgml ##
    +@@ doc/src/sgml/monitoring.sgml: postgres   27093  0.0  0.0  30096  2752 ?        Ss   11:34   0:00 postgres: ser
    +        see <xref linkend="wait-event-activity-table"/>.
    +       </entry>
    +      </row>
    ++     <row>
    ++      <entry><literal>Auth</literal></entry>
    ++      <entry>The server process is waiting for an external system to
    ++       authenticate and/or authorize the client connection.
    ++       <literal>wait_event</literal> will identify the specific wait point;
    ++       see <xref linkend="wait-event-auth-table"/>.
    ++      </entry>
    ++     </row>
    +      <row>
    +       <entry><literal>BufferPin</literal></entry>
    +       <entry>The server process is waiting for exclusive access to
     
      ## src/backend/libpq/auth.c ##
     @@
    @@ src/backend/libpq/auth.c: 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);
    ++		pgstat_report_wait_start(WAIT_EVENT_GSSAPI_ACCEPT_SEC_CONTEXT);
      		maj_stat = gss_accept_sec_context(&min_stat,
      										  &port->gss->ctx,
      										  port->gss->cred,
    @@ src/backend/libpq/auth.c: pg_SSPI_recvauth(Port *port)
      	/*
      	 * Acquire a handle to the server credentials.
      	 */
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
    ++	pgstat_report_wait_start(WAIT_EVENT_SSPI_ACQUIRE_CREDENTIALS_HANDLE);
      	r = AcquireCredentialsHandle(NULL,
      								 "negotiate",
      								 SECPKG_CRED_INBOUND,
    @@ src/backend/libpq/auth.c: 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);
    ++		pgstat_report_wait_start(WAIT_EVENT_SSPI_ACCEPT_SECURITY_CONTEXT);
      		r = AcceptSecurityContext(&sspicred,
      								  sspictx,
      								  &inbuf,
    @@ src/backend/libpq/auth.c: pg_SSPI_recvauth(Port *port)
      
      	CloseHandle(token);
      
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
    ++	pgstat_report_wait_start(WAIT_EVENT_SSPI_LOOKUP_ACCOUNT_SID);
      	if (!LookupAccountSid(NULL, tokenuser->User.Sid, accountname, &accountnamesize,
      						  domainname, &domainnamesize, &accountnameuse))
      		ereport(ERROR,
    @@ src/backend/libpq/auth.c: pg_SSPI_recvauth(Port *port)
     -											  port->hba->upn_username);
     +		int			status;
     +
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_SSPI);
    ++		pgstat_report_wait_start(WAIT_EVENT_SSPI_MAKE_UPN);
     +		status = pg_SSPI_make_upn(accountname, sizeof(accountname),
     +								  domainname, sizeof(domainname),
     +								  port->hba->upn_username);
    @@ src/backend/libpq/auth.c: CheckPAMAuth(Port *port, const char *user, const char
      		return STATUS_ERROR;
      	}
      
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_PAM);
    ++	pgstat_report_wait_start(WAIT_EVENT_PAM_AUTHENTICATE);
      	retval = pam_authenticate(pamh, 0);
     +	pgstat_report_wait_end();
      
    @@ src/backend/libpq/auth.c: CheckPAMAuth(Port *port, const char *user, const char
      		return pam_no_password ? STATUS_EOF : STATUS_ERROR;
      	}
      
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_PAM);
    ++	pgstat_report_wait_start(WAIT_EVENT_PAM_ACCT_MGMT);
      	retval = pam_acct_mgmt(pamh, 0);
     +	pgstat_report_wait_end();
      
    @@ src/backend/libpq/auth.c: CheckLDAPAuth(Port *port)
      		return STATUS_EOF;		/* client wouldn't send password */
      
     -	if (InitializeLDAPConnection(port, &ldap) == STATUS_ERROR)
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
    ++	pgstat_report_wait_start(WAIT_EVENT_LDAP_INITIALIZE);
     +	r = InitializeLDAPConnection(port, &ldap);
     +	pgstat_report_wait_end();
     +
    @@ src/backend/libpq/auth.c: 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);
    ++		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) : "");
    @@ src/backend/libpq/auth.c: CheckLDAPAuth(Port *port)
      
      		search_message = NULL;
     +
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
    ++		pgstat_report_wait_start(WAIT_EVENT_LDAP_SEARCH);
      		r = ldap_search_s(ldap,
      						  port->hba->ldapbasedn,
      						  port->hba->ldapscope,
    @@ src/backend/libpq/auth.c: CheckLDAPAuth(Port *port)
      							port->user_name,
      							port->hba->ldapsuffix ? port->hba->ldapsuffix : "");
      
    -+	pgstat_report_wait_start(WAIT_EVENT_AUTHN_LDAP);
    ++	pgstat_report_wait_start(WAIT_EVENT_LDAP_BIND);
      	r = ldap_simple_bind_s(ldap, fulluser, passwd);
     +	pgstat_report_wait_end();
      
    @@ src/backend/libpq/auth.c: CheckRADIUSAuth(Port *port)
     -												   passwd);
     +		int			ret;
     +
    -+		pgstat_report_wait_start(WAIT_EVENT_AUTHN_RADIUS);
    ++		pgstat_report_wait_start(WAIT_EVENT_RADIUS_TRANSACTION);
     +		ret = PerformRadiusTransaction(lfirst(server),
     +									   lfirst(secrets),
     +									   radiusports ? lfirst(radiusports) : NULL,
    @@ src/backend/libpq/auth.c: CheckRADIUSAuth(Port *port)
      		/*------
      		 * STATUS_OK = Login OK
     
    + ## src/backend/utils/activity/wait_event.c ##
    +@@ src/backend/utils/activity/wait_event.c: 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;
    +@@ src/backend/utils/activity/wait_event.c: 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;
    +@@ src/backend/utils/activity/wait_event.c: 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;
    +
      ## src/backend/utils/activity/wait_event_names.txt ##
    -@@ src/backend/utils/activity/wait_event_names.txt: 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."
    +@@ src/backend/utils/activity/wait_event_names.txt: 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_INITIALIZE	"Waiting to initialize an LDAP connection."
    ++LDAP_SEARCH	"Waiting for an LDAP search operation to complete."
    ++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."
    ++RADIUS_TRANSACTION	"Waiting for a RADIUS transaction to complete."
    ++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 account SID."
    ++SSPI_MAKE_UPN	"Waiting for Windows to translate a Kerberos UPN."
    ++
    ++ABI_compatibility:
    ++
    + #
    + # Wait Events - Timeout
    + #
    +
    + ## src/include/utils/wait_event.h ##
    +@@
    + #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"
    +
    + ## src/test/regress/expected/sysviews.out ##
    +@@ src/test/regress/expected/sysviews.out: select type, count(*) > 0 as ok FROM pg_wait_events
    +    type    | ok 
    + -----------+----
    +  Activity  | t
    ++ Auth      | t
    +  BufferPin | t
    +  Client    | t
    +  Extension | t
    +@@ src/test/regress/expected/sysviews.out: 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