diff --git a/packages/service-library/src/servicelib/aiohttp/application_setup.py b/packages/service-library/src/servicelib/aiohttp/application_setup.py index 0d52603f9651..330e341313db 100644 --- a/packages/service-library/src/servicelib/aiohttp/application_setup.py +++ b/packages/service-library/src/servicelib/aiohttp/application_setup.py @@ -2,9 +2,12 @@ import inspect import logging from collections.abc import Callable +from contextlib import ContextDecorator from copy import deepcopy +from datetime import datetime from enum import Enum -from typing import Any, Protocol +from types import TracebackType +from typing import Any, Final, Protocol import arrow from aiohttp import web @@ -15,21 +18,19 @@ from .application_keys import APP_CONFIG_KEY, APP_SETTINGS_KEY -log = logging.getLogger(__name__) +_logger = logging.getLogger(__name__) -APP_SETUP_COMPLETED_KEY = f"{__name__ }.setup" +APP_SETUP_COMPLETED_KEY: Final[str] = f"{__name__ }.setup" class _SetupFunc(Protocol): __name__: str - def __call__(self, app: web.Application, *args: Any, **kwds: Any) -> bool: - ... + def __call__(self, app: web.Application, *args: Any, **kwds: Any) -> bool: ... class _ApplicationSettings(Protocol): - def is_enabled(self, field_name: str) -> bool: - ... + def is_enabled(self, field_name: str) -> bool: ... class ModuleCategory(Enum): @@ -46,12 +47,10 @@ def __init__(self, *, reason) -> None: super().__init__(reason) -class ApplicationSetupError(Exception): - ... +class ApplicationSetupError(Exception): ... -class DependencyError(ApplicationSetupError): - ... +class DependencyError(ApplicationSetupError): ... class SetupMetadataDict(TypedDict): @@ -134,6 +133,53 @@ def _get_app_settings_and_field_name( return app_settings, settings_field_name +class _SetupTimingContext(ContextDecorator): + """Context manager/decorator for timing and logging module setup operations.""" + + def __init__( + self, + module_name: str, + *, + logger: logging.Logger, + category: ModuleCategory | None = None, + depends: list[str] | None = None, + ) -> None: + """Initialize timing context. + + :param module_name: Name of the module being set up + :param category: Optional module category for detailed logging + :param depends: Optional dependencies for detailed logging + """ + self.module_name = module_name + self.category = category + self.depends = depends + self.started: datetime | None = None + self.head_msg = f"Setup of {module_name}" + self.logger = logger + + def __enter__(self) -> None: + self.started = arrow.utcnow().datetime + if self.category is not None: + self.logger.info( + "%s (%s, %s) started ... ", + self.head_msg, + f"{self.category.name=}", + f"{self.depends}", + ) + else: + self.logger.info("%s started ...", self.head_msg) + + def __exit__( + self, + exc_type: type[BaseException] | None, + exc_val: BaseException | None, + exc_tb: TracebackType | None, + ) -> None: + if self.started: + elapsed = (arrow.utcnow() - self.started).total_seconds() + _logger.info("%s completed [Elapsed: %3.1f secs]", self.head_msg, elapsed) + + # PUBLIC API ------------------------------------------------------------------ @@ -141,13 +187,68 @@ def is_setup_completed(module_name: str, app: web.Application) -> bool: return module_name in app[APP_SETUP_COMPLETED_KEY] +def ensure_single_setup( + module_name: str, + *, + logger: logging.Logger, +) -> Callable[[Callable[..., Any]], Callable[..., Any]]: + """Ensures a setup function is executed only once per application and handles completion. + + :param module_name: Name of the module being set up + """ + + def _log_skip(reason: str) -> bool: + logger.info("Skipping '%s' setup: %s", module_name, reason) + return False + + def decorator(setup_func: _SetupFunc) -> _SetupFunc: + + @functools.wraps(setup_func) + def _wrapper(app: web.Application, *args: Any, **kwargs: Any) -> bool: + + # pre-setup init + if APP_SETUP_COMPLETED_KEY not in app: + app[APP_SETUP_COMPLETED_KEY] = [] + + # check + if is_setup_completed(module_name, app): + _log_skip( + f"'{module_name}' was already initialized in {app}." + " Setup can only be executed once per app." + ) + return False + + try: + completed = setup_func(app, *args, **kwargs) + + # post-setup handling + if completed is None: + completed = True + + if completed: # registers completed setup + app[APP_SETUP_COMPLETED_KEY].append(module_name) + return completed + + assert not completed # nosec + _log_skip("Undefined (setup function returned false)") + return False + + except SkipModuleSetupError as err: + _log_skip(err.reason) + return False + + return _wrapper + + return decorator + + def app_module_setup( module_name: str, category: ModuleCategory, *, settings_name: str | None = None, depends: list[str] | None = None, - logger: logging.Logger = log, + logger: logging.Logger = _logger, # TODO: SEE https://github.com/ITISFoundation/osparc-simcore/issues/2008 # TODO: - settings_name becomes module_name!! # TODO: - plugin base should be aware of setup and settings -> model instead of function? @@ -190,35 +291,27 @@ def setup(app: web.Application): module_name, depends, config_section, config_enabled ) - def _decorate(setup_func: _SetupFunc): - if "setup" not in setup_func.__name__: - logger.warning("Rename '%s' to contain 'setup'", setup_func.__name__) - - # metadata info - def setup_metadata() -> SetupMetadataDict: - return SetupMetadataDict( - module_name=module_name, - dependencies=depends, - config_section=section, - config_enabled=config_enabled, - ) + # metadata info + def _setup_metadata() -> SetupMetadataDict: + return SetupMetadataDict( + module_name=module_name, + dependencies=depends, + config_section=section, + config_enabled=config_enabled, + ) - # wrapper - @functools.wraps(setup_func) - def _wrapper(app: web.Application, *args, **kargs) -> bool: - # pre-setup - head_msg = f"Setup of {module_name}" - started = arrow.utcnow() - logger.info( - "%s (%s, %s) started ... ", - head_msg, - f"{category.name=}", - f"{depends}", - ) + def decorator(setup_func: _SetupFunc) -> _SetupFunc: - if APP_SETUP_COMPLETED_KEY not in app: - app[APP_SETUP_COMPLETED_KEY] = [] + assert ( # nosec + "setup_" in setup_func.__name__ + ), f"Rename '{setup_func.__name__}' like 'setup_$(plugin-name)'" + @functools.wraps(setup_func) + @ensure_single_setup(module_name, logger=logger) + @_SetupTimingContext( + module_name, category=category, depends=depends, logger=logger + ) + def _wrapper(app: web.Application, *args, **kargs) -> bool: if category == ModuleCategory.ADDON: # ONLY addons can be enabled/disabled @@ -258,7 +351,6 @@ def _wrapper(app: web.Application, *args, **kargs) -> bool: return False if depends: - # TODO: no need to enforce. Use to deduce order instead. uninitialized = [ dep for dep in depends if not is_setup_completed(dep, app) ] @@ -266,52 +358,24 @@ def _wrapper(app: web.Application, *args, **kargs) -> bool: msg = f"Cannot setup app module '{module_name}' because the following dependencies are still uninitialized: {uninitialized}" raise DependencyError(msg) - # execution of setup - try: - if is_setup_completed(module_name, app): - raise SkipModuleSetupError( # noqa: TRY301 - reason=f"'{module_name}' was already initialized in {app}." - " Setup can only be executed once per app." - ) - - completed = setup_func(app, *args, **kargs) - - # post-setup - if completed is None: - completed = True - - if completed: # registers completed setup - app[APP_SETUP_COMPLETED_KEY].append(module_name) - else: - raise SkipModuleSetupError( # noqa: TRY301 - reason="Undefined (setup function returned false)" - ) + # execution of setup with module name + completed: bool = setup_func(app, *args, **kargs) - except SkipModuleSetupError as exc: - logger.info("Skipping '%s' setup: %s", module_name, exc.reason) - completed = False - - elapsed = arrow.utcnow() - started - logger.info( - "%s %s [Elapsed: %3.1f secs]", - head_msg, - "completed" if completed else "skipped", - elapsed.total_seconds(), - ) return completed - _wrapper.metadata = setup_metadata # type: ignore[attr-defined] - _wrapper.mark_as_simcore_servicelib_setup_func = True # type: ignore[attr-defined] - # NOTE: this is added by functools.wraps decorated - assert _wrapper.__wrapped__ == setup_func # nosec + assert ( + _wrapper.__wrapped__ == setup_func + ), "this is added by functools.wraps decorator" # nosec + + setattr(_wrapper, "metadata", _setup_metadata) # noqa: B010 + setattr(_wrapper, "mark_as_simcore_servicelib_setup_func", True) # noqa: B010 return _wrapper - return _decorate + return decorator def is_setup_function(fun: Callable) -> bool: - # TODO: use _SetupFunc protocol to check in runtime return ( inspect.isfunction(fun) and hasattr(fun, "mark_as_simcore_servicelib_setup_func") diff --git a/packages/service-library/tests/aiohttp/test_application_setup.py b/packages/service-library/tests/aiohttp/test_application_setup.py index 94af1c07a335..55f92820eddb 100644 --- a/packages/service-library/tests/aiohttp/test_application_setup.py +++ b/packages/service-library/tests/aiohttp/test_application_setup.py @@ -1,52 +1,30 @@ -# pylint:disable=unused-variable -# pylint:disable=unused-argument -# pylint:disable=redefined-outer-name +# pylint: disable=protected-access +# pylint: disable=redefined-outer-name +# pylint: disable=too-many-arguments +# pylint: disable=unused-argument +# pylint: disable=unused-variable -from unittest.mock import Mock + +import logging import pytest from aiohttp import web +from pytest_mock import MockerFixture, MockType from servicelib.aiohttp.application_keys import APP_CONFIG_KEY from servicelib.aiohttp.application_setup import ( DependencyError, ModuleCategory, SkipModuleSetupError, app_module_setup, + ensure_single_setup, is_setup_completed, ) -log = Mock() - - -@app_module_setup("package.bar", ModuleCategory.ADDON, logger=log) -def setup_bar(app: web.Application, arg1, *, raise_skip: bool = False): - return True - -@app_module_setup("package.foo", ModuleCategory.ADDON, logger=log) -def setup_foo(app: web.Application, arg1, kargs=33, *, raise_skip: bool = False): - if raise_skip: - raise SkipModuleSetupError(reason="explicit skip") - return True - - -@app_module_setup( - "package.zee", ModuleCategory.ADDON, config_enabled="main.zee_enabled", logger=log -) -def setup_zee(app: web.Application, arg1, kargs=55): - return True - - -@app_module_setup( - "package.needs_foo", - ModuleCategory.SYSTEM, - depends=[ - "package.foo", - ], - logger=log, -) -def setup_needs_foo(app: web.Application, arg1, kargs=55): - return True +@pytest.fixture +def mock_logger(mocker: MockerFixture) -> MockType: + logger_mock: MockType = mocker.create_autospec(logging.Logger, instance=True) + return logger_mock @pytest.fixture @@ -59,55 +37,128 @@ def app_config() -> dict: @pytest.fixture -def app(app_config): +def app(app_config: dict) -> web.Application: _app = web.Application() _app[APP_CONFIG_KEY] = app_config return _app -def test_setup_config_enabled(app_config, app): +def test_setup_config_enabled(app_config: dict, app: web.Application): + + @app_module_setup( + "package.zee", + ModuleCategory.ADDON, + # legacy support for config_enabled + config_enabled="main.zee_enabled", + ) + def setup_zee(app: web.Application, arg) -> bool: + assert arg + return True + assert setup_zee(app, 1) assert setup_zee.metadata()["config_enabled"] == "main.zee_enabled" app_config["main"]["zee_enabled"] = False + assert not setup_zee(app, 2) -def test_setup_dependencies(app_config, app): +def test_setup_dependencies(app: web.Application): + + @app_module_setup("package.foo", ModuleCategory.ADDON) + def setup_foo(app: web.Application) -> bool: + return True + + @app_module_setup( + "package.needs_foo", + ModuleCategory.SYSTEM, + depends=[ + # This module needs foo to be setup first + "package.foo", + ], + ) + def setup_needs_foo(app: web.Application) -> bool: + return True + # setup_foo is not called yet with pytest.raises(DependencyError): - setup_needs_foo(app, 1) + setup_needs_foo(app) - assert setup_foo(app, 1) - assert setup_needs_foo(app, 2) + # ok + assert setup_foo(app) + assert setup_needs_foo(app) + # meta assert setup_needs_foo.metadata()["dependencies"] == [ setup_foo.metadata()["module_name"], ] -def test_marked_setup(app_config, app): - assert setup_foo(app, 1) +def test_marked_setup(app_config: dict, app: web.Application): + @app_module_setup("package.foo", ModuleCategory.ADDON) + def setup_foo(app: web.Application) -> bool: + return True + assert setup_foo(app) assert setup_foo.metadata()["module_name"] == "package.foo" assert is_setup_completed(setup_foo.metadata()["module_name"], app) app_config["foo"]["enabled"] = False - assert not setup_foo(app, 2) + assert not setup_foo(app) + + +def test_skip_setup(app: web.Application, mock_logger: MockType): + @app_module_setup("package.foo", ModuleCategory.ADDON, logger=mock_logger) + def setup_foo(app: web.Application, *, raise_skip: bool = False) -> bool: + if raise_skip: + raise SkipModuleSetupError(reason="explicit skip") + return True + + assert not setup_foo(app, raise_skip=True) + assert setup_foo(app) + + assert mock_logger.info.called + args = [call.args[-1] for call in mock_logger.info.mock_calls] + assert any("explicit skip" in arg for arg in args) + + +def setup_basic(app: web.Application) -> bool: + return True + + +def setup_that_raises(app: web.Application) -> bool: + error_msg = "Setup failed" + raise ValueError(error_msg) + + +def test_ensure_single_setup_runs_once(app: web.Application, mock_logger: MockType): + decorated = ensure_single_setup("test.module", logger=mock_logger)(setup_basic) + + # First call succeeds + assert decorated(app) + assert is_setup_completed("test.module", app) + + # Second call skips + assert not decorated(app) + +def test_ensure_single_setup_error_handling( + app: web.Application, mock_logger: MockType +): + decorated = ensure_single_setup("test.error", logger=mock_logger)(setup_that_raises) -def test_skip_setup(app_config, app): - try: - log.reset_mock() + with pytest.raises(ValueError, match="Setup failed"): + decorated(app) + assert not is_setup_completed("test.error", app) - assert not setup_foo(app, 1, raise_skip=True) - # FIXME: mock logger - # assert log.warning.called - # warn_msg = log.warning.call_args()[0] - # assert "package.foo" in warn_msg - # assert "explicit skip" in warn_msg +def test_ensure_single_setup_multiple_modules( + app: web.Application, mock_logger: MockType +): + decorated1 = ensure_single_setup("module1", logger=mock_logger)(setup_basic) + decorated2 = ensure_single_setup("module2", logger=mock_logger)(setup_basic) - assert setup_foo(app, 1) - finally: - log.reset_mock() + assert decorated1(app) + assert decorated2(app) + assert is_setup_completed("module1", app) + assert is_setup_completed("module2", app) diff --git a/services/web/server/src/simcore_service_webserver/login/plugin.py b/services/web/server/src/simcore_service_webserver/login/plugin.py index 60c8db47b6fc..fa7c7b452480 100644 --- a/services/web/server/src/simcore_service_webserver/login/plugin.py +++ b/services/web/server/src/simcore_service_webserver/login/plugin.py @@ -4,7 +4,11 @@ import asyncpg from aiohttp import web from pydantic import ValidationError -from servicelib.aiohttp.application_setup import ModuleCategory, app_module_setup +from servicelib.aiohttp.application_setup import ( + ModuleCategory, + app_module_setup, + ensure_single_setup, +) from settings_library.email import SMTPSettings from settings_library.postgres import PostgresSettings @@ -61,11 +65,13 @@ async def _setup_login_storage_ctx(app: web.Application): yield # ---------------- +@ensure_single_setup(f"{__name__}.setup_login_storage", logger=log) def setup_login_storage(app: web.Application): if _setup_login_storage_ctx not in app.cleanup_ctx: app.cleanup_ctx.append(_setup_login_storage_ctx) +@ensure_single_setup(f"{__name__}._setup_login_options", logger=log) def _setup_login_options(app: web.Application): settings: SMTPSettings = get_email_plugin_settings(app)