From 452dff5c37ba158e04ffb2aef1302a9396c94a6e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E9=9D=9E=E6=B3=95=E6=93=8D=E4=BD=9C?= Date: Thu, 23 Jul 2026 17:08:04 +0800 Subject: [PATCH] fix(api): prevent identity logging deadlock (#39449) --- api/controllers/web/wraps.py | 6 + api/core/logging/context.py | 36 +++- api/core/logging/filters.py | 54 +---- api/extensions/ext_login.py | 23 ++- api/extensions/otel/runtime.py | 11 +- .../unit_tests/controllers/web/test_wraps.py | 49 +++++ .../unit_tests/core/logging/test_context.py | 50 +++++ .../unit_tests/core/logging/test_filters.py | 193 ++++++++---------- .../extensions/otel/test_runtime.py | 75 +++++++ .../unit_tests/extensions/test_ext_login.py | 59 ++++++ 10 files changed, 392 insertions(+), 164 deletions(-) create mode 100644 api/tests/unit_tests/controllers/web/test_wraps.py create mode 100644 api/tests/unit_tests/extensions/otel/test_runtime.py diff --git a/api/controllers/web/wraps.py b/api/controllers/web/wraps.py index eff4b70ff0f..51014521d41 100644 --- a/api/controllers/web/wraps.py +++ b/api/controllers/web/wraps.py @@ -11,6 +11,7 @@ from werkzeug.exceptions import BadRequest, NotFound, Unauthorized from constants import HEADER_NAME_APP_CODE from controllers.web.error import WebAppAuthAccessDeniedError, WebAppAuthRequiredError +from core.logging.context import set_identity_context from extensions.ext_database import db from libs.passport import PassportService from libs.token import extract_webapp_passport @@ -28,6 +29,11 @@ def validate_jwt_token[**P, R]( @wraps(view) def decorated(*args: P.args, **kwargs: P.kwargs) -> R: app_model, end_user = decode_jwt_token() + set_identity_context( + tenant_id=end_user.tenant_id, + user_id=end_user.id, + user_type=end_user.type or "end_user", + ) return view(app_model, end_user, *args, **kwargs) return decorated diff --git a/api/core/logging/context.py b/api/core/logging/context.py index 18633a0b050..8ec2232906a 100644 --- a/api/core/logging/context.py +++ b/api/core/logging/context.py @@ -6,9 +6,21 @@ using Python's contextvars for thread-safe and async-safe storage. import uuid from contextvars import ContextVar +from typing import NamedTuple + + +class IdentityContext(NamedTuple): + """Immutable identity values captured for logging.""" + + tenant_id: str + user_id: str + user_type: str + _request_id: ContextVar[str] = ContextVar("log_request_id", default="") _trace_id: ContextVar[str] = ContextVar("log_trace_id", default="") +_EMPTY_IDENTITY_CONTEXT = IdentityContext(tenant_id="", user_id="", user_type="") +_identity: ContextVar[IdentityContext] = ContextVar("log_identity", default=_EMPTY_IDENTITY_CONTEXT) def get_request_id() -> str: @@ -21,15 +33,35 @@ def get_trace_id() -> str: return _trace_id.get() +def get_identity_context() -> IdentityContext: + """Get the immutable tenant, user, and user-type snapshot for logging.""" + return _identity.get() + + +def set_identity_context( + *, tenant_id: str | None = None, user_id: str | None = None, user_type: str | None = None +) -> None: + """Set primitive identity values already resolved by an authentication boundary.""" + _identity.set( + IdentityContext( + tenant_id=tenant_id or "", + user_id=user_id or "", + user_type=user_type or "", + ) + ) + + def init_request_context() -> None: - """Initialize request context. Call at start of each request.""" + """Initialize request context and discard identity left by earlier work.""" req_id = uuid.uuid4().hex[:10] trace_id = uuid.uuid5(uuid.NAMESPACE_DNS, req_id).hex _request_id.set(req_id) _trace_id.set(trace_id) + _identity.set(_EMPTY_IDENTITY_CONTEXT) def clear_request_context() -> None: - """Clear request context. Call at end of request (optional).""" + """Clear request context at a request or task lifecycle boundary.""" _request_id.set("") _trace_id.set("") + _identity.set(_EMPTY_IDENTITY_CONTEXT) diff --git a/api/core/logging/filters.py b/api/core/logging/filters.py index 3f6c565e131..2621cd81d98 100644 --- a/api/core/logging/filters.py +++ b/api/core/logging/filters.py @@ -4,10 +4,7 @@ import contextlib import logging from typing import override -import flask - -from core.logging.context import get_request_id, get_trace_id -from core.logging.structured_formatter import IdentityDict +from core.logging.context import get_identity_context, get_request_id, get_trace_id class TraceContextFilter(logging.Filter): @@ -51,49 +48,16 @@ class TraceContextFilter(logging.Filter): class IdentityContextFilter(logging.Filter): - """ - Filter that adds user identity context to log records. - Extracts tenant_id, user_id, and user_type from Flask-Login current_user. + """Add an identity snapshot without invoking authentication or database work. + + Logging can run while other libraries hold internal locks, so this filter must + only read primitive ContextVar values populated by authentication boundaries. """ @override def filter(self, record: logging.LogRecord) -> bool: - identity = self._extract_identity() - record.tenant_id = identity.get("tenant_id", "") - record.user_id = identity.get("user_id", "") - record.user_type = identity.get("user_type", "") + identity = get_identity_context() + record.tenant_id = identity.tenant_id + record.user_id = identity.user_id + record.user_type = identity.user_type return True - - def _extract_identity(self) -> IdentityDict: - """Extract identity from current_user if in request context.""" - try: - if not flask.has_request_context(): - return {} - from flask_login import current_user - - # Check if user is authenticated using the proxy - if not current_user.is_authenticated: - return {} - - # Access the underlying user object - user = current_user - - from models import Account - from models.model import EndUser - - identity: IdentityDict = {} - - match user: - case Account(): - if user.current_tenant_id: - identity["tenant_id"] = user.current_tenant_id - identity["user_id"] = user.id - identity["user_type"] = "account" - case EndUser(): - identity["tenant_id"] = user.tenant_id - identity["user_id"] = user.id - identity["user_type"] = user.type or "end_user" - - return identity - except Exception: - return {} diff --git a/api/extensions/ext_login.py b/api/extensions/ext_login.py index 3bc8b7baf17..fddefb14f52 100644 --- a/api/extensions/ext_login.py +++ b/api/extensions/ext_login.py @@ -1,5 +1,6 @@ import json -from typing import cast, override +import logging +from typing import assert_never, cast, override import flask_login from flask import Request, Response, request @@ -11,6 +12,7 @@ from werkzeug.exceptions import NotFound, Unauthorized from configs import dify_config from constants import HEADER_NAME_APP_CODE from core.db.session_factory import session_factory +from core.logging.context import set_identity_context from dify_app import DifyApp from libs.passport import PassportService from libs.token import extract_access_token, extract_console_cookie_token, extract_webapp_passport @@ -19,6 +21,8 @@ from models.enums import EndUserType from models.model import AppMCPServer, EndUser from services.account_service import AccountService +logger = logging.getLogger(__name__) + type LoginUser = Account | EndUser @@ -156,13 +160,24 @@ def _load_user_from_request(request_from_flask_login: Request, session: Session) @user_logged_in.connect @user_loaded_from_request.connect def on_user_logged_in(_sender: object, user: LoginUser) -> None: - """Called when a user logged in. + """Snapshot authenticated identity into the side-effect-free logging context. Note: AccountService.load_logged_in_account will populate user.current_tenant_id through the load_user method, which calls account.set_tenant_id_with_session(). """ - # tenant_id context variable removed - using current_user.current_tenant_id directly - pass + set_identity_context() + try: + match user: + case Account(): + set_identity_context(tenant_id=user.current_tenant_id, user_id=user.id, user_type="account") + case EndUser(): + set_identity_context(tenant_id=user.tenant_id, user_id=user.id, user_type=user.type or "end_user") + case _ as unreachable: + assert_never(unreachable) + except Exception: + # Logging enrichment must never make authentication fail. + logger.exception("Failed to set logging identity context") + return @login_manager.unauthorized_handler diff --git a/api/extensions/otel/runtime.py b/api/extensions/otel/runtime.py index 149d76b07b2..4f749a49e5d 100644 --- a/api/extensions/otel/runtime.py +++ b/api/extensions/otel/runtime.py @@ -69,12 +69,17 @@ def on_user_loaded(_sender, user: Union["Account", "EndUser"]): if user: try: current_span = get_current_span() + if not current_span.is_recording(): + return tenant_id = extract_tenant_id(user) if not tenant_id: return - if current_span: - current_span.set_attribute(DifySpanAttributes.TENANT_ID, tenant_id) - current_span.set_attribute(GenAIAttributes.USER_ID, user.id) + current_span.set_attributes( + { + DifySpanAttributes.TENANT_ID: tenant_id, + GenAIAttributes.USER_ID: user.id, + } + ) except Exception: logger.exception("Error setting tenant and user attributes") pass diff --git a/api/tests/unit_tests/controllers/web/test_wraps.py b/api/tests/unit_tests/controllers/web/test_wraps.py new file mode 100644 index 00000000000..2855d1bb663 --- /dev/null +++ b/api/tests/unit_tests/controllers/web/test_wraps.py @@ -0,0 +1,49 @@ +from unittest import mock + +import pytest +from werkzeug.exceptions import Unauthorized + +from core.logging.context import clear_request_context, get_identity_context + + +@pytest.fixture(autouse=True) +def _reset_logging_context(): + clear_request_context() + yield + clear_request_context() + + +def test_validate_jwt_token_sets_logging_identity_before_view() -> None: + from controllers.web import wraps + + app_model = mock.Mock() + end_user = mock.Mock(id="end-user-id", tenant_id="tenant-id", type=None) + clear_request_context() + + @wraps.validate_jwt_token + def protected_view(received_app, received_user): + assert get_identity_context() == ("tenant-id", "end-user-id", "end_user") + return received_app, received_user + + with mock.patch.object(wraps, "decode_jwt_token", return_value=(app_model, end_user)): + result = protected_view() + + assert result == (app_model, end_user) + + +def test_validate_jwt_token_does_not_set_identity_when_authentication_fails() -> None: + from controllers.web import wraps + + clear_request_context() + + @wraps.validate_jwt_token + def protected_view(_app, _user): + raise AssertionError("view must not be called") + + with ( + mock.patch.object(wraps, "decode_jwt_token", side_effect=Unauthorized()), + pytest.raises(Unauthorized), + ): + protected_view() + + assert get_identity_context() == ("", "", "") diff --git a/api/tests/unit_tests/core/logging/test_context.py b/api/tests/unit_tests/core/logging/test_context.py index f388a3a0b9f..2458d57ef75 100644 --- a/api/tests/unit_tests/core/logging/test_context.py +++ b/api/tests/unit_tests/core/logging/test_context.py @@ -1,15 +1,27 @@ """Tests for logging context module.""" import uuid +from contextvars import copy_context + +import pytest from core.logging.context import ( clear_request_context, + get_identity_context, get_request_id, get_trace_id, init_request_context, + set_identity_context, ) +@pytest.fixture(autouse=True) +def _reset_logging_context(): + clear_request_context() + yield + clear_request_context() + + class TestLoggingContext: """Tests for the logging context functions.""" @@ -77,3 +89,41 @@ class TestLoggingContext: # IDs should be different assert id1 != id2 + + def test_set_identity_context(self): + set_identity_context(tenant_id="tenant-1", user_id="user-1", user_type="end_user") + + identity = get_identity_context() + assert identity.tenant_id == "tenant-1" + assert identity.user_id == "user-1" + assert identity.user_type == "end_user" + + def test_set_identity_context_replaces_all_fields(self): + set_identity_context(tenant_id="tenant-1", user_id="user-1", user_type="account") + + set_identity_context(user_id="user-2", user_type="end_user") + + assert get_identity_context() == ("", "user-2", "end_user") + + def test_identity_context_is_copied_as_primitive_values(self): + set_identity_context(tenant_id="tenant-1", user_id="user-1", user_type="end_user") + copied_context = copy_context() + + clear_request_context() + + assert get_identity_context() == ("", "", "") + assert copied_context.run(get_identity_context) == ("tenant-1", "user-1", "end_user") + + def test_init_clears_existing_identity_context(self): + set_identity_context(tenant_id="tenant-1", user_id="user-1", user_type="end_user") + + init_request_context() + + assert get_identity_context() == ("", "", "") + + def test_clear_resets_identity_context(self): + set_identity_context(tenant_id="tenant-1", user_id="user-1", user_type="end_user") + + clear_request_context() + + assert get_identity_context() == ("", "", "") diff --git a/api/tests/unit_tests/core/logging/test_filters.py b/api/tests/unit_tests/core/logging/test_filters.py index a8b186ac8aa..fcbbc7e9bbd 100644 --- a/api/tests/unit_tests/core/logging/test_filters.py +++ b/api/tests/unit_tests/core/logging/test_filters.py @@ -1,5 +1,6 @@ """Tests for logging filters.""" +import io import logging from unittest import mock @@ -19,6 +20,15 @@ def log_record(): ) +@pytest.fixture(autouse=True) +def _reset_logging_context(): + from core.logging.context import clear_request_context + + clear_request_context() + yield + clear_request_context() + + class TestTraceContextFilter: def test_sets_empty_trace_id_without_context(self, log_record): from core.logging.context import clear_request_context @@ -147,8 +157,10 @@ class TestTraceContextFilter: class TestIdentityContextFilter: def test_sets_empty_identity_without_request_context(self, log_record): + from core.logging.context import clear_request_context from core.logging.filters import IdentityContextFilter + clear_request_context() filter = IdentityContextFilter() result = filter.filter(log_record) @@ -164,131 +176,92 @@ class TestIdentityContextFilter: result = filter.filter(log_record) assert result is True - def test_handles_exception_gracefully(self, log_record): + def test_uses_explicit_identity_context_without_flask_context(self, log_record): + from core.logging.context import set_identity_context from core.logging.filters import IdentityContextFilter + set_identity_context(tenant_id="tenant_id", user_id="end_user_id", user_type="end_user") + filter = IdentityContextFilter() + filter.filter(log_record) - # Should not raise even if something goes wrong - with mock.patch( - "core.logging.filters.flask.has_request_context", side_effect=Exception("Test error"), autospec=True - ): - result = filter.filter(log_record) - assert result is True - assert log_record.tenant_id == "" + assert log_record.tenant_id == "tenant_id" + assert log_record.user_id == "end_user_id" + assert log_record.user_type == "end_user" - def test_sets_empty_identity_unauthenticated(self, log_record): + def test_does_not_trigger_flask_login_request_loader(self, log_record): + from flask import Flask + from flask_login import LoginManager + + from core.logging.context import clear_request_context from core.logging.filters import IdentityContextFilter - mock_user = mock.MagicMock() - mock_user.is_authenticated = False + app = Flask(__name__) + app.secret_key = "test" + login_manager = LoginManager(app) + request_loader = mock.Mock(return_value=None) + login_manager.request_loader(request_loader) + clear_request_context() - with ( - mock.patch("flask.has_request_context", return_value=True), - mock.patch("flask_login.current_user", mock_user), - ): - filter = IdentityContextFilter() - filter.filter(log_record) - assert log_record.user_id == "" + with app.test_request_context("/"): + from flask import g - def test_sets_identity_for_account(self, log_record): + assert "_login_user" not in g + IdentityContextFilter().filter(log_record) + assert "_login_user" not in g + + request_loader.assert_not_called() + assert log_record.tenant_id == "" + assert log_record.user_id == "" + assert log_record.user_type == "" + + def test_ended_otel_span_warning_does_not_trigger_request_loader(self): + from flask import Flask, g + from flask_login import LoginManager + from opentelemetry import trace + from opentelemetry.sdk.trace import TracerProvider + + from core.logging.context import clear_request_context from core.logging.filters import IdentityContextFilter - class MockAccount: - pass + app = Flask(__name__) + app.secret_key = "test" + login_manager = LoginManager(app) + request_loader = mock.Mock(return_value=None) + login_manager.request_loader(request_loader) - mock_user = MockAccount() - mock_user.id = "account_id" - mock_user.current_tenant_id = "tenant_id" - mock_user.is_authenticated = True + span = TracerProvider().get_tracer(__name__).start_span("ended") + span.end() - with ( - mock.patch("flask.has_request_context", return_value=True), - mock.patch("models.Account", MockAccount), - mock.patch("flask_login.current_user", mock_user), - ): - filter = IdentityContextFilter() - filter.filter(log_record) + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.addFilter(IdentityContextFilter()) + handler.setFormatter(logging.Formatter("%(tenant_id)s %(user_id)s %(user_type)s %(message)s")) - assert log_record.tenant_id == "tenant_id" - assert log_record.user_id == "account_id" - assert log_record.user_type == "account" + sdk_logger = logging.getLogger("opentelemetry.sdk.trace") + previous_level = sdk_logger.level + previous_propagate = sdk_logger.propagate + previous_disabled = sdk_logger.disabled + sdk_logger.addHandler(handler) + sdk_logger.setLevel(logging.WARNING) + sdk_logger.propagate = False + sdk_logger.disabled = False + clear_request_context() - def test_sets_identity_for_account_no_tenant(self, log_record): - from core.logging.filters import IdentityContextFilter + try: + with app.test_request_context("/"), trace.use_span(span, end_on_exit=False): + assert "_login_user" not in g - class MockAccount: - pass + span.set_attribute("test.key", "test-value") - mock_user = MockAccount() - mock_user.id = "account_id" - mock_user.current_tenant_id = None - mock_user.is_authenticated = True + assert "_login_user" not in g + finally: + clear_request_context() + sdk_logger.removeHandler(handler) + sdk_logger.setLevel(previous_level) + sdk_logger.propagate = previous_propagate + sdk_logger.disabled = previous_disabled + handler.close() - with ( - mock.patch("flask.has_request_context", return_value=True), - mock.patch("models.Account", MockAccount), - mock.patch("flask_login.current_user", mock_user), - ): - filter = IdentityContextFilter() - filter.filter(log_record) - - assert log_record.tenant_id == "" - assert log_record.user_id == "account_id" - assert log_record.user_type == "account" - - def test_sets_identity_for_end_user(self, log_record): - from core.logging.filters import IdentityContextFilter - - class MockEndUser: - pass - - class AnotherClass: - pass - - mock_user = MockEndUser() - mock_user.id = "end_user_id" - mock_user.tenant_id = "tenant_id" - mock_user.type = "custom_type" - mock_user.is_authenticated = True - - with ( - mock.patch("flask.has_request_context", return_value=True), - mock.patch("models.model.EndUser", MockEndUser), - mock.patch("models.Account", AnotherClass), - mock.patch("flask_login.current_user", mock_user), - ): - filter = IdentityContextFilter() - filter.filter(log_record) - - assert log_record.tenant_id == "tenant_id" - assert log_record.user_id == "end_user_id" - assert log_record.user_type == "custom_type" - - def test_sets_identity_for_end_user_default_type(self, log_record): - from core.logging.filters import IdentityContextFilter - - class MockEndUser: - pass - - class AnotherClass: - pass - - mock_user = MockEndUser() - mock_user.id = "end_user_id" - mock_user.tenant_id = "tenant_id" - mock_user.type = None - mock_user.is_authenticated = True - - with ( - mock.patch("flask.has_request_context", return_value=True), - mock.patch("models.model.EndUser", MockEndUser), - mock.patch("models.Account", AnotherClass), - mock.patch("flask_login.current_user", mock_user), - ): - filter = IdentityContextFilter() - filter.filter(log_record) - - assert log_record.tenant_id == "tenant_id" - assert log_record.user_id == "end_user_id" - assert log_record.user_type == "end_user" + request_loader.assert_not_called() + assert "Setting attribute on ended span" in stream.getvalue() diff --git a/api/tests/unit_tests/extensions/otel/test_runtime.py b/api/tests/unit_tests/extensions/otel/test_runtime.py new file mode 100644 index 00000000000..842e02a5210 --- /dev/null +++ b/api/tests/unit_tests/extensions/otel/test_runtime.py @@ -0,0 +1,75 @@ +from unittest import mock + +import pytest +from opentelemetry import trace +from opentelemetry.sdk.trace import TracerProvider + +from core.logging.context import clear_request_context + + +@pytest.fixture(autouse=True) +def _reset_logging_context(): + clear_request_context() + yield + clear_request_context() + + +def test_on_user_loaded_does_not_write_to_non_recording_span() -> None: + from extensions.otel import runtime + + span = mock.MagicMock() + span.is_recording.return_value = False + user = mock.Mock(id="user-id") + + with ( + mock.patch.object(runtime.dify_config, "ENABLE_OTEL", True), + mock.patch("opentelemetry.trace.get_current_span", return_value=span), + mock.patch.object(runtime, "extract_tenant_id", return_value="tenant-id"), + ): + runtime.on_user_loaded(None, user) + + span.is_recording.assert_called_once_with() + span.set_attribute.assert_not_called() + span.set_attributes.assert_not_called() + + +def test_on_user_loaded_sets_attributes_on_recording_span() -> None: + from extensions.otel import runtime + from extensions.otel.semconv import DifySpanAttributes, GenAIAttributes + + span = mock.MagicMock() + span.is_recording.return_value = True + user = mock.Mock(id="user-id") + + with ( + mock.patch.object(runtime.dify_config, "ENABLE_OTEL", True), + mock.patch("opentelemetry.trace.get_current_span", return_value=span), + mock.patch.object(runtime, "extract_tenant_id", return_value="tenant-id"), + ): + runtime.on_user_loaded(None, user) + + span.set_attributes.assert_called_once_with( + { + DifySpanAttributes.TENANT_ID: "tenant-id", + GenAIAttributes.USER_ID: "user-id", + } + ) + + +def test_on_user_loaded_ignores_ended_sdk_span(caplog) -> None: + from extensions.otel import runtime + + tracer_provider = TracerProvider() + span = tracer_provider.get_tracer(__name__).start_span("ended") + span.end() + user = mock.Mock(id="user-id") + + with ( + trace.use_span(span, end_on_exit=False), + mock.patch.object(runtime.dify_config, "ENABLE_OTEL", True), + mock.patch.object(runtime, "extract_tenant_id", return_value="tenant-id"), + caplog.at_level("WARNING", logger="opentelemetry.sdk.trace"), + ): + runtime.on_user_loaded(None, user) + + assert "Setting attribute on ended span" not in caplog.text diff --git a/api/tests/unit_tests/extensions/test_ext_login.py b/api/tests/unit_tests/extensions/test_ext_login.py index 64abc194276..cd7bde22967 100644 --- a/api/tests/unit_tests/extensions/test_ext_login.py +++ b/api/tests/unit_tests/extensions/test_ext_login.py @@ -1,10 +1,22 @@ import json +from typing import cast +from unittest import mock +import pytest from flask import Response +from core.logging.context import clear_request_context, get_identity_context +from extensions import ext_login from extensions.ext_login import unauthorized_handler +@pytest.fixture(autouse=True) +def _reset_logging_context(): + clear_request_context() + yield + clear_request_context() + + def test_unauthorized_handler_returns_json_response() -> None: response = unauthorized_handler() @@ -15,3 +27,50 @@ def test_unauthorized_handler_returns_json_response() -> None: "code": "unauthorized", "message": "Unauthorized.", } + + +def test_on_user_logged_in_sets_account_logging_identity() -> None: + account = mock.Mock(spec=ext_login.Account) + account.id = "account-id" + account.current_tenant_id = "tenant-id" + clear_request_context() + + ext_login.on_user_logged_in(None, account) + + assert get_identity_context() == ("tenant-id", "account-id", "account") + + +def test_on_user_logged_in_sets_end_user_logging_identity() -> None: + end_user = mock.Mock(spec=ext_login.EndUser) + end_user.id = "end-user-id" + end_user.tenant_id = "tenant-id" + end_user.type = "browser" + clear_request_context() + + ext_login.on_user_logged_in(None, end_user) + + assert get_identity_context() == ("tenant-id", "end-user-id", "browser") + + +def test_on_user_logged_in_does_not_break_auth_when_identity_is_unavailable() -> None: + account = mock.Mock(spec=ext_login.Account) + type(account).current_tenant_id = mock.PropertyMock(side_effect=RuntimeError("unavailable")) + account.id = "account-id" + clear_request_context() + + with mock.patch.object(ext_login.logger, "exception") as logger_exception: + ext_login.on_user_logged_in(None, account) + + assert get_identity_context() == ("", "", "") + logger_exception.assert_called_once_with("Failed to set logging identity context") + + +def test_on_user_logged_in_logs_unsupported_user_type() -> None: + unsupported_user = cast(ext_login.LoginUser, object()) + clear_request_context() + + with mock.patch.object(ext_login.logger, "exception") as logger_exception: + ext_login.on_user_logged_in(None, unsupported_user) + + assert get_identity_context() == ("", "", "") + logger_exception.assert_called_once_with("Failed to set logging identity context")