oauth: Don't log discovery connections by default

Currently, when the client sends a parameter discovery request within
OAUTHBEARER, the server logs the attempt with

    FATAL:  OAuth bearer authentication failed for user

These log entries are difficult to distinguish from true authentication
failures, and by default, libpq sends a discovery request as part of
every OAuth connection, making them annoyingly noisy. Use the new
PG_SASL_EXCHANGE_ABANDONED status to suppress them.

Patch by Zsolt Parragi, with some additional comments added by me.

Author: Zsolt Parragi <zsolt.parragi@percona.com>
Reviewed-by: Andrey Borodin <x4mmm@yandex-team.ru>
Reviewed-by: Chao Li <li.evan.chao@gmail.com>
Discussion: https://postgr.es/m/CAN4CZFPim7hUiyb7daNKQPSZ8CvQRBGkVhbvED7yZi8VktSn4Q%40mail.gmail.com

diff --git a/src/backend/libpq/auth-oauth.c b/src/backend/libpq/auth-oauth.c
index 11365048951b9968e2bbd9b89645f685d48f759b..894efe3c904c76fdf4a53bba2e026ca2dc830145 100644 (file)
--- a/src/backend/libpq/auth-oauth.c
+++ b/src/backend/libpq/auth-oauth.c
@@ -58,6 +58,7 @@ enum oauth_state
 {
        OAUTH_STATE_INIT = 0,
        OAUTH_STATE_ERROR,
+       OAUTH_STATE_ERROR_DISCOVERY,
        OAUTH_STATE_FINISHED,
 };
 
@@ -181,6 +182,7 @@ oauth_exchange(void *opaq, const char *input, int inputlen,
                        break;
 
                case OAUTH_STATE_ERROR:
+               case OAUTH_STATE_ERROR_DISCOVERY:
 
                        /*
                         * Only one response is valid for the client during authentication
@@ -192,7 +194,19 @@ oauth_exchange(void *opaq, const char *input, int inputlen,
                                                errmsg("malformed OAUTHBEARER message"),
                                                errdetail("Client did not send a kvsep response."));
 
-                       /* The (failed) handshake is now complete. */
+                       /*
+                        * The (failed) handshake is now complete. Don't report discovery
+                        * requests in the server log unless the log level is high enough.
+                        */
+                       if (ctx->state == OAUTH_STATE_ERROR_DISCOVERY)
+                       {
+                               ereport(DEBUG1, errmsg("OAuth issuer discovery requested"));
+
+                               ctx->state = OAUTH_STATE_FINISHED;
+                               return PG_SASL_EXCHANGE_ABANDONED;
+                       }
+
+                       /* We're not in discovery, so this is just a normal auth failure. */
                        ctx->state = OAUTH_STATE_FINISHED;
                        return PG_SASL_EXCHANGE_FAILURE;
 
@@ -279,7 +293,19 @@ oauth_exchange(void *opaq, const char *input, int inputlen,
                                errmsg("malformed OAUTHBEARER message"),
                                errdetail("Message contains additional data after the final terminator."));
 
-       if (!validate(ctx->port, auth))
+       if (auth[0] == '\0')
+       {
+               /*
+                * An empty auth value represents a discovery request; the client
+                * expects it to fail.  Skip validation entirely and move directly to
+                * the error response.
+                */
+               generate_error_response(ctx, output, outputlen);
+
+               ctx->state = OAUTH_STATE_ERROR_DISCOVERY;
+               status = PG_SASL_EXCHANGE_CONTINUE;
+       }
+       else if (!validate(ctx->port, auth))
        {
                generate_error_response(ctx, output, outputlen);
 
@@ -564,19 +590,8 @@ validate_token_format(const char *header)
 
        /* Missing auth headers should be handled by the caller. */
        Assert(header);
-
-       if (header[0] == '\0')
-       {
-               /*
-                * A completely empty auth header represents a query for
-                * authentication parameters. The client expects it to fail; there's
-                * no need to make any extra noise in the logs.
-                *
-                * TODO: should we find a way to return STATUS_EOF at the top level,
-                * to suppress the authentication error entirely?
-                */
-               return NULL;
-       }
+       /* Empty auth (discovery) should be handled before calling validate(). */
+       Assert(header[0] != '\0');
 
        if (pg_strncasecmp(header, BEARER_SCHEME, strlen(BEARER_SCHEME)))
        {

diff --git a/src/test/modules/oauth_validator/t/001_server.pl b/src/test/modules/oauth_validator/t/001_server.pl
index 9e4dba8c9246c66127955fdf8109a529e5ba5044..c9c46e635399edcce586a9fdfdb5453bf3e15976 100644 (file)
--- a/src/test/modules/oauth_validator/t/001_server.pl
+++ b/src/test/modules/oauth_validator/t/001_server.pl
@@ -169,7 +169,8 @@ $node->connect_ok(
                qr/oauth_validator: issuer="\Q$issuer\E", scope="openid postgres"/,
                qr/connection authenticated: identity="test" method=oauth/,
                qr/connection authorized/,
-       ]);
+       ],
+       log_unlike => [qr/FATAL.*OAuth bearer authentication failed/]);
 
 # Enable PGOAUTHDEBUG for all remaining tests.
 $ENV{PGOAUTHDEBUG} = "UNSAFE";
@@ -187,7 +188,8 @@ $node->connect_ok(
                qr|oauth_validator: issuer="\Q$issuer/.well-known/oauth-authorization-server/alternate\E", scope="openid postgres alt"|,
                qr/connection authenticated: identity="testalt" method=oauth/,
                qr/connection authorized/,
-       ]);
+       ],
+       log_unlike => [qr/FATAL.*OAuth bearer authentication failed/]);
 
 # The issuer linked by the server must match the client's oauth_issuer setting.
 $node->connect_fails(