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

diff --git a/doc/src/sgml/oauth-validators.sgml b/doc/src/sgml/oauth-validators.sgml
index 704089dd7b3cb844507a5eb31c7568d8ddebac58..5f29f2be1863897d6544d4436234f9436245d0dc 100644 (file)
--- a/doc/src/sgml/oauth-validators.sgml
+++ b/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

diff --git a/src/backend/libpq/auth-oauth.c b/src/backend/libpq/auth-oauth.c
index 894efe3c904c76fdf4a53bba2e026ca2dc830145..6a75b79efbff4036845c60fb0edfe61b5fb967c8 100644 (file)
--- a/src/backend/libpq/auth-oauth.c
+++ b/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;

diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index fdacc060381466358660cfe13a9d45eeaf09e07f..47b5eeb8f2268422dafa57ea098f0da4fc7c777e 100644 (file)
--- a/src/backend/libpq/auth.c
+++ b/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;
        }

diff --git a/src/include/libpq/oauth.h b/src/include/libpq/oauth.h
index 4a822e9a1f2314964346fdd26d70784fea91ef91..60f493acdddb4fafbeb0b35ab585b78e245264c0 100644 (file)
--- a/src/include/libpq/oauth.h
+++ b/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;
 
 /*

diff --git a/src/test/modules/oauth_validator/t/001_server.pl b/src/test/modules/oauth_validator/t/001_server.pl
index c9c46e635399edcce586a9fdfdb5453bf3e15976..ac62555675a209246e8ecbd9f5f6b95929bcb57a 100644 (file)
--- a/src/test/modules/oauth_validator/t/001_server.pl
+++ b/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/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.
 #

diff --git a/src/test/modules/oauth_validator/validator.c b/src/test/modules/oauth_validator/validator.c
index 0b983a9dc8fded6d54441173222219624e67276c..353e0e0d32ac8bcadc047fd81258b0f8c55aac3f 100644 (file)
--- a/src/test/modules/oauth_validator/validator.c
+++ b/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);