oauth: Let validators provide failure DETAILs

At the moment, the only way for a validator module to report error
details on failure is to log them separately before returning from
validate_cb. Independently of that problem, the ereport() calls that we
make during validation failure partially duplicate some of the work of
auth_failed().

The end result is overly verbose and confusing for readers of the logs:

    [768233] LOG:  [my_validator] bad signature in bearer token
    [768233] LOG:  OAuth bearer authentication failed for user "jacob"
    [768233] DETAIL:  Validator failed to authorize the provided token.
    [768233] FATAL:  OAuth bearer authentication failed for user "jacob"
    [768233] DETAIL:  Connection matched file ".../pg_hba.conf" line ...

Solve both problems by making use of the existing logdetail pointer
that's provided by ClientAuthentication. Validator modules may set
ValidatorModuleResult->error_detail to override our default generic
message.

The end result looks something like

    [242284] FATAL:  OAuth bearer authentication failed for user "jacob"
    [242284] DETAIL:  [my_validator] bad signature in bearer token
        Connection matched file ".../pg_hba.conf" line ...

Reported-by: Álvaro Herrera <alvherre@kurilemu.de>
Reported-by: Zsolt Parragi <zsolt.parragi@percona.com>
Reviewed-by: Chao Li <li.evan.chao@gmail.com>
Reviewed-by: Daniel Gustafsson <daniel@yesql.se>
Reviewed-by: Zsolt Parragi <zsolt.parragi@percona.com>
Discussion: https://postgr.es/m/202601241015.y5uvxd7oxnfs%40alvherre.pgsql

doc/src/sgml/oauth-validators.sgml

@@ -192,11 +192,20 @@
      <term>Logging</term>
      <listitem>
       <para>
-       Modules may use the same <link linkend="error-message-reporting">logging
+       To simply log the reason for a validation failure, modules may set the
+       freeform <structfield>error_detail</structfield> field during the
+       <link linkend="oauth-validator-callback-validate">validate callback</link>.
+       (<xref linkend="error-style-guide"/> has guidelines for writing good
+       <literal>DETAIL</literal> messages.) <structfield>error_detail</structfield>
+       is printed only to the server log, as part of the final authentication
+       failure message, and it is not shared with the client.
+      </para>
+      <para>
+       Modules may also use the same <link linkend="error-message-reporting">logging
        facilities</link> as standard extensions; however, the rules for emitting
        log entries to the client are subtly different during the authentication
        phase of the connection. Generally speaking, modules should log
-       verification problems at the <symbol>COMMERROR</symbol> level and return
+       problems at the <symbol>COMMERROR</symbol> level and return
        normally, instead of using <symbol>ERROR</symbol>/<symbol>FATAL</symbol>
        to unwind the stack, to avoid leaking information to unauthenticated
        clients.
@@ -370,6 +379,7 @@ typedef struct ValidatorModuleResult
 {
     bool        authorized;
     char       *authn_id;
+    char       *error_detail;
 } ValidatorModuleResult;
 </programlisting>
 
@@ -387,6 +397,15 @@ typedef struct ValidatorModuleResult
     Otherwise the validator should return <literal>true</literal> to indicate
     that it has processed the token and made an authorization decision.
    </para>
+   <para>
+    In either failure case (validation error or internal error) the module may
+    store a user-readable reason for the failure in <structfield>result->error_detail</structfield>.
+    This will be printed to the server logs (not sent to the client) as a
+    <literal>DETAIL</literal> entry for the authentication failure. The memory
+    pointed to by <structfield>error_detail</structfield> may be either palloc'd
+    or of static duration. <structfield>error_detail</structfield> is ignored
+    on success.
+   </para>
    <para>
     The behavior after <function>validate_cb</function> returns depends on the
     specific HBA setup.  Normally, the <structfield>result->authn_id</structfield> user

src/backend/libpq/auth-oauth.c

@@ -74,7 +74,7 @@ struct oauth_ctx
 static char *sanitize_char(char c);
 static char *parse_kvpairs_for_auth(char **input);
 static void generate_error_response(struct oauth_ctx *ctx, char **output, int *outputlen);
-static bool validate(Port *port, const char *auth);
+static bool validate(Port *port, const char *auth, const char **logdetail);
 
 /* Constants seen in an OAUTHBEARER client initial response. */
 #define KVSEP 0x01				/* separator byte for key/value pairs */
@@ -305,7 +305,7 @@ oauth_exchange(void *opaq, const char *input, int inputlen,
 		ctx->state = OAUTH_STATE_ERROR_DISCOVERY;
 		status = PG_SASL_EXCHANGE_CONTINUE;
 	}
-	else if (!validate(ctx->port, auth))
+	else if (!validate(ctx->port, auth, logdetail))
 	{
 		generate_error_response(ctx, output, outputlen);
 
@@ -650,7 +650,7 @@ validate_token_format(const char *header)
  * authorization. Returns true if validation succeeds.
  */
 static bool
-validate(Port *port, const char *auth)
+validate(Port *port, const char *auth, const char **logdetail)
 {
 	int			map_status;
 	ValidatorModuleResult *ret;
@@ -677,7 +677,10 @@ validate(Port *port, const char *auth)
 	{
 		ereport(WARNING,
 				errcode(ERRCODE_INTERNAL_ERROR),
-				errmsg("internal error in OAuth validator module"));
+				errmsg("internal error in OAuth validator module"),
+				ret->error_detail ? errdetail_log("%s", ret->error_detail) : 0);
+
+		*logdetail = ret->error_detail;
 		return false;
 	}
 
@@ -690,10 +693,10 @@ validate(Port *port, const char *auth)
 
 	if (!ret->authorized)
 	{
-		ereport(LOG,
-				errmsg("OAuth bearer authentication failed for user \"%s\"",
-					   port->user_name),
-				errdetail_log("Validator failed to authorize the provided token."));
+		if (ret->error_detail)
+			*logdetail = ret->error_detail;
+		else
+			*logdetail = _("Validator failed to authorize the provided token.");
 
 		status = false;
 		goto cleanup;
@@ -714,10 +717,7 @@ validate(Port *port, const char *auth)
 	/* Make sure the validator authenticated the user. */
 	if (ret->authn_id == NULL || ret->authn_id[0] == '\0')
 	{
-		ereport(LOG,
-				errmsg("OAuth bearer authentication failed for user \"%s\"",
-					   port->user_name),
-				errdetail_log("Validator provided no identity."));
+		*logdetail = _("Validator provided no identity.");
 
 		status = false;
 		goto cleanup;

src/backend/libpq/auth.c

@@ -639,7 +639,7 @@ ClientAuthentication(Port *port)
 			status = STATUS_OK;
 			break;
 		case uaOAuth:
-			status = CheckSASLAuth(&pg_be_oauth_mech, port, NULL, NULL,
+			status = CheckSASLAuth(&pg_be_oauth_mech, port, NULL, &logdetail,
 								   &abandoned);
 			break;
 	}

src/include/libpq/oauth.h

@@ -49,6 +49,20 @@ typedef struct ValidatorModuleResult
 	 * delegation. See the validator module documentation for details.
 	 */
 	char	   *authn_id;
+
+	/*
+	 * When validation fails, this may optionally be set to a string
+	 * containing an explanation for the failure. It will be sent to the
+	 * server log only; it is not provided to the client, and it's ignored if
+	 * validation succeeds.
+	 *
+	 * This description will be attached to the final authentication failure
+	 * message in the logs, as a DETAIL, which may be preferable to separate
+	 * ereport() calls that have to be correlated by the reader.
+	 *
+	 * This string may be either of static duration or palloc'd.
+	 */
+	char	   *error_detail;
 } ValidatorModuleResult;
 
 /*

src/test/modules/oauth_validator/t/001_server.pl

@@ -544,8 +544,8 @@ $node->connect_fails(
 	expected_stderr => qr/OAuth bearer authentication failed/,
 	log_like => [
 		qr/connection authenticated: identity=""/,
-		qr/DETAIL:\s+Validator provided no identity/,
 		qr/FATAL:\s+OAuth bearer authentication failed/,
+		qr/DETAIL:\s+Validator provided no identity/,
 	]);
 
 # Even if a validator authenticates the user, if the token isn't considered
@@ -564,10 +564,48 @@ $node->connect_fails(
 	expected_stderr => qr/OAuth bearer authentication failed/,
 	log_like => [
 		qr/connection authenticated: identity="test\@example\.org"/,
-		qr/DETAIL:\s+Validator failed to authorize the provided token/,
 		qr/FATAL:\s+OAuth bearer authentication failed/,
+		qr/DETAIL:\s+Validator failed to authorize the provided token/,
 	]);
 
+# Validators can provide their own explanations.
+$bgconn->query_safe(
+	"ALTER SYSTEM SET oauth_validator.error_detail TO 'something failed'");
+$node->reload;
+$log_start =
+  $node->wait_for_log(qr/reloading configuration files/, $log_start);
+
+$node->connect_fails(
+	"$common_connstr user=test",
+	"validator must authorize token explicitly (custom logdetail)",
+	expected_stderr => qr/OAuth bearer authentication failed/,
+	log_like => [
+		qr/connection authenticated: identity="test\@example\.org"/,
+		qr/FATAL:\s+OAuth bearer authentication failed/,
+		qr/DETAIL:\s+something failed/,
+	]);
+
+$bgconn->query_safe(
+	"ALTER SYSTEM SET oauth_validator.internal_error TO true");
+$node->reload;
+$log_start =
+  $node->wait_for_log(qr/reloading configuration files/, $log_start);
+
+$node->connect_fails(
+	"$common_connstr user=test",
+	"validator internal error (custom logdetail)",
+	expected_stderr => qr/OAuth bearer authentication failed/,
+	log_like => [
+		qr/WARNING:\s+internal error in OAuth validator module/,
+		qr/DETAIL:\s+something failed/,
+	]);
+
+$bgconn->query_safe("ALTER SYSTEM RESET oauth_validator.error_detail");
+$bgconn->query_safe("ALTER SYSTEM RESET oauth_validator.internal_error");
+$node->reload;
+$log_start =
+  $node->wait_for_log(qr/reloading configuration files/, $log_start);
+
 #
 # Test user mapping.
 #

src/test/modules/oauth_validator/validator.c

@@ -40,6 +40,8 @@ static const OAuthValidatorCallbacks validator_callbacks = {
 /* GUCs */
 static char *authn_id = NULL;
 static bool authorize_tokens = true;
+static char *error_detail = NULL;
+static bool internal_error = false;
 
 /*---
  * Extension entry point. Sets up GUCs for use by tests:
@@ -51,6 +53,13 @@ static bool authorize_tokens = true;
  * - oauth_validator.authorize_tokens
  *								Sets whether to successfully validate incoming
  *								tokens. Defaults to true.
+ *
+ * - oauth_validator.error_detail
+ *                              Sets an error message to be included as a
+ *                              DETAIL on failure.
+ *
+ * - oauth_validator.internal_error
+ *                              Reports an internal error to the server.
  */
 void
 _PG_init(void)
@@ -71,6 +80,22 @@ _PG_init(void)
 							 PGC_SIGHUP,
 							 0,
 							 NULL, NULL, NULL);
+	DefineCustomStringVariable("oauth_validator.error_detail",
+							   "Error message to print during failures",
+							   NULL,
+							   &error_detail,
+							   NULL,
+							   PGC_SIGHUP,
+							   0,
+							   NULL, NULL, NULL);
+	DefineCustomBoolVariable("oauth_validator.internal_error",
+							 "Should the validator report an internal error?",
+							 NULL,
+							 &internal_error,
+							 false,
+							 PGC_SIGHUP,
+							 0,
+							 NULL, NULL, NULL);
 
 	MarkGUCPrefixReserved("oauth_validator");
 }
@@ -133,6 +158,10 @@ validate_token(const ValidatorModuleState *state,
 		 MyProcPort->hba->oauth_issuer,
 		 MyProcPort->hba->oauth_scope);
 
+	res->error_detail = error_detail;	/* only relevant for failures */
+	if (internal_error)
+		return false;
+
 	res->authorized = authorize_tokens;
 	if (authn_id)
 		res->authn_id = pstrdup(authn_id);