fix(oauth2): log database token failures

UPDATING.md

@@ -24,6 +24,13 @@ assists people when migrating to a new version.
 
 ## Next
 
+### OAuth2 database callback metrics include their outcome
+
+The unqualified `DatabaseRestApi.oauth2` StatsD counter has been replaced with
+`DatabaseRestApi.oauth2.success`, `DatabaseRestApi.oauth2.warning`, and
+`DatabaseRestApi.oauth2.error`. Update monitoring rules and dashboards that consume
+the old counter to use the outcome-specific replacements.
+
 ### Principal listing APIs now honour related-field filters
 
 Two authorization-related listing behaviors changed for API clients. Neither

superset/commands/database/oauth2.py

@@ -15,6 +15,7 @@
 # specific language governing permissions and limitations
 # under the License.
 
+import logging
 from datetime import datetime, timedelta
 from functools import partial
 from typing import cast
@@ -32,6 +33,8 @@
 from superset.utils.decorators import on_error, transaction
 from superset.utils.oauth2 import decode_oauth2_state
 
+logger = logging.getLogger(__name__)
+
 
 class OAuth2StoreTokenCommand(BaseCommand):
     """
@@ -71,11 +74,21 @@ def run(self) -> DatabaseUserOAuth2Tokens:
                 code_verifier = kv_value.get("code_verifier")
                 KeyValueDAO.delete_entry(KeyValueResource.PKCE_CODE_VERIFIER, tab_uuid)
 
-        token_response = self._database.db_engine_spec.get_oauth2_token(
-            oauth2_config,
-            self._parameters["code"],
-            code_verifier=code_verifier,
-        )
+        engine_spec = self._database.db_engine_spec
+        try:
+            token_response = engine_spec.get_oauth2_token(
+                oauth2_config,
+                self._parameters["code"],
+                code_verifier=code_verifier,
+            )
+        except Exception as ex:
+            logger.error(
+                "OAuth2 token exchange failed: database_id=%s engine=%s error_type=%s",
+                self._database.id,
+                engine_spec.engine,
+                type(ex).__name__,
+            )
+            raise
 
         # delete old tokens
         if existing := DatabaseUserOAuth2TokensDAO.find_one_or_none(

superset/databases/api.py

@@ -1454,10 +1454,12 @@ def validate_sql(self, pk: int) -> FlaskResponse:
             return self.response_404()
 
     @expose("/oauth2/", methods=["GET"])
+    @statsd_metrics
     @transaction()
     @event_logger.log_this_with_context(
         action=lambda self, *args, **kwargs: f"{self.__class__.__name__}.oauth2",
-        log_to_statsd=True,
+        log_to_statsd=False,
+        include_request_data=False,
     )
     def oauth2(self) -> FlaskResponse:
         """

superset/utils/log.py

@@ -38,21 +38,21 @@
 logger = logging.getLogger(__name__)
 
 
-def collect_request_payload() -> dict[str, Any]:
+def collect_request_payload(include_request_data: bool = True) -> dict[str, Any]:
     """Collect log payload identifiable from request context"""
     if not request:
         return {}
 
-    payload: dict[str, Any] = {
-        "path": request.path,
-        **request.form.to_dict(),
-        # url search params can overwrite POST body
-        **request.args.to_dict(),
-    }
+    payload: dict[str, Any] = {"path": request.path}
+
+    if include_request_data:
+        payload.update(request.form.to_dict())
+        # URL search params can overwrite POST body.
+        payload.update(request.args.to_dict())
 
-    if request.is_json:
-        json_payload = request.get_json(cache=True, silent=True) or {}
-        payload.update(json_payload)
+        if request.is_json:
+            json_payload = request.get_json(cache=True, silent=True) or {}
+            payload.update(json_payload)
 
     # save URL match pattern in addition to the request path
     url_rule = str(request.url_rule)
@@ -120,7 +120,7 @@ def __call__(
         object_ref: str | None = None,
         log_to_statsd: bool = True,
         duration: timedelta | None = None,
-        **payload_override: dict[str, Any],
+        **payload_override: Any,
     ) -> object:
         # pylint: disable=W0201
         self.action = action
@@ -176,7 +176,8 @@ def log_with_context(  # pylint: disable=too-many-locals,too-many-arguments
         object_ref: str | None = None,
         log_to_statsd: bool = True,
         database: Any | None = None,
-        **payload_override: dict[str, Any] | None,
+        include_request_data: bool = True,
+        **payload_override: Any,
     ) -> None:
         # pylint: disable=import-outside-toplevel
         from superset import db
@@ -203,7 +204,7 @@ def log_with_context(  # pylint: disable=too-many-locals,too-many-arguments
             except Exception as ex:
                 logger.debug("Failed to add user to db session: %s", ex)
                 user_id = None
-        payload = collect_request_payload()
+        payload = collect_request_payload(include_request_data)
         if object_ref:
             payload["object_ref"] = object_ref
         if payload_override:
@@ -258,13 +259,15 @@ def log_context(
         action: str,
         object_ref: str | None = None,
         log_to_statsd: bool = True,
+        include_request_data: bool = True,
         **kwargs: Any,
     ) -> Iterator[Callable[..., None]]:
         """
         Log an event with additional information from the request context.
         :param action: a name to identify the event
         :param object_ref: reference to the Python object that triggered this action
         :param log_to_statsd: whether to update statsd counter for the action
+        :param include_request_data: whether to include form, query, and JSON fields
         """
         payload_override = kwargs.copy()
         start = datetime.now()
@@ -275,7 +278,12 @@ def log_context(
         # take the action from payload_override else take the function param action
         action_str = payload_override.pop("action", action)
         self.log_with_context(
-            action_str, duration, object_ref, log_to_statsd, **payload_override
+            action_str,
+            duration,
+            object_ref,
+            log_to_statsd,
+            include_request_data=include_request_data,
+            **payload_override,
         )
 
     def _wrapper(

superset/utils/oauth2.py

@@ -164,21 +164,22 @@ def refresh_oauth2_token(
         except db_engine_spec.oauth2_exception as ex:
             # OAuth token is no longer valid, delete it and start OAuth2 dance
             logger.warning(
-                "OAuth2 token refresh failed for user=%s db=%s, "
-                "deleting token. Error: %s",
-                user_id,
+                "OAuth2 token refresh failed: database_id=%s engine=%s error_type=%s; "
+                "deleting token",
                 database_id,
-                ex,
+                db_engine_spec.engine,
+                type(ex).__name__,
             )
             db.session.delete(token)
             db.session.flush()
             raise
-        except Exception:
-            # non-OAuth related failure, log the exception
-            logger.warning(
-                "OAuth2 token refresh failed for user=%s db=%s",
-                user_id,
+        except Exception as ex:
+            # Non-OAuth failure: preserve the token and log structured context
+            logger.error(
+                "OAuth2 token refresh failed: database_id=%s engine=%s error_type=%s",
                 database_id,
+                db_engine_spec.engine,
+                type(ex).__name__,
             )
             raise
 

tests/unit_tests/commands/databases/oauth2_test.py

@@ -15,11 +15,13 @@
 # specific language governing permissions and limitations
 # under the License.
 
+import logging
 from typing import Any
 from unittest.mock import MagicMock
 
 import pytest
 from pytest_mock import MockerFixture
+from requests.exceptions import HTTPError
 
 from superset.commands.database.exceptions import DatabaseNotFoundError
 from superset.commands.database.oauth2 import OAuth2StoreTokenCommand
@@ -33,6 +35,8 @@
 @pytest.fixture
 def mock_database(mocker: MockerFixture) -> MagicMock:
     database = mocker.MagicMock(spec=Database)
+    database.id = 123
+    database.db_engine_spec.engine = "postgresql"
     database.get_oauth2_config.return_value = {
         "client_id": "test",
         "client_secret": "secret",
@@ -135,6 +139,40 @@ def test_run_success(
     mock_create.assert_called_once()
 
 
+def test_run_logs_token_exchange_failure(
+    mocker: MockerFixture,
+    caplog: pytest.LogCaptureFixture,
+    mock_database: MagicMock,
+    mock_parameters: OAuth2ProviderResponseSchema,
+) -> None:
+    mock_parameters["code"] = "oauth-code-sentinel"
+    mock_database.get_oauth2_config.return_value["client_secret"] = (
+        "client-secret-sentinel"  # noqa: S105
+    )
+    mocker.patch.object(
+        DatabaseUserOAuth2TokensDAO,
+        "get_database",
+        return_value=mock_database,
+    )
+    mock_database.db_engine_spec.get_oauth2_token.side_effect = HTTPError(
+        "provider-payload-sentinel"
+    )
+
+    with (
+        caplog.at_level(logging.ERROR, logger="superset.commands.database.oauth2"),
+        pytest.raises(HTTPError),
+    ):
+        OAuth2StoreTokenCommand(mock_parameters).run()
+
+    assert (
+        "OAuth2 token exchange failed: database_id=123 engine=postgresql "
+        "error_type=HTTPError"
+    ) in caplog.messages
+    assert "oauth-code-sentinel" not in caplog.text
+    assert "client-secret-sentinel" not in caplog.text
+    assert "provider-payload-sentinel" not in caplog.text
+
+
 def test_run_existing_token(
     mocker: MockerFixture,
     mock_database: MagicMock,

tests/unit_tests/databases/oauth2_api_test.py

@@ -0,0 +1,117 @@
+# Licensed to the Apache Software Foundation (ASF) under one
+# or more contributor license agreements.  See the NOTICE file
+# distributed with this work for additional information
+# regarding copyright ownership.  The ASF licenses this file
+# to you under the Apache License, Version 2.0 (the
+# "License"); you may not use this file except in compliance
+# with the License.  You may obtain a copy of the License at
+#
+#   http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing,
+# software distributed under the License is distributed on an
+# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+# KIND, either express or implied.  See the License for the
+# specific language governing permissions and limitations
+# under the License.
+
+from typing import Any
+from unittest.mock import call, MagicMock
+
+import pytest
+from pytest_mock import MockerFixture
+from requests.exceptions import HTTPError
+
+from superset import db
+from superset.extensions import event_logger, stats_logger_manager
+from superset.superset_typing import OAuth2State
+from superset.utils.oauth2 import encode_oauth2_state
+
+
+@pytest.fixture
+def oauth2_command(mocker: MockerFixture) -> MagicMock:
+    command = mocker.patch("superset.databases.api.OAuth2StoreTokenCommand")
+    mocker.patch("superset.databases.api.render_template", return_value="OK")
+    return command
+
+
+def callback_state() -> str:
+    state: OAuth2State = {
+        "user_id": 1,
+        "database_id": 1,
+        "tab_id": "42",
+        "default_redirect_uri": "http://localhost:8088/api/v1/oauth2/",
+    }
+    return encode_oauth2_state(state)
+
+
+@pytest.mark.parametrize(
+    ("exchange_error", "expected_status", "expected_outcome", "transaction_method"),
+    [
+        (None, 200, "success", "commit"),
+        (HTTPError("token endpoint unavailable"), 500, "error", "rollback"),
+    ],
+)
+def test_oauth2_callback_emits_one_outcome_metric_after_transaction(
+    mocker: MockerFixture,
+    client: Any,
+    full_api_access: None,
+    oauth2_command: MagicMock,
+    exchange_error: Exception | None,
+    expected_status: int,
+    expected_outcome: str,
+    transaction_method: str,
+) -> None:
+    oauth2_command.return_value.run.side_effect = exchange_error
+    mocker.patch.object(event_logger, "log")
+
+    calls = mocker.MagicMock()
+    transaction_complete = mocker.patch.object(db.session, transaction_method)
+    metric = mocker.patch.object(stats_logger_manager.instance, "incr")
+    calls.attach_mock(transaction_complete, "transaction_complete")
+    calls.attach_mock(metric, "metric")
+
+    response = client.get(
+        "/api/v1/database/oauth2/",
+        query_string={
+            "state": callback_state(),
+            "code": "XXX",
+        },
+    )
+
+    assert response.status_code == expected_status
+    assert calls.mock_calls == [
+        call.transaction_complete(),
+        call.metric(f"DatabaseRestApi.oauth2.{expected_outcome}"),
+    ]
+
+
+def test_oauth2_callback_excludes_provider_data_from_event_log(
+    mocker: MockerFixture,
+    client: Any,
+    full_api_access: None,
+    oauth2_command: MagicMock,
+) -> None:
+    event_log = mocker.patch.object(event_logger, "log")
+
+    response = client.get(
+        "/api/v1/database/oauth2/",
+        query_string={
+            "state": callback_state(),
+            "code": "oauth-code-sentinel",
+            "scope": "oauth-scope-sentinel",
+            "error_description": "provider-error-sentinel",
+            "provider_payload": "provider-payload-sentinel",
+        },
+    )
+
+    assert response.status_code == 200
+    record = event_log.call_args.kwargs["records"][0]
+    assert record["path"] == "/api/v1/database/oauth2/"
+    assert {
+        "state",
+        "code",
+        "scope",
+        "error_description",
+        "provider_payload",
+    }.isdisjoint(record)