diff --git a/.env-devel b/.env-devel index 167b4e36c59..3a8f1090375 100644 --- a/.env-devel +++ b/.env-devel @@ -161,7 +161,7 @@ INVITATIONS_USERNAME=admin INVITATIONS_TRACING={} LOG_FORMAT_LOCAL_DEV_ENABLED=1 -LOG_FILTER_MAPPING='{"gunicorn.access":[" /v0/ ", " /v0/health "], "uvicorn.access":[" / "]}' +LOG_FILTER_MAPPING='{"gunicorn.access":[" /v0/ ", " /v0/health "], "uvicorn.access":[" / ", " /v0/ "]}' NOTIFICATIONS_LOGLEVEL=INFO NOTIFICATIONS_TRACING={} diff --git a/.gitignore b/.gitignore index 964ac9035e6..4c2bf1934a9 100644 --- a/.gitignore +++ b/.gitignore @@ -55,7 +55,6 @@ locust_report/ nosetests.xml test_failures/ - # Translations *.mo *.pot @@ -182,3 +181,6 @@ tests/public-api/osparc_python_wheels/* # osparc-config repo files repo.config + +# repomix +.repomix/* diff --git a/packages/aws-library/tests/conftest.py b/packages/aws-library/tests/conftest.py index 47fcdd327e3..0300b9de075 100644 --- a/packages/aws-library/tests/conftest.py +++ b/packages/aws-library/tests/conftest.py @@ -14,6 +14,7 @@ "pytest_simcore.aws_ssm_service", "pytest_simcore.environment_configs", "pytest_simcore.file_extra", + "pytest_simcore.logging", "pytest_simcore.pydantic_models", "pytest_simcore.pytest_global_environs", "pytest_simcore.repository_paths", diff --git a/packages/celery-library/tests/conftest.py b/packages/celery-library/tests/conftest.py index 2553d9df6d7..e9fc599136a 100644 --- a/packages/celery-library/tests/conftest.py +++ b/packages/celery-library/tests/conftest.py @@ -26,6 +26,7 @@ "pytest_simcore.docker_compose", "pytest_simcore.docker_swarm", "pytest_simcore.environment_configs", + "pytest_simcore.logging", "pytest_simcore.rabbit_service", "pytest_simcore.redis_service", "pytest_simcore.repository_paths", diff --git a/packages/notifications-library/tests/conftest.py b/packages/notifications-library/tests/conftest.py index 006b7ed1a7b..e8440aa573c 100644 --- a/packages/notifications-library/tests/conftest.py +++ b/packages/notifications-library/tests/conftest.py @@ -72,7 +72,7 @@ def product_data( return ProductData( # type: ignore product_name=product_name, display_name=product["display_name"], - vendor_display_inline=f"{vendor.get('name','')}, {vendor.get('address','')}", + vendor_display_inline=f"{vendor.get('name', '')}, {vendor.get('address', '')}", support_email=product["support_email"], homepage_url=vendor.get("url"), ui=product_ui, diff --git a/packages/pytest-simcore/src/pytest_simcore/logging.py b/packages/pytest-simcore/src/pytest_simcore/logging.py new file mode 100644 index 00000000000..2db9ae93c5d --- /dev/null +++ b/packages/pytest-simcore/src/pytest_simcore/logging.py @@ -0,0 +1,42 @@ +# In conftest.py or test_logging_utils.py +import contextlib +import logging +from collections.abc import Iterator +from contextlib import contextmanager + +import pytest +from pytest_mock import MockerFixture +from servicelib.logging_utils import async_loggers + + +@pytest.fixture(autouse=True) +def preserve_caplog_for_async_logging(mocker: MockerFixture) -> None: + # Patch async_loggers to preserve caplog handlers, + # and pytest logs in general as pytest captures logs in a special way + # that is not compatible with the queue handler used in async logging. + original_setup = async_loggers + + @contextmanager + def patched_async_loggers(**kwargs) -> Iterator[None]: + # Find caplog's handler in root logger + root_logger = logging.getLogger() + caplog_handlers = [ + h for h in root_logger.handlers if "LogCaptureHandler" in f"{type(h)}" + ] + + with original_setup(**kwargs): + # After setup, restore caplog handlers alongside queue handler + for handler in caplog_handlers: + if handler not in root_logger.handlers: + root_logger.addHandler(handler) + yield + + methods_to_patch = [ + "servicelib.logging_utils.async_loggers", + "servicelib.fastapi.logging_lifespan.async_loggers", + "tests.test_logging_utils.async_loggers", + ] + for method in methods_to_patch: + with contextlib.suppress(AttributeError, ModuleNotFoundError): + # Patch the method to use our patched version + mocker.patch(method, patched_async_loggers) diff --git a/packages/service-library/src/servicelib/fastapi/lifespan_utils.py b/packages/service-library/src/servicelib/fastapi/lifespan_utils.py index 4ccf0410930..894d9178855 100644 --- a/packages/service-library/src/servicelib/fastapi/lifespan_utils.py +++ b/packages/service-library/src/servicelib/fastapi/lifespan_utils.py @@ -1,6 +1,6 @@ import contextlib -from collections.abc import Iterator -from typing import Final +from collections.abc import AsyncIterator, Callable, Iterator +from typing import Final, TypeAlias from common_library.errors_classes import OsparcErrorMixin from fastapi import FastAPI @@ -8,6 +8,8 @@ from ..logging_utils import log_context +Lifespan: TypeAlias = Callable[[FastAPI], AsyncIterator[None]] + class LifespanError(OsparcErrorMixin, RuntimeError): ... diff --git a/packages/service-library/src/servicelib/fastapi/logging_lifespan.py b/packages/service-library/src/servicelib/fastapi/logging_lifespan.py new file mode 100644 index 00000000000..e06d976878b --- /dev/null +++ b/packages/service-library/src/servicelib/fastapi/logging_lifespan.py @@ -0,0 +1,78 @@ +import logging +from collections.abc import AsyncIterator, Awaitable, Callable +from contextlib import AsyncExitStack + +from fastapi import FastAPI +from settings_library.tracing import TracingSettings + +from ..logging_utils import ( + LogLevelInt, + async_loggers, + log_context, +) +from ..logging_utils_filtering import LoggerName, MessageSubstring +from .lifespan_utils import Lifespan + +_logger = logging.getLogger(__name__) + + +def create_logging_lifespan( + *, + log_format_local_dev_enabled: bool, + logger_filter_mapping: dict[LoggerName, list[MessageSubstring]], + tracing_settings: TracingSettings | None, + log_base_level: LogLevelInt, + noisy_loggers: tuple[str, ...] | None, +) -> Lifespan: + """Returns a FastAPI-compatible lifespan handler to set up async logging.""" + exit_stack = AsyncExitStack() + exit_stack.enter_context( + async_loggers( + log_base_level=log_base_level, + noisy_loggers=noisy_loggers, + log_format_local_dev_enabled=log_format_local_dev_enabled, + logger_filter_mapping=logger_filter_mapping, + tracing_settings=tracing_settings, + ) + ) + + async def _logging_lifespan(app: FastAPI) -> AsyncIterator[None]: + assert app is not None, "app must be provided" + yield + with log_context(_logger, logging.INFO, "Re-enable Blocking logger"): + await exit_stack.aclose() + + return _logging_lifespan + + +def create_logging_shutdown_event( + *, + log_format_local_dev_enabled: bool, + logger_filter_mapping: dict[LoggerName, list[MessageSubstring]], + tracing_settings: TracingSettings | None, + log_base_level: LogLevelInt, + noisy_loggers: tuple[str, ...] | None, +) -> Callable[[], Awaitable[None]]: + """retruns a fastapi-compatible shutdown event handler to be used with old style lifespan + handlers. This is useful for applications that do not use the new async lifespan + handlers introduced in fastapi 0.100.0. + + Note: This function is for backwards compatibility only and will be removed in the future. + setup_logging_lifespan should be used instead for new style lifespan handlers. + """ + exit_stack = AsyncExitStack() + exit_stack.enter_context( + async_loggers( + log_base_level=log_base_level, + noisy_loggers=noisy_loggers, + log_format_local_dev_enabled=log_format_local_dev_enabled, + logger_filter_mapping=logger_filter_mapping, + tracing_settings=tracing_settings, + ) + ) + + async def _on_shutdown_event() -> None: + with log_context(_logger, logging.INFO, "Re-enable Blocking logger"): + await exit_stack.aclose() + + return _on_shutdown_event diff --git a/packages/service-library/src/servicelib/logging_utils.py b/packages/service-library/src/servicelib/logging_utils.py index 7ef3bc28e94..d335fc05989 100644 --- a/packages/service-library/src/servicelib/logging_utils.py +++ b/packages/service-library/src/servicelib/logging_utils.py @@ -8,14 +8,18 @@ import asyncio import functools import logging +import logging.handlers +import queue from asyncio import iscoroutinefunction from collections.abc import Callable, Iterator from contextlib import contextmanager +from dataclasses import dataclass from datetime import datetime from inspect import getframeinfo, stack from pathlib import Path -from typing import Any, NotRequired, TypeAlias, TypedDict, TypeVar +from typing import Any, Final, NotRequired, TypeAlias, TypedDict, TypeVar +from common_library.json_serialization import json_dumps from settings_library.tracing import TracingSettings from .logging_utils_filtering import GeneralLogFilter, LoggerName, MessageSubstring @@ -24,6 +28,8 @@ _logger = logging.getLogger(__name__) +LogLevelInt: TypeAlias = int +LogMessageStr: TypeAlias = str BLACK = "\033[0;30m" BLUE = "\033[0;34m" @@ -106,68 +112,80 @@ def format(self, record) -> str: # SEE https://docs.python.org/3/library/logging.html#logrecord-attributes -DEFAULT_FORMATTING = ( - "log_level=%(levelname)s " - "| log_timestamp=%(asctime)s " - "| log_source=%(name)s:%(funcName)s(%(lineno)d) " - "| log_uid=%(log_uid)s " - "| log_oec=%(log_oec)s" - "| log_msg=%(message)s" +_DEFAULT_FORMATTING: Final[str] = " | ".join( + [ + "log_level=%(levelname)s", + "log_timestamp=%(asctime)s", + "log_source=%(name)s:%(funcName)s(%(lineno)d)", + "log_uid=%(log_uid)s", + "log_oec=%(log_oec)s", + "log_msg=%(message)s", + ] +) + +_LOCAL_FORMATTING: Final[str] = ( + "%(levelname)s: [%(asctime)s/%(processName)s] [%(name)s:%(funcName)s(%(lineno)d)] - %(message)s" +) + +# Tracing format strings +_TRACING_FORMATTING: Final[str] = " | ".join( + [ + "log_level=%(levelname)s", + "log_timestamp=%(asctime)s", + "log_source=%(name)s:%(funcName)s(%(lineno)d)", + "log_uid=%(log_uid)s", + "log_oec=%(log_oec)s", + "log_trace_id=%(otelTraceID)s", + "log_span_id=%(otelSpanID)s", + "log_resource.service.name=%(otelServiceName)s", + "log_trace_sampled=%(otelTraceSampled)s", + "log_msg=%(message)s", + ] +) + +_LOCAL_TRACING_FORMATTING: Final[str] = ( + "%(levelname)s: [%(asctime)s/%(processName)s] " + "[log_trace_id=%(otelTraceID)s log_span_id=%(otelSpanID)s " + "log_resource.service.name=%(otelServiceName)s log_trace_sampled=%(otelTraceSampled)s] " + "[%(name)s:%(funcName)s(%(lineno)d)] - %(message)s" ) -LOCAL_FORMATTING = "%(levelname)s: [%(asctime)s/%(processName)s] [%(name)s:%(funcName)s(%(lineno)d)] - %(message)s" # Graylog Grok pattern extractor: # log_level=%{WORD:log_level} \| log_timestamp=%{TIMESTAMP_ISO8601:log_timestamp} \| log_source=%{DATA:log_source} \| (log_uid=%{WORD:log_uid} \| )?log_msg=%{GREEDYDATA:log_msg} -def config_all_loggers( +def _setup_logging_formatter( *, - log_format_local_dev_enabled: bool, - logger_filter_mapping: dict[LoggerName, list[MessageSubstring]], tracing_settings: TracingSettings | None, -) -> None: - """ - Applies common configuration to ALL registered loggers - """ - the_manager: logging.Manager = logging.Logger.manager - root_logger = logging.getLogger() - - loggers = [root_logger] + [ - logging.getLogger(name) for name in the_manager.loggerDict - ] - - fmt = DEFAULT_FORMATTING - if tracing_settings is not None: + log_format_local_dev_enabled: bool, +) -> logging.Formatter: + if log_format_local_dev_enabled: fmt = ( - "log_level=%(levelname)s " - "| log_timestamp=%(asctime)s " - "| log_source=%(name)s:%(funcName)s(%(lineno)d) " - "| log_uid=%(log_uid)s " - "| log_oec=%(log_oec)s" - "| log_trace_id=%(otelTraceID)s " - "| log_span_id=%(otelSpanID)s " - "| log_resource.service.name=%(otelServiceName)s " - "| log_trace_sampled=%(otelTraceSampled)s] " - "| log_msg=%(message)s" + _LOCAL_TRACING_FORMATTING + if tracing_settings is not None + else _LOCAL_FORMATTING ) - setup_log_tracing(tracing_settings=tracing_settings) - if log_format_local_dev_enabled: - fmt = LOCAL_FORMATTING - if tracing_settings is not None: - fmt = ( - "%(levelname)s: [%(asctime)s/%(processName)s] " - "[log_trace_id=%(otelTraceID)s log_span_id=%(otelSpanID)s log_resource.service.name=%(otelServiceName)s log_trace_sampled=%(otelTraceSampled)s] " - "[%(name)s:%(funcName)s(%(lineno)d)] - %(message)s" - ) - - for logger in loggers: - _set_logging_handler( - logger, fmt=fmt, log_format_local_dev_enabled=log_format_local_dev_enabled + else: + fmt = ( + _TRACING_FORMATTING if tracing_settings is not None else _DEFAULT_FORMATTING ) + return CustomFormatter( + fmt, log_format_local_dev_enabled=log_format_local_dev_enabled + ) + + +def _get_all_loggers() -> list[logging.Logger]: + manager = logging.Logger.manager + root_logger = logging.getLogger() + return [root_logger] + [logging.getLogger(name) for name in manager.loggerDict] + + +def _apply_logger_filters( + logger_filter_mapping: dict[LoggerName, list[MessageSubstring]], +) -> None: for logger_name, filtered_routes in logger_filter_mapping.items(): logger = logging.getLogger(logger_name) - # Check if the logger has any handlers or is in active use if not logger.hasHandlers(): _logger.warning( "Logger %s does not have any handlers. Filter will not be added.", @@ -179,43 +197,240 @@ def config_all_loggers( logger.addFilter(log_filter) -def _set_logging_handler( - logger: logging.Logger, +def _setup_base_logging_level(log_level: LogLevelInt) -> None: + logging.basicConfig(level=log_level) + logging.root.setLevel(log_level) + + +def _dampen_noisy_loggers( + noisy_loggers: tuple[str, ...], +) -> None: + """Sets a less verbose level for noisy loggers.""" + quiet_level: int = max( + min(logging.root.level + logging.CRITICAL - logging.ERROR, logging.CRITICAL), + logging.WARNING, + ) + + for name in noisy_loggers: + logging.getLogger(name).setLevel(quiet_level) + + +def _configure_common_logging_settings( *, - fmt: str, log_format_local_dev_enabled: bool, + tracing_settings: TracingSettings | None, + log_base_level: LogLevelInt, + noisy_loggers: tuple[str, ...] | None, +) -> logging.Formatter: + """ + Common configuration logic shared by both sync and async logging setups. + + Returns the configured formatter to be used with the appropriate handler. + """ + _setup_base_logging_level(log_base_level) + if noisy_loggers is not None: + _dampen_noisy_loggers(noisy_loggers) + if tracing_settings is not None: + setup_log_tracing(tracing_settings=tracing_settings) + + return _setup_logging_formatter( + tracing_settings=tracing_settings, + log_format_local_dev_enabled=log_format_local_dev_enabled, + ) + + +def _apply_logging_configuration( + handler: logging.Handler, + logger_filter_mapping: dict[LoggerName, list[MessageSubstring]], ) -> None: - for handler in logger.handlers: - handler.setFormatter( - CustomFormatter( - fmt, log_format_local_dev_enabled=log_format_local_dev_enabled - ) - ) + """ + Apply the logging configuration with the given handler. + """ + _clean_all_handlers() + _set_root_handler(handler) + + if logger_filter_mapping: + _apply_logger_filters(logger_filter_mapping) + +def setup_loggers( + *, + log_format_local_dev_enabled: bool, + logger_filter_mapping: dict[LoggerName, list[MessageSubstring]], + tracing_settings: TracingSettings | None, + log_base_level: LogLevelInt, + noisy_loggers: tuple[str, ...] | None, +) -> None: + """ + Applies comprehensive configuration to ALL registered loggers. + + Flow Diagram (Synchronous Logging): + ┌─────────────────┐ ┌─────────────────┐ + │ Application │ │ Root Logger │ + │ Thread │───────────────────▶│ StreamHandler │ + │ │ │ ├─ Formatter │ + │ logger.info() │ │ └─ Output │ + │ logger.error() │ │ │ + │ (blocking I/O) │ │ │ + └─────────────────┘ └─────────────────┘ + │ │ + │ ▼ + │ ┌─────────────┐ + │ │ Console/ │ + │ │ Terminal │ + │ └─────────────┘ + │ + └─ Blocks until I/O completes + + This function uses a comprehensive approach: + - Removes all handlers from all loggers + - Ensures all loggers propagate to root + - Sets up root logger with properly formatted handler + - All logging calls are synchronous and may block on I/O + + For async/non-blocking logging, use `async_loggers` context manager instead. + + Args: + log_format_local_dev_enabled: Enable local development formatting + logger_filter_mapping: Mapping of logger names to filtered message substrings + tracing_settings: OpenTelemetry tracing configuration + log_base_level: Base logging level to set + noisy_loggers: Loggers to set to a quieter level + """ + formatter = _configure_common_logging_settings( + log_format_local_dev_enabled=log_format_local_dev_enabled, + tracing_settings=tracing_settings, + log_base_level=log_base_level, + noisy_loggers=noisy_loggers, + ) + + # Create a properly formatted handler for the root logger + stream_handler = logging.StreamHandler() + stream_handler.setFormatter(formatter) + + _store_logger_state(_get_all_loggers()) + _apply_logging_configuration(stream_handler, logger_filter_mapping) + + +@contextmanager +def _queued_logging_handler( + log_formatter: logging.Formatter, +) -> Iterator[logging.Handler]: + log_queue: queue.Queue[logging.LogRecord] = queue.Queue() + # Create handler with proper formatting + handler = logging.StreamHandler() + handler.setFormatter(log_formatter) + + # Create and start the queue listener + listener = logging.handlers.QueueListener( + log_queue, handler, respect_handler_level=True + ) + listener.start() + + queue_handler = logging.handlers.QueueHandler(log_queue) -def test_logger_propagation(logger: logging.Logger) -> None: - """log propagation and levels can sometimes be daunting to get it right. + yield queue_handler - This function uses the `logger`` passed as argument to log the same message at different levels + # cleanup + with log_context( + _logger, + level=logging.DEBUG, + msg="Shutdown async logging listener", + ): + listener.stop() + + +def _clean_all_handlers() -> None: + """ + Cleans all handlers from all loggers. + This is useful for resetting the logging configuration. + """ + root_logger = logging.getLogger() + all_loggers = _get_all_loggers() + for logger in all_loggers: + if logger is root_logger: + continue + logger.handlers.clear() + logger.propagate = True # Ensure propagation is enabled - This should help to visually test a given configuration - USAGE: - from .logging_utils import test_logger_propagation - for n in ("aiohttp.access", "gunicorn.access"): - test_logger_propagation(logging.getLogger(n)) +def _set_root_handler(handler: logging.Handler) -> None: + root_logger = logging.getLogger() + root_logger.handlers.clear() # Clear existing handlers + root_logger.addHandler(handler) # Add the new handler + + +@contextmanager +def async_loggers( + *, + log_format_local_dev_enabled: bool, + logger_filter_mapping: dict[LoggerName, list[MessageSubstring]], + tracing_settings: TracingSettings | None, + log_base_level: LogLevelInt, + noisy_loggers: tuple[str, ...] | None, +) -> Iterator[None]: + """ + Context manager for non-blocking logging infrastructure. + + Flow Diagram: + ┌─────────────────┐ ┌──────────────┐ ┌─────────────────┐ + │ Application │ │ Queue │ │ Background │ + │ Thread │───▶│ (unlimited) │───▶│ Listener Thread │ + │ │ │ │ │ │ + │ logger.info() │ │ LogRecord │ │ StreamHandler │ + │ logger.error() │ │ LogRecord │ │ ├─ Formatter │ + │ (non-blocking) │ │ LogRecord │ │ └─ Output │ + └─────────────────┘ └──────────────┘ └─────────────────┘ + │ │ │ + │ │ ▼ + │ │ ┌─────────────┐ + │ │ │ Console/ │ + │ │ │ Terminal │ + │ │ └─────────────┘ + │ │ + └───────────────────────┴─ No blocking, immediate return + + The async logging setup ensures that: + 1. All log calls return immediately (non-blocking) + 2. Log records are queued in an unlimited queue + 3. A background thread processes the queue and handles actual I/O + 4. All loggers propagate to root for centralized handling + + For more details on the underlying implementation, see: + https://docs.python.org/3/library/logging.handlers.html#queuehandler + + Usage: + with async_loggers(log_format_local_dev_enabled=True, logger_filter_mapping={}, tracing_settings=None): + # Your async application code here + logger.info("This is non-blocking!") + + Args: + log_format_local_dev_enabled: Enable local development formatting + logger_filter_mapping: Mapping of logger names to filtered message substrings + tracing_settings: OpenTelemetry tracing configuration + log_base_level: Base logging level to set + noisy_loggers: Loggers to set to a quieter level """ - msg = f"TESTING %s log using {logger=}" - logger.critical(msg, "critical") - logger.error(msg, "error") - logger.info(msg, "info") - logger.warning(msg, "warning") - logger.debug(msg, "debug") + formatter = _configure_common_logging_settings( + log_format_local_dev_enabled=log_format_local_dev_enabled, + tracing_settings=tracing_settings, + log_base_level=log_base_level, + noisy_loggers=noisy_loggers, + ) + + with ( + _queued_logging_handler(formatter) as queue_handler, + _stored_logger_states(_get_all_loggers()), + ): + _apply_logging_configuration(queue_handler, logger_filter_mapping) + + with log_context(_logger, logging.INFO, "Asynchronous logging"): + yield class LogExceptionsKwargsDict(TypedDict, total=True): logger: logging.Logger - level: int + level: LogLevelInt msg_prefix: str exc_info: bool stack_info: bool @@ -224,7 +439,7 @@ class LogExceptionsKwargsDict(TypedDict, total=True): @contextmanager def log_exceptions( logger: logging.Logger, - level: int, + level: LogLevelInt, msg_prefix: str = "", *, exc_info: bool = False, @@ -264,7 +479,7 @@ def log_exceptions( def _log_before_call( - logger_obj: logging.Logger, level: int, func: Callable, *args, **kwargs + logger_obj: logging.Logger, level: LogLevelInt, func: Callable, *args, **kwargs ) -> dict[str, str]: # NOTE: We should avoid logging arguments but in the meantime, we are trying to # avoid exposing sensitive data in the logs. For `args` is more difficult. We could eventually @@ -302,7 +517,7 @@ def _log_before_call( def _log_after_call( logger_obj: logging.Logger, - level: int, + level: LogLevelInt, func: Callable, result: Any, extra_args: dict[str, str], @@ -322,7 +537,7 @@ def _log_after_call( def log_decorator( logger: logging.Logger | None, - level: int = logging.DEBUG, + level: LogLevelInt = logging.DEBUG, *, # NOTE: default defined by legacy: ANE defined full stack tracebacks # on exceptions @@ -339,7 +554,6 @@ def log_decorator( logger_obj = logger or _logger def _decorator(func_or_coro: F) -> F: - _log_exc_kwargs = LogExceptionsKwargsDict( logger=logger_obj, level=level, @@ -390,10 +604,6 @@ def log_catch(logger: logging.Logger, *, reraise: bool = True) -> Iterator[None] raise exc from exc -LogLevelInt: TypeAlias = int -LogMessageStr: TypeAlias = str - - def _un_capitalize(s: str) -> str: return s[:1].lower() + s[1:] if s else "" @@ -420,7 +630,7 @@ def log_context( logger.log(level, log_msg, *args, **kwargs, stacklevel=stackelvel) yield duration = ( - f" in {(datetime.now() - start ).total_seconds()}s" # noqa: DTZ005 + f" in {(datetime.now() - start).total_seconds()}s" # noqa: DTZ005 if log_duration else "" ) @@ -456,6 +666,58 @@ def guess_message_log_level(message: str) -> LogLevelInt: return logging.INFO -def set_parent_module_log_level(current_module: str, desired_log_level: int) -> None: +def set_parent_module_log_level( + current_module: str, desired_log_level: LogLevelInt +) -> None: parent_module = ".".join(current_module.split(".")[:-1]) logging.getLogger(parent_module).setLevel(desired_log_level) + + +@dataclass(frozen=True) +class _LoggerState: + logger: logging.Logger + handlers: list[logging.Handler] + propagate: bool + + +@contextmanager +def _stored_logger_states( + loggers: list[logging.Logger], +) -> Iterator[list[_LoggerState]]: + """ + Context manager to store and restore the state of loggers. + It captures the current handlers and propagation state of each logger. + """ + original_state = _store_logger_state(loggers) + + try: + yield original_state + finally: + _restore_logger_state(original_state) + + +def _store_logger_state(loggers: list[logging.Logger]) -> list[_LoggerState]: + logger_states = [ + _LoggerState(logger, logger.handlers.copy(), logger.propagate) + for logger in loggers + if logger.handlers or not logger.propagate + ] + # log which loggers states were stored + _logger.info( + "Stored logger states: %s. TIP: these loggers configuration will be restored later.", + json_dumps( + [ + f"{state.logger.name}(handlers={len(state.handlers)}, propagate={state.propagate})" + for state in logger_states + ] + ), + ) + return logger_states + + +def _restore_logger_state(original_state: list[_LoggerState]) -> None: + for state in original_state: + logger = state.logger + logger.handlers.clear() + logger.handlers.extend(state.handlers) + logger.propagate = state.propagate diff --git a/packages/service-library/tests/conftest.py b/packages/service-library/tests/conftest.py index 45a456fed02..d123e16f12e 100644 --- a/packages/service-library/tests/conftest.py +++ b/packages/service-library/tests/conftest.py @@ -24,6 +24,7 @@ "pytest_simcore.docker", "pytest_simcore.environment_configs", "pytest_simcore.file_extra", + "pytest_simcore.logging", "pytest_simcore.pytest_global_environs", "pytest_simcore.rabbit_service", "pytest_simcore.redis_service", diff --git a/packages/service-library/tests/test_logging_utils.py b/packages/service-library/tests/test_logging_utils.py index d56e07962f2..287487c17c6 100644 --- a/packages/service-library/tests/test_logging_utils.py +++ b/packages/service-library/tests/test_logging_utils.py @@ -13,14 +13,35 @@ LogExtra, LogLevelInt, LogMessageStr, + async_loggers, guess_message_log_level, log_context, log_decorator, log_exceptions, set_parent_module_log_level, ) +from tenacity import ( + retry, + retry_if_exception_type, + stop_after_delay, + wait_fixed, +) _logger = logging.getLogger(__name__) + + +@retry( + wait=wait_fixed(0.01), + stop=stop_after_delay(2.0), + reraise=True, + retry=retry_if_exception_type(AssertionError), +) +def _assert_check_log_message( + caplog: pytest.LogCaptureFixture, expected_message: str +) -> None: + assert expected_message in caplog.text + + _ALL_LOGGING_LEVELS = [ logging.CRITICAL, logging.ERROR, @@ -325,8 +346,9 @@ def test_log_exceptions_and_suppress_without_exc_info( caplog.set_level(level) exc_msg = "logs exceptions and suppresses" - with suppress(ValueError), log_exceptions( - _logger, level, "CONTEXT", exc_info=False + with ( + suppress(ValueError), + log_exceptions(_logger, level, "CONTEXT", exc_info=False), ): raise ValueError(exc_msg) @@ -410,3 +432,144 @@ def test_set_parent_module_log_level_(caplog: pytest.LogCaptureFixture): assert "parent warning" in caplog.text assert "child warning" in caplog.text + + +@pytest.mark.parametrize("log_format_local_dev_enabled", [True, False]) +def test_setup_async_loggers_basic( + caplog: pytest.LogCaptureFixture, + log_format_local_dev_enabled: bool, +): + """Test basic async logging setup without filters.""" + caplog.clear() + caplog.set_level(logging.INFO) + + with async_loggers( + log_format_local_dev_enabled=log_format_local_dev_enabled, + logger_filter_mapping={}, # No filters for this test + tracing_settings=None, # No tracing for this test + log_base_level=logging.INFO, # Set base log level + noisy_loggers=(), # No noisy loggers for this test + ): + test_logger = logging.getLogger("test_async_logger") + test_logger.info("Test async log message") + + _assert_check_log_message(caplog, "Test async log message") + + +def test_setup_async_loggers_with_filters( + caplog: pytest.LogCaptureFixture, +): + caplog.clear() + caplog.set_level(logging.INFO) + + # Define filter mapping + filter_mapping = { + "test_filtered_logger": ["filtered_message"], + } + + with async_loggers( + log_format_local_dev_enabled=True, + logger_filter_mapping=filter_mapping, + tracing_settings=None, # No tracing for this test + log_base_level=logging.INFO, # Set base log level + noisy_loggers=(), # No noisy loggers for this test + ): + test_logger = logging.getLogger("test_filtered_logger") + unfiltered_logger = logging.getLogger("test_unfiltered_logger") + + # This should be filtered out + test_logger.info("This is a filtered_message") + + # This should pass through + test_logger.info("This is an unfiltered message") + unfiltered_logger.info("This is from unfiltered logger") + + _assert_check_log_message(caplog, "This is an unfiltered message") + _assert_check_log_message(caplog, "This is from unfiltered logger") + + # Check that filtered message was not captured + assert "This is a filtered_message" not in caplog.text + + # Check that unfiltered messages were captured + assert "This is an unfiltered message" in caplog.text + assert "This is from unfiltered logger" in caplog.text + + +def test_setup_async_loggers_with_tracing_settings( + caplog: pytest.LogCaptureFixture, +): + """Test async logging setup with tracing settings.""" + caplog.clear() + caplog.set_level(logging.INFO) + + # Note: We can't easily test actual tracing without setting up OpenTelemetry + # But we can test that the function accepts the parameter + with async_loggers( + log_format_local_dev_enabled=False, + logger_filter_mapping={}, # No filters for this test + tracing_settings=None, + log_base_level=logging.INFO, # Set base log level + noisy_loggers=(), # No noisy loggers for this test + ): + test_logger = logging.getLogger("test_tracing_logger") + test_logger.info("Test message with tracing settings") + + _assert_check_log_message(caplog, "Test message with tracing settings") + + +def test_setup_async_loggers_context_manager_cleanup( + caplog: pytest.LogCaptureFixture, +): + """Test that async logging context manager properly cleans up.""" + caplog.clear() + caplog.set_level(logging.DEBUG) + + test_logger = logging.getLogger("test_cleanup_logger") + + with async_loggers( + log_format_local_dev_enabled=True, + logger_filter_mapping={}, + tracing_settings=None, + log_base_level=logging.INFO, # Set base log level + noisy_loggers=(), # No noisy loggers for this test + ): + # During the context, handlers should be replaced + test_logger.info("Message during context") + + _assert_check_log_message(caplog, "Message during context") + + +def test_setup_async_loggers_exception_handling( + caplog: pytest.LogCaptureFixture, +): + """Test that async logging handles exceptions gracefully.""" + caplog.clear() + caplog.set_level(logging.DEBUG) # Set to DEBUG to capture cleanup messages + + def _raise_test_exception(): + """Helper function to raise exception for testing.""" + exc_msg = "Test exception" + raise ValueError(exc_msg) + + try: + with async_loggers( + log_format_local_dev_enabled=True, + logger_filter_mapping={}, + tracing_settings=None, + log_base_level=logging.INFO, # Set base log level + noisy_loggers=(), # No noisy loggers for this test + ): + test_logger = logging.getLogger("test_exception_logger") + test_logger.info("Message before exception") + + _assert_check_log_message(caplog, "Message before exception") + + # Raise an exception to test cleanup + _raise_test_exception() + + except ValueError: + # Expected exception + pass + + # Check that the message was logged and cleanup happened + assert "Message before exception" in caplog.text diff --git a/packages/simcore-sdk/tests/conftest.py b/packages/simcore-sdk/tests/conftest.py index 2cf26c9a49e..e419fbdba8f 100644 --- a/packages/simcore-sdk/tests/conftest.py +++ b/packages/simcore-sdk/tests/conftest.py @@ -28,6 +28,7 @@ "pytest_simcore.docker_compose", "pytest_simcore.docker_swarm", "pytest_simcore.file_extra", + "pytest_simcore.logging", "pytest_simcore.minio_service", "pytest_simcore.postgres_service", "pytest_simcore.pytest_global_environs", diff --git a/services/agent/docker/boot.sh b/services/agent/docker/boot.sh index b972c9dfd78..3b502cd9574 100755 --- a/services/agent/docker/boot.sh +++ b/services/agent/docker/boot.sh @@ -51,7 +51,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then reload_dir_packages=$(fdfind src /devel/packages --exec echo '--reload-dir {} ' | tr '\n' ' ') exec sh -c " cd services/agent/src/simcore_service_agent && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${AGENT_SERVER_REMOTE_DEBUG_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${AGENT_SERVER_REMOTE_DEBUG_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --port 8000 \ --reload \ @@ -60,7 +62,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_agent.main:the_app \ + exec uvicorn \ + --factory simcore_service_agent.main:app_factory \ --host 0.0.0.0 \ --port 8000 \ --log-level "${SERVER_LOG_LEVEL}" \ diff --git a/services/agent/docker/entrypoint.sh b/services/agent/docker/entrypoint.sh index c1697b74b85..a319c6824d7 100755 --- a/services/agent/docker/entrypoint.sh +++ b/services/agent/docker/entrypoint.sh @@ -19,6 +19,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/agent/src/simcore_service_agent/core/application.py b/services/agent/src/simcore_service_agent/core/application.py index 442c4649c62..e7972c1042a 100644 --- a/services/agent/src/simcore_service_agent/core/application.py +++ b/services/agent/src/simcore_service_agent/core/application.py @@ -1,5 +1,6 @@ import logging +from common_library.json_serialization import json_dumps from fastapi import FastAPI from servicelib.fastapi.openapi import ( get_common_oas_options, @@ -9,7 +10,6 @@ initialize_fastapi_app_tracing, setup_tracing, ) -from servicelib.logging_utils import config_all_loggers from .._meta import ( API_VTAG, @@ -27,24 +27,16 @@ from ..services.volumes_manager import setup_volume_manager from .settings import ApplicationSettings -logger = logging.getLogger(__name__) +_logger = logging.getLogger(__name__) -def _setup_logger(settings: ApplicationSettings): - # SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 - logging.basicConfig(level=settings.LOG_LEVEL.value) # NOSONAR - logging.root.setLevel(settings.LOG_LEVEL.value) - config_all_loggers( - log_format_local_dev_enabled=settings.AGENT_VOLUMES_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=settings.AGENT_VOLUMES_LOG_FILTER_MAPPING, - tracing_settings=settings.AGENT_TRACING, - ) - - -def create_app() -> FastAPI: - settings = ApplicationSettings.create_from_envs() - _setup_logger(settings) - logger.debug(settings.model_dump_json(indent=2)) +def create_app(settings: ApplicationSettings | None = None) -> FastAPI: + if settings is None: + settings = ApplicationSettings.create_from_envs() + _logger.info( + "Application settings: %s", + json_dumps(settings, indent=2, sort_keys=True), + ) assert settings.SC_BOOT_MODE # nosec app = FastAPI( diff --git a/services/agent/src/simcore_service_agent/main.py b/services/agent/src/simcore_service_agent/main.py index a16db0c3d52..1af4eb695c2 100644 --- a/services/agent/src/simcore_service_agent/main.py +++ b/services/agent/src/simcore_service_agent/main.py @@ -1,3 +1,36 @@ +import logging +from typing import Final + +from common_library.json_serialization import json_dumps +from fastapi import FastAPI +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_agent.core.application import create_app +from simcore_service_agent.core.settings import ApplicationSettings + +_logger = logging.getLogger(__name__) + +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aio_pika", + "aiormq", + "httpcore", + "httpx", +) + + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.AGENT_VOLUMES_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.AGENT_VOLUMES_LOG_FILTER_MAPPING, + tracing_settings=app_settings.AGENT_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) -the_app = create_app() + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/agent/tests/conftest.py b/services/agent/tests/conftest.py index 624669ce7f4..8213e84ad47 100644 --- a/services/agent/tests/conftest.py +++ b/services/agent/tests/conftest.py @@ -16,6 +16,7 @@ "pytest_simcore.aws_server", "pytest_simcore.docker_compose", "pytest_simcore.docker_swarm", + "pytest_simcore.logging", "pytest_simcore.rabbit_service", "pytest_simcore.repository_paths", ] diff --git a/services/api-server/Makefile b/services/api-server/Makefile index e923de11db8..4db8527326b 100644 --- a/services/api-server/Makefile +++ b/services/api-server/Makefile @@ -30,7 +30,7 @@ define _create_and_validate_openapi # generating openapi specs file under $< (NOTE: Skips DEV FEATURES since this OAS is the 'offically released'!) @source .env; \ export API_SERVER_DEV_FEATURES_ENABLED=$1; \ - python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(the_app.openapi(), indent=2) )" > $@ + python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ # validates OAS file: $@ docker run --rm \ diff --git a/services/api-server/docker/boot.sh b/services/api-server/docker/boot.sh index 1e41a3f8e13..0f19b262c78 100755 --- a/services/api-server/docker/boot.sh +++ b/services/api-server/docker/boot.sh @@ -44,7 +44,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/api-server/src/simcore_service_api_server && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${API_SERVER_REMOTE_DEBUG_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${API_SERVER_REMOTE_DEBUG_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -52,7 +54,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_api_server.main:the_app \ + exec uvicorn \ + --factory simcore_service_api_server.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/api-server/docker/entrypoint.sh b/services/api-server/docker/entrypoint.sh index e5060ff8f7b..0124a12961b 100755 --- a/services/api-server/docker/entrypoint.sh +++ b/services/api-server/docker/entrypoint.sh @@ -20,6 +20,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" USERNAME=scu GROUPNAME=scu diff --git a/services/api-server/src/simcore_service_api_server/cli.py b/services/api-server/src/simcore_service_api_server/cli.py index 11427f61d4e..e4ead859f31 100644 --- a/services/api-server/src/simcore_service_api_server/cli.py +++ b/services/api-server/src/simcore_service_api_server/cli.py @@ -18,6 +18,6 @@ def run(): """Runs application""" typer.secho("Sorry, this entrypoint is intentionally disabled. Use instead") typer.secho( - "$ uvicorn simcore_service_api_server.main:the_app", + "$ uvicorn --factory simcore_service_api_server.main:app_factory", fg=typer.colors.BLUE, ) diff --git a/services/api-server/src/simcore_service_api_server/core/application.py b/services/api-server/src/simcore_service_api_server/core/application.py index 145ff8efb77..33505c35c5f 100644 --- a/services/api-server/src/simcore_service_api_server/core/application.py +++ b/services/api-server/src/simcore_service_api_server/core/application.py @@ -1,5 +1,6 @@ import logging +from common_library.json_serialization import json_dumps from fastapi import FastAPI from fastapi_pagination import add_pagination from models_library.basic_types import BootModeEnum @@ -9,7 +10,6 @@ initialize_fastapi_app_tracing, setup_tracing, ) -from servicelib.logging_utils import config_all_loggers from .. import exceptions from .._meta import API_VERSION, API_VTAG, APP_NAME @@ -48,20 +48,15 @@ def _label_title_and_version(settings: ApplicationSettings, title: str, version: return title, version -def init_app(settings: ApplicationSettings | None = None) -> FastAPI: +def create_app(settings: ApplicationSettings | None = None) -> FastAPI: if settings is None: settings = ApplicationSettings.create_from_envs() + _logger.info( + "Application settings: %s", + json_dumps(settings, indent=2, sort_keys=True), + ) assert settings # nosec - logging.basicConfig(level=settings.log_level) - logging.root.setLevel(settings.log_level) - config_all_loggers( - log_format_local_dev_enabled=settings.API_SERVER_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=settings.API_SERVER_LOG_FILTER_MAPPING, - tracing_settings=settings.API_SERVER_TRACING, - ) - _logger.debug("App settings:\n%s", settings.model_dump_json(indent=2)) - # Labeling title = "osparc.io public API" version = API_VERSION # public version identifier diff --git a/services/api-server/src/simcore_service_api_server/main.py b/services/api-server/src/simcore_service_api_server/main.py index 8b636ac4315..6b8ccc1783f 100644 --- a/services/api-server/src/simcore_service_api_server/main.py +++ b/services/api-server/src/simcore_service_api_server/main.py @@ -1,7 +1,38 @@ -"""Main application to be deployed in for example uvicorn. -""" +"""Main application to be deployed in for example uvicorn.""" + +import logging +from typing import Final + +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from simcore_service_api_server.core.application import init_app +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event +from simcore_service_api_server.core.application import create_app +from simcore_service_api_server.core.settings import ApplicationSettings + +_logger = logging.getLogger(__name__) + +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aio_pika", + "aiormq", + "httpcore", + "httpx", +) + + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.API_SERVER_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.API_SERVER_LOG_FILTER_MAPPING, + tracing_settings=app_settings.API_SERVER_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) -# SINGLETON FastAPI app -the_app: FastAPI = init_app() + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/api-server/tests/conftest.py b/services/api-server/tests/conftest.py index 9aed5258956..2fd59c2f626 100644 --- a/services/api-server/tests/conftest.py +++ b/services/api-server/tests/conftest.py @@ -25,6 +25,7 @@ "pytest_simcore.faker_users_data", "pytest_simcore.httpbin_service", "pytest_simcore.httpx_calls_capture", + "pytest_simcore.logging", "pytest_simcore.pydantic_models", "pytest_simcore.pytest_global_environs", "pytest_simcore.rabbit_service", diff --git a/services/api-server/tests/unit/_with_db/conftest.py b/services/api-server/tests/unit/_with_db/conftest.py index fd2441c879e..90fcea5f809 100644 --- a/services/api-server/tests/unit/_with_db/conftest.py +++ b/services/api-server/tests/unit/_with_db/conftest.py @@ -34,7 +34,7 @@ from simcore_postgres_database.models.products import products from simcore_postgres_database.models.users import users from simcore_service_api_server.clients.postgres import get_engine -from simcore_service_api_server.core.application import init_app +from simcore_service_api_server.core.application import create_app from simcore_service_api_server.core.settings import PostgresSettings from sqlalchemy.ext.asyncio import AsyncEngine @@ -187,7 +187,7 @@ def app(app_environment: EnvVarsDict, migrated_db: None) -> FastAPI: - it uses default environ as pg - db is started and initialized """ - return init_app() + return create_app() @pytest.fixture diff --git a/services/api-server/tests/unit/_with_db/data/docker-compose.yml b/services/api-server/tests/unit/_with_db/data/docker-compose.yml index ae76474af7c..75eb2f48245 100644 --- a/services/api-server/tests/unit/_with_db/data/docker-compose.yml +++ b/services/api-server/tests/unit/_with_db/data/docker-compose.yml @@ -1,6 +1,6 @@ services: postgres: - image: postgres:14.5-alpine@sha256:db802f226b620fc0b8adbeca7859eb203c8d3c9ce5d84870fadee05dea8f50ce + image: "postgres:14.8-alpine@sha256:150dd39ccb7ae6c7ba6130c3582c39a30bb5d3d22cb08ad0ba37001e3f829abc" environment: - POSTGRES_USER=${POSTGRES_USER:-test} - POSTGRES_PASSWORD=${POSTGRES_PASSWORD:-test} diff --git a/services/api-server/tests/unit/conftest.py b/services/api-server/tests/unit/conftest.py index 5879d2a25ba..84837222595 100644 --- a/services/api-server/tests/unit/conftest.py +++ b/services/api-server/tests/unit/conftest.py @@ -54,7 +54,7 @@ from pytest_simcore.simcore_webserver_projects_rest_api import GET_PROJECT from requests.auth import HTTPBasicAuth from respx import MockRouter -from simcore_service_api_server.core.application import init_app +from simcore_service_api_server.core.application import create_app from simcore_service_api_server.core.settings import ApplicationSettings from simcore_service_api_server.repository.api_keys import UserAndProductTuple from simcore_service_api_server.services_http.solver_job_outputs import ResultsTypes @@ -131,7 +131,7 @@ def app( patch_lrt_response_urls() - return init_app() + return create_app() MAX_TIME_FOR_APP_TO_STARTUP = 10 diff --git a/services/api-server/tests/unit/test_cli.py b/services/api-server/tests/unit/test_cli.py index febeca14b1f..f96be2ffb2f 100644 --- a/services/api-server/tests/unit/test_cli.py +++ b/services/api-server/tests/unit/test_cli.py @@ -34,7 +34,7 @@ def test_cli_list_settings(cli_runner: CliRunner, app_environment: EnvVarsDict): def test_main(app_environment: EnvVarsDict): - from simcore_service_api_server.main import the_app + from simcore_service_api_server.main import app_factory - assert the_app + the_app = app_factory() assert isinstance(the_app, FastAPI) diff --git a/services/autoscaling/docker/boot.sh b/services/autoscaling/docker/boot.sh index 79f86d977af..8a5d3adb709 100755 --- a/services/autoscaling/docker/boot.sh +++ b/services/autoscaling/docker/boot.sh @@ -51,7 +51,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/autoscaling/src/simcore_service_autoscaling && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${AUTOSCALING_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${AUTOSCALING_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -59,7 +61,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_autoscaling.main:the_app \ + exec uvicorn \ + --factory simcore_service_autoscaling.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/autoscaling/docker/entrypoint.sh b/services/autoscaling/docker/entrypoint.sh index 1071a664b92..651a1ea875f 100755 --- a/services/autoscaling/docker/entrypoint.sh +++ b/services/autoscaling/docker/entrypoint.sh @@ -26,6 +26,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/autoscaling/src/simcore_service_autoscaling/cli.py b/services/autoscaling/src/simcore_service_autoscaling/cli.py index c02e20e348b..c280b67368a 100644 --- a/services/autoscaling/src/simcore_service_autoscaling/cli.py +++ b/services/autoscaling/src/simcore_service_autoscaling/cli.py @@ -19,6 +19,6 @@ def run(): """Runs application""" typer.secho("Sorry, this entrypoint is intentionally disabled. Use instead") typer.secho( - "$ uvicorn simcore_service_autoscaling.main:the_app", + "$ uvicorn --factory simcore_service_autoscaling.main:app_factory", fg=typer.colors.BLUE, ) diff --git a/services/autoscaling/src/simcore_service_autoscaling/core/application.py b/services/autoscaling/src/simcore_service_autoscaling/core/application.py index f0c9d7f3c32..ba833512565 100644 --- a/services/autoscaling/src/simcore_service_autoscaling/core/application.py +++ b/services/autoscaling/src/simcore_service_autoscaling/core/application.py @@ -31,28 +31,10 @@ from ..modules.ssm import setup as setup_ssm from .settings import ApplicationSettings -_LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -_NOISY_LOGGERS = ( - "aiobotocore", - "aio_pika", - "aiormq", - "botocore", - "werkzeug", -) - logger = logging.getLogger(__name__) def create_app(settings: ApplicationSettings) -> FastAPI: - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + _LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING - ) - for name in _NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) - - logger.info("app settings: %s", settings.model_dump_json(indent=1)) - app = FastAPI( debug=settings.AUTOSCALING_DEBUG, title=APP_NAME, diff --git a/services/autoscaling/src/simcore_service_autoscaling/core/settings.py b/services/autoscaling/src/simcore_service_autoscaling/core/settings.py index ff67aeeaab1..f39f7b0208b 100644 --- a/services/autoscaling/src/simcore_service_autoscaling/core/settings.py +++ b/services/autoscaling/src/simcore_service_autoscaling/core/settings.py @@ -17,6 +17,7 @@ model_validator, ) from pydantic_settings import SettingsConfigDict +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.application import BaseApplicationSettings from settings_library.base import BaseCustomSettings @@ -34,8 +35,7 @@ AUTOSCALING_ENV_PREFIX: Final[str] = "AUTOSCALING_" -class AutoscalingSSMSettings(SSMSettings): - ... +class AutoscalingSSMSettings(SSMSettings): ... class AutoscalingEC2Settings(EC2Settings): @@ -361,8 +361,8 @@ class ApplicationSettings(BaseApplicationSettings, MixinLoggingSettings): ] = False @cached_property - def LOG_LEVEL(self): # noqa: N802 - return self.AUTOSCALING_LOGLEVEL + def log_level(self) -> LogLevelInt: + return cast(LogLevelInt, self.AUTOSCALING_LOGLEVEL) @field_validator("AUTOSCALING_LOGLEVEL", mode="before") @classmethod diff --git a/services/autoscaling/src/simcore_service_autoscaling/main.py b/services/autoscaling/src/simcore_service_autoscaling/main.py index 102258cac70..b1f7055d75d 100644 --- a/services/autoscaling/src/simcore_service_autoscaling/main.py +++ b/services/autoscaling/src/simcore_service_autoscaling/main.py @@ -1,22 +1,39 @@ -"""Main application to be deployed by uvicorn (or equivalent) server - -""" +"""Main application to be deployed by uvicorn (or equivalent) server""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_autoscaling.core.application import create_app from simcore_service_autoscaling.core.settings import ApplicationSettings -the_settings = ApplicationSettings.create_from_envs() -logging.basicConfig(level=the_settings.log_level) -logging.root.setLevel(the_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=the_settings.AUTOSCALING_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=the_settings.AUTOSCALING_LOG_FILTER_MAPPING, - tracing_settings=the_settings.AUTOSCALING_TRACING, +_logger = logging.getLogger(__name__) + +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aiobotocore", + "aio_pika", + "aiormq", + "botocore", + "werkzeug", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.AUTOSCALING_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.AUTOSCALING_LOG_FILTER_MAPPING, + tracing_settings=app_settings.AUTOSCALING_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/autoscaling/tests/unit/conftest.py b/services/autoscaling/tests/unit/conftest.py index d348fd7abe0..97e852b44d6 100644 --- a/services/autoscaling/tests/unit/conftest.py +++ b/services/autoscaling/tests/unit/conftest.py @@ -110,6 +110,7 @@ "pytest_simcore.docker_compose", "pytest_simcore.docker_swarm", "pytest_simcore.environment_configs", + "pytest_simcore.logging", "pytest_simcore.rabbit_service", "pytest_simcore.repository_paths", ] diff --git a/services/autoscaling/tests/unit/test_main.py b/services/autoscaling/tests/unit/test_main.py index 525748023ec..b1e0b41985a 100644 --- a/services/autoscaling/tests/unit/test_main.py +++ b/services/autoscaling/tests/unit/test_main.py @@ -7,6 +7,6 @@ def test_main_app(app_environment: EnvVarsDict): - from simcore_service_autoscaling.main import the_app, the_settings + from simcore_service_autoscaling.main import app_factory - assert the_app.state.settings == the_settings + app_factory() diff --git a/services/catalog/Makefile b/services/catalog/Makefile index 31b3a327698..6fa07010255 100644 --- a/services/catalog/Makefile +++ b/services/catalog/Makefile @@ -17,7 +17,7 @@ openapi.json: .env-ignore @set -o allexport; \ source $<; \ set +o allexport; \ - python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(the_app.openapi(), indent=2) )" > $@ + python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ # validates OAS file: $@ $(call validate_openapi_specs,$@) diff --git a/services/catalog/docker/boot.sh b/services/catalog/docker/boot.sh index 3efc6789681..81a4874d3fc 100755 --- a/services/catalog/docker/boot.sh +++ b/services/catalog/docker/boot.sh @@ -44,7 +44,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/catalog/src/simcore_service_catalog && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${CATALOG_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${CATALOG_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -52,7 +54,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_catalog.main:the_app \ + exec uvicorn \ + --factory simcore_service_catalog.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/catalog/docker/entrypoint.sh b/services/catalog/docker/entrypoint.sh index 9e820488a53..5e534412b4a 100755 --- a/services/catalog/docker/entrypoint.sh +++ b/services/catalog/docker/entrypoint.sh @@ -20,6 +20,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" USERNAME=scu GROUPNAME=scu diff --git a/services/catalog/src/simcore_service_catalog/cli.py b/services/catalog/src/simcore_service_catalog/cli.py index 0d4fbf5107b..9fd453f1f55 100644 --- a/services/catalog/src/simcore_service_catalog/cli.py +++ b/services/catalog/src/simcore_service_catalog/cli.py @@ -30,7 +30,7 @@ def run(): """Runs application""" typer.secho("Sorry, this entrypoint is intentionally disabled. Use instead") typer.secho( - "$ uvicorn simcore_service_catalog.main:the_app", + "$ uvicorn --factory simcore_service_catalog.main:app_factory", fg=typer.colors.BLUE, ) diff --git a/services/catalog/src/simcore_service_catalog/core/application.py b/services/catalog/src/simcore_service_catalog/core/application.py index 3f726883066..1d579741862 100644 --- a/services/catalog/src/simcore_service_catalog/core/application.py +++ b/services/catalog/src/simcore_service_catalog/core/application.py @@ -1,9 +1,11 @@ import logging +from common_library.json_serialization import json_dumps from fastapi import FastAPI from fastapi.middleware.gzip import GZipMiddleware from models_library.basic_types import BootModeEnum from servicelib.fastapi import timing_middleware +from servicelib.fastapi.lifespan_utils import Lifespan from servicelib.fastapi.monitoring import ( setup_prometheus_instrumentation, ) @@ -27,27 +29,18 @@ _logger = logging.getLogger(__name__) -_LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -_NOISY_LOGGERS = ( - "aio_pika", - "aiobotocore", - "aiormq", - "botocore", - "httpcore", - "werkzeug", -) - -def create_app() -> FastAPI: - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + _LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING - ) - for name in _NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) - - settings = ApplicationSettings.create_from_envs() - _logger.debug(settings.model_dump_json(indent=2)) +def create_app( + *, + settings: ApplicationSettings | None = None, + logging_lifespan: Lifespan | None = None, +) -> FastAPI: + if not settings: + settings = ApplicationSettings.create_from_envs() + _logger.info( + "Application settings: %s", + json_dumps(settings, indent=2, sort_keys=True), + ) app = FastAPI( debug=settings.SC_BOOT_MODE @@ -58,7 +51,7 @@ def create_app() -> FastAPI: openapi_url=f"/api/{API_VTAG}/openapi.json", docs_url="/dev/doc", redoc_url=None, # default disabled - lifespan=events.create_app_lifespan(), + lifespan=events.create_app_lifespan(logging_lifespan=logging_lifespan), ) override_fastapi_openapi_method(app) diff --git a/services/catalog/src/simcore_service_catalog/core/events.py b/services/catalog/src/simcore_service_catalog/core/events.py index 8695b10f15e..673bdf2f80f 100644 --- a/services/catalog/src/simcore_service_catalog/core/events.py +++ b/services/catalog/src/simcore_service_catalog/core/events.py @@ -3,6 +3,7 @@ from fastapi import FastAPI from fastapi_lifespan_manager import LifespanManager, State +from servicelib.fastapi.lifespan_utils import Lifespan from servicelib.fastapi.monitoring import ( create_prometheus_instrumentationmain_input_state, prometheus_instrumentation_lifespan, @@ -50,9 +51,11 @@ async def _settings_lifespan(app: FastAPI) -> AsyncIterator[State]: } -def create_app_lifespan() -> LifespanManager: +def create_app_lifespan(logging_lifespan: Lifespan | None = None) -> LifespanManager: # WARNING: order matters app_lifespan = LifespanManager() + if logging_lifespan: + app_lifespan.add(logging_lifespan) app_lifespan.add(_settings_lifespan) # - postgres diff --git a/services/catalog/src/simcore_service_catalog/main.py b/services/catalog/src/simcore_service_catalog/main.py index 52bd949a542..60f5da962d4 100644 --- a/services/catalog/src/simcore_service_catalog/main.py +++ b/services/catalog/src/simcore_service_catalog/main.py @@ -1,24 +1,40 @@ -"""Main application to be deployed in for example uvicorn. -""" +"""Main application to be deployed in for example uvicorn.""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_lifespan from simcore_service_catalog.core.application import create_app from simcore_service_catalog.core.settings import ApplicationSettings -_the_settings = ApplicationSettings.create_from_envs() +_logger = logging.getLogger(__name__) -# SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 -logging.basicConfig(level=_the_settings.log_level) # NOSONAR -logging.root.setLevel(_the_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=_the_settings.CATALOG_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=_the_settings.CATALOG_LOG_FILTER_MAPPING, - tracing_settings=_the_settings.CATALOG_TRACING, + +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aio_pika", + "aiobotocore", + "aiormq", + "botocore", + "httpcore", + "werkzeug", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app() +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_lifespan = create_logging_lifespan( + log_format_local_dev_enabled=app_settings.CATALOG_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.CATALOG_LOG_FILTER_MAPPING, + tracing_settings=app_settings.CATALOG_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + + return create_app(settings=app_settings, logging_lifespan=logging_lifespan) diff --git a/services/catalog/tests/unit/conftest.py b/services/catalog/tests/unit/conftest.py index 3cc1e633efc..0088fa436a0 100644 --- a/services/catalog/tests/unit/conftest.py +++ b/services/catalog/tests/unit/conftest.py @@ -44,6 +44,7 @@ "pytest_simcore.environment_configs", "pytest_simcore.faker_products_data", "pytest_simcore.faker_users_data", + "pytest_simcore.logging", "pytest_simcore.postgres_service", "pytest_simcore.pydantic_models", "pytest_simcore.pytest_global_environs", @@ -179,7 +180,6 @@ def client( assert spy_app.on_shutdown.call_count == 0 with TestClient(app_under_test) as cli: - assert spy_app.on_startup.call_count == 1 assert spy_app.on_shutdown.call_count == 0 @@ -392,7 +392,6 @@ def mocked_director_rest_api_base( assert_all_called=False, assert_all_mocked=True, ) as respx_mock: - # HEATHCHECK assert openapi["paths"].get("/") respx_mock.head("/", name="healthcheck").respond( diff --git a/services/clusters-keeper/docker/boot.sh b/services/clusters-keeper/docker/boot.sh index 562dcc89f14..c465ac2316f 100755 --- a/services/clusters-keeper/docker/boot.sh +++ b/services/clusters-keeper/docker/boot.sh @@ -52,7 +52,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/clusters-keeper/src/simcore_service_clusters_keeper && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${CLUSTERS_KEEPER_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${CLUSTERS_KEEPER_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -60,7 +62,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_clusters_keeper.main:the_app \ + exec uvicorn \ + --factory simcore_service_clusters_keeper.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/clusters-keeper/docker/entrypoint.sh b/services/clusters-keeper/docker/entrypoint.sh index 1071a664b92..651a1ea875f 100755 --- a/services/clusters-keeper/docker/entrypoint.sh +++ b/services/clusters-keeper/docker/entrypoint.sh @@ -26,6 +26,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/clusters-keeper/src/simcore_service_clusters_keeper/cli.py b/services/clusters-keeper/src/simcore_service_clusters_keeper/cli.py index b65355463c4..66a71546a00 100644 --- a/services/clusters-keeper/src/simcore_service_clusters_keeper/cli.py +++ b/services/clusters-keeper/src/simcore_service_clusters_keeper/cli.py @@ -19,6 +19,6 @@ def run(): """Runs application""" typer.secho("Sorry, this entrypoint is intentionally disabled. Use instead") typer.secho( - "$ uvicorn simcore_service_clusters_keeper.main:the_app", + "$ uvicorn --factory simcore_service_clusters_keeper.main:app_factory", fg=typer.colors.BLUE, ) diff --git a/services/clusters-keeper/src/simcore_service_clusters_keeper/core/application.py b/services/clusters-keeper/src/simcore_service_clusters_keeper/core/application.py index bbda1b456a4..1c8c7e448c0 100644 --- a/services/clusters-keeper/src/simcore_service_clusters_keeper/core/application.py +++ b/services/clusters-keeper/src/simcore_service_clusters_keeper/core/application.py @@ -26,26 +26,10 @@ from ..rpc.rpc_routes import setup_rpc_routes from .settings import ApplicationSettings -_LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -_NOISY_LOGGERS = ( - "aiobotocore", - "aio_pika", - "aiormq", - "botocore", - "werkzeug", -) - _logger = logging.getLogger(__name__) def create_app(settings: ApplicationSettings) -> FastAPI: - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + _LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING - ) - for name in _NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) - _logger.info("app settings: %s", settings.model_dump_json(indent=1)) app = FastAPI( diff --git a/services/clusters-keeper/src/simcore_service_clusters_keeper/core/settings.py b/services/clusters-keeper/src/simcore_service_clusters_keeper/core/settings.py index 525148fa257..2fde9fcbcd8 100644 --- a/services/clusters-keeper/src/simcore_service_clusters_keeper/core/settings.py +++ b/services/clusters-keeper/src/simcore_service_clusters_keeper/core/settings.py @@ -23,6 +23,7 @@ field_validator, ) from pydantic_settings import SettingsConfigDict +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.base import BaseCustomSettings from settings_library.docker_registry import RegistrySettings @@ -454,8 +455,8 @@ class ApplicationSettings(BaseCustomSettings, MixinLoggingSettings): ] @cached_property - def LOG_LEVEL(self) -> LogLevel: # noqa: N802 - return self.CLUSTERS_KEEPER_LOGLEVEL + def log_level(self) -> LogLevelInt: + return cast(LogLevelInt, self.CLUSTERS_KEEPER_LOGLEVEL) @field_validator("CLUSTERS_KEEPER_LOGLEVEL", mode="before") @classmethod diff --git a/services/clusters-keeper/src/simcore_service_clusters_keeper/main.py b/services/clusters-keeper/src/simcore_service_clusters_keeper/main.py index b2844bde6af..d4e4bdf99ee 100644 --- a/services/clusters-keeper/src/simcore_service_clusters_keeper/main.py +++ b/services/clusters-keeper/src/simcore_service_clusters_keeper/main.py @@ -1,22 +1,39 @@ -"""Main application to be deployed by uvicorn (or equivalent) server - -""" +"""Main application to be deployed by uvicorn (or equivalent) server""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_clusters_keeper.core.application import create_app from simcore_service_clusters_keeper.core.settings import ApplicationSettings -the_settings = ApplicationSettings.create_from_envs() -logging.basicConfig(level=the_settings.log_level) -logging.root.setLevel(the_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=the_settings.CLUSTERS_KEEPER_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=the_settings.CLUSTERS_KEEPER_LOG_FILTER_MAPPING, - tracing_settings=the_settings.CLUSTERS_KEEPER_TRACING, +_logger = logging.getLogger(__name__) + +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aiobotocore", + "aio_pika", + "aiormq", + "botocore", + "werkzeug", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.CLUSTERS_KEEPER_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.CLUSTERS_KEEPER_LOG_FILTER_MAPPING, + tracing_settings=app_settings.CLUSTERS_KEEPER_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/clusters-keeper/src/simcore_service_clusters_keeper/utils/clusters.py b/services/clusters-keeper/src/simcore_service_clusters_keeper/utils/clusters.py index d2820ef2b88..81bd7279399 100644 --- a/services/clusters-keeper/src/simcore_service_clusters_keeper/utils/clusters.py +++ b/services/clusters-keeper/src/simcore_service_clusters_keeper/utils/clusters.py @@ -96,7 +96,7 @@ def _convert_to_env_dict(entries: dict[str, Any]) -> str: f"DASK_WORKER_SATURATION={app_settings.CLUSTERS_KEEPER_DASK_WORKER_SATURATION}", f"DOCKER_IMAGE_TAG={app_settings.CLUSTERS_KEEPER_COMPUTATIONAL_BACKEND_DOCKER_IMAGE_TAG}", f"EC2_INSTANCES_NAME_PREFIX={cluster_machines_name_prefix}", - f"LOG_LEVEL={app_settings.LOG_LEVEL}", + f"LOG_LEVEL={app_settings.log_level}", f"WORKERS_EC2_INSTANCES_ALLOWED_TYPES={_convert_to_env_dict(app_settings.CLUSTERS_KEEPER_WORKERS_EC2_INSTANCES.WORKERS_EC2_INSTANCES_ALLOWED_TYPES)}", f"WORKERS_EC2_INSTANCES_CUSTOM_TAGS={_convert_to_env_dict(app_settings.CLUSTERS_KEEPER_WORKERS_EC2_INSTANCES.WORKERS_EC2_INSTANCES_CUSTOM_TAGS | additional_custom_tags)}", f"WORKERS_EC2_INSTANCES_KEY_NAME={app_settings.CLUSTERS_KEEPER_WORKERS_EC2_INSTANCES.WORKERS_EC2_INSTANCES_KEY_NAME}", diff --git a/services/clusters-keeper/tests/unit/conftest.py b/services/clusters-keeper/tests/unit/conftest.py index 43bb1bacde1..15c52ee996d 100644 --- a/services/clusters-keeper/tests/unit/conftest.py +++ b/services/clusters-keeper/tests/unit/conftest.py @@ -48,6 +48,7 @@ "pytest_simcore.docker_swarm", "pytest_simcore.environment_configs", "pytest_simcore.faker_users_data", + "pytest_simcore.logging", "pytest_simcore.rabbit_service", "pytest_simcore.repository_paths", "pytest_simcore.simcore_service_library_fixtures", diff --git a/services/clusters-keeper/tests/unit/test_main.py b/services/clusters-keeper/tests/unit/test_main.py index 96d7fb8507d..13cd355678c 100644 --- a/services/clusters-keeper/tests/unit/test_main.py +++ b/services/clusters-keeper/tests/unit/test_main.py @@ -7,6 +7,6 @@ def test_main_app(app_environment: EnvVarsDict): - from simcore_service_clusters_keeper.main import the_app, the_settings + from simcore_service_clusters_keeper.main import app_factory - assert the_app.state.settings == the_settings + app_factory() diff --git a/services/dask-sidecar/src/simcore_service_dask_sidecar/settings.py b/services/dask-sidecar/src/simcore_service_dask_sidecar/settings.py index e0a3e41d3a5..f2629768175 100644 --- a/services/dask-sidecar/src/simcore_service_dask_sidecar/settings.py +++ b/services/dask-sidecar/src/simcore_service_dask_sidecar/settings.py @@ -1,8 +1,10 @@ +from functools import cached_property from pathlib import Path -from typing import Annotated, Any +from typing import Annotated, Any, cast from models_library.basic_types import LogLevel from pydantic import AliasChoices, Field, field_validator +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.application import BaseApplicationSettings from settings_library.rabbit import RabbitSettings @@ -61,6 +63,10 @@ class ApplicationSettings(BaseApplicationSettings, MixinLoggingSettings): RabbitSettings | None, Field(json_schema_extra={"auto_default_from_env": True}) ] + @cached_property + def log_level(self) -> LogLevelInt: + return cast(LogLevelInt, self.DASK_SIDECAR_LOGLEVEL) + @field_validator("DASK_SIDECAR_LOGLEVEL", mode="before") @classmethod def _validate_loglevel(cls, value: Any) -> str: diff --git a/services/dask-sidecar/src/simcore_service_dask_sidecar/utils/logs.py b/services/dask-sidecar/src/simcore_service_dask_sidecar/utils/logs.py index 74b158de9e2..76eaef67431 100644 --- a/services/dask-sidecar/src/simcore_service_dask_sidecar/utils/logs.py +++ b/services/dask-sidecar/src/simcore_service_dask_sidecar/utils/logs.py @@ -1,20 +1,21 @@ -import logging +from typing import Final -from servicelib.logging_utils import config_all_loggers +from servicelib.logging_utils import setup_loggers from ..settings import ApplicationSettings +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aio_pika", + "aiormq", + "werkzeug", +) + def setup_app_logging(settings: ApplicationSettings) -> None: - # set up logging - logging.basicConfig(level=settings.DASK_SIDECAR_LOGLEVEL.value) - logging.root.setLevel(level=settings.DASK_SIDECAR_LOGLEVEL.value) - # NOTE: Dask attaches a StreamHandler to the logger in distributed - # removing them solves dual propagation of logs - for handler in logging.getLogger("distributed").handlers: - logging.getLogger("distributed").removeHandler(handler) - config_all_loggers( + setup_loggers( log_format_local_dev_enabled=settings.DASK_LOG_FORMAT_LOCAL_DEV_ENABLED, logger_filter_mapping=settings.DASK_LOG_FILTER_MAPPING, tracing_settings=None, # no tracing for dask sidecar + log_base_level=settings.log_level, + noisy_loggers=_NOISY_LOGGERS, ) diff --git a/services/dask-sidecar/tests/unit/conftest.py b/services/dask-sidecar/tests/unit/conftest.py index 2e3fb246f88..e4bc735025c 100644 --- a/services/dask-sidecar/tests/unit/conftest.py +++ b/services/dask-sidecar/tests/unit/conftest.py @@ -42,6 +42,7 @@ "pytest_simcore.docker_swarm", "pytest_simcore.environment_configs", "pytest_simcore.faker_users_data", + "pytest_simcore.logging", "pytest_simcore.rabbit_service", "pytest_simcore.repository_paths", ] diff --git a/services/datcore-adapter/docker/boot.sh b/services/datcore-adapter/docker/boot.sh index ca19372d572..d4c20cad1ab 100755 --- a/services/datcore-adapter/docker/boot.sh +++ b/services/datcore-adapter/docker/boot.sh @@ -49,7 +49,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/datcore-adapter/src/simcore_service_datcore_adapter && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DATCORE_ADAPTER_REMOTE_DEBUG_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DATCORE_ADAPTER_REMOTE_DEBUG_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -57,7 +59,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_datcore_adapter.main:the_app \ + exec uvicorn \ + --factory simcore_service_datcore_adapter.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/datcore-adapter/docker/entrypoint.sh b/services/datcore-adapter/docker/entrypoint.sh index b55d4bc7716..357d8b604d9 100755 --- a/services/datcore-adapter/docker/entrypoint.sh +++ b/services/datcore-adapter/docker/entrypoint.sh @@ -19,6 +19,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/datcore-adapter/src/simcore_service_datcore_adapter/cli.py b/services/datcore-adapter/src/simcore_service_datcore_adapter/cli.py index 60839168e97..79006573380 100644 --- a/services/datcore-adapter/src/simcore_service_datcore_adapter/cli.py +++ b/services/datcore-adapter/src/simcore_service_datcore_adapter/cli.py @@ -20,6 +20,6 @@ def run() -> None: """Runs application""" typer.secho("Sorry, this entrypoint is intentionally disabled. Use instead") typer.secho( - f"$ uvicorn {PROJECT_NAME}.main:the_app", + f"$ uvicorn --factory {PROJECT_NAME}.main:app_factory", fg=typer.colors.BLUE, ) diff --git a/services/datcore-adapter/src/simcore_service_datcore_adapter/core/application.py b/services/datcore-adapter/src/simcore_service_datcore_adapter/core/application.py index 50fd0b8b888..397a686e746 100644 --- a/services/datcore-adapter/src/simcore_service_datcore_adapter/core/application.py +++ b/services/datcore-adapter/src/simcore_service_datcore_adapter/core/application.py @@ -27,27 +27,10 @@ ) from .settings import ApplicationSettings -LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -NOISY_LOGGERS = ( - "aiocache", - "botocore", - "hpack", -) - _logger = logging.getLogger(__name__) def create_app(settings: ApplicationSettings) -> FastAPI: - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING - ) - - for name in NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) - - _logger.debug("App settings:\n%s", settings.model_dump_json(indent=1)) - app = FastAPI( debug=settings.SC_BOOT_MODE in [BootModeEnum.DEBUG, BootModeEnum.DEVELOPMENT, BootModeEnum.LOCAL], diff --git a/services/datcore-adapter/src/simcore_service_datcore_adapter/main.py b/services/datcore-adapter/src/simcore_service_datcore_adapter/main.py index 7bd6a787163..0a46179524d 100644 --- a/services/datcore-adapter/src/simcore_service_datcore_adapter/main.py +++ b/services/datcore-adapter/src/simcore_service_datcore_adapter/main.py @@ -1,22 +1,37 @@ """Main application to be deployed in for example uvicorn""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_datcore_adapter.core.application import create_app from simcore_service_datcore_adapter.core.settings import ApplicationSettings -_the_settings = ApplicationSettings.create_from_envs() +_logger = logging.getLogger(__name__) -# SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 -logging.basicConfig(level=_the_settings.log_level) # NOSONAR -logging.root.setLevel(_the_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=_the_settings.DATCORE_ADAPTER_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=_the_settings.DATCORE_ADAPTER_LOG_FILTER_MAPPING, - tracing_settings=_the_settings.DATCORE_ADAPTER_TRACING, +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aiocache", + "botocore", + "hpack", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(_the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.DATCORE_ADAPTER_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.DATCORE_ADAPTER_LOG_FILTER_MAPPING, + tracing_settings=app_settings.DATCORE_ADAPTER_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/datcore-adapter/tests/unit/conftest.py b/services/datcore-adapter/tests/unit/conftest.py index 65120234b3e..976d86ad334 100644 --- a/services/datcore-adapter/tests/unit/conftest.py +++ b/services/datcore-adapter/tests/unit/conftest.py @@ -28,6 +28,7 @@ "pytest_simcore.asyncio_event_loops", "pytest_simcore.cli_runner", "pytest_simcore.environment_configs", + "pytest_simcore.logging", "pytest_simcore.repository_paths", "pytest_simcore.pytest_global_environs", ] @@ -70,9 +71,9 @@ def pennsieve_mock_dataset_packages(mocks_dir: Path) -> dict[str, Any]: def minimal_app( app_environment: None, ) -> FastAPI: - from simcore_service_datcore_adapter.main import the_app + from simcore_service_datcore_adapter.main import app_factory - return the_app + return app_factory() @pytest.fixture() diff --git a/services/director-v2/Makefile b/services/director-v2/Makefile index 030084bcb4e..0332ca3a657 100644 --- a/services/director-v2/Makefile +++ b/services/director-v2/Makefile @@ -18,7 +18,7 @@ openapi.json: .env @set -o allexport; \ source .env; \ set +o allexport; \ - python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(the_app.openapi(), indent=2) )" > $@ + python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ DOCKER_API_VERSION ?= 1.41 @@ -65,7 +65,7 @@ down down-extra: ## stops extra stack run-devel: .env up-extra ## starts app with extra stack # start app (within $<) in devel mode - uvicorn $(APP_PACKAGE_NAME).__main__:the_app \ + uvicorn --factory $(APP_PACKAGE_NAME).__main__:app_factory \ --reload --reload-dir $(SRC_DIR) \ --port=8000 --host=0.0.0.0 diff --git a/services/director-v2/docker-compose-extra.yml b/services/director-v2/docker-compose-extra.yml index 5923b000384..4ec97a3c48b 100644 --- a/services/director-v2/docker-compose-extra.yml +++ b/services/director-v2/docker-compose-extra.yml @@ -1,6 +1,6 @@ services: postgres: - image: postgres:14.5-alpine@sha256:db802f226b620fc0b8adbeca7859eb203c8d3c9ce5d84870fadee05dea8f50ce + image: "postgres:14.8-alpine@sha256:150dd39ccb7ae6c7ba6130c3582c39a30bb5d3d22cb08ad0ba37001e3f829abc" init: true environment: - POSTGRES_USER=${POSTGRES_USER:-test} diff --git a/services/director-v2/docker/boot.sh b/services/director-v2/docker/boot.sh index 9dc04a97fcf..b8d637b23ec 100755 --- a/services/director-v2/docker/boot.sh +++ b/services/director-v2/docker/boot.sh @@ -51,7 +51,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/director-v2/src/simcore_service_director_v2 && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DIRECTOR_V2_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DIRECTOR_V2_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -59,7 +61,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_director_v2.main:the_app \ + exec uvicorn \ + --factory simcore_service_director_v2.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/director-v2/docker/entrypoint.sh b/services/director-v2/docker/entrypoint.sh index 244f9b6a1db..9d5a38625a1 100755 --- a/services/director-v2/docker/entrypoint.sh +++ b/services/director-v2/docker/entrypoint.sh @@ -26,6 +26,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/director-v2/src/simcore_service_director_v2/cli/_core.py b/services/director-v2/src/simcore_service_director_v2/cli/_core.py index bc7cc095898..f857949b274 100644 --- a/services/director-v2/src/simcore_service_director_v2/cli/_core.py +++ b/services/director-v2/src/simcore_service_director_v2/cli/_core.py @@ -16,7 +16,6 @@ from rich.live import Live from rich.table import Table from servicelib.services_utils import get_service_from_key -from simcore_service_director_v2.modules.catalog import CatalogClient from tenacity.asyncio import AsyncRetrying from tenacity.stop import stop_after_attempt from tenacity.wait import wait_random_exponential @@ -25,6 +24,7 @@ from ..core.settings import AppSettings from ..models.dynamic_services_scheduler import DynamicSidecarNamesHelper from ..modules import db, director_v0, dynamic_sidecar +from ..modules.catalog import CatalogClient from ..modules.db.repositories.projects import ProjectsRepository from ..modules.dynamic_sidecar import api_client from ..modules.projects_networks import requires_dynamic_sidecar diff --git a/services/director-v2/src/simcore_service_director_v2/core/application.py b/services/director-v2/src/simcore_service_director_v2/core/application.py index 9dfc9ec6974..4a9c71605dc 100644 --- a/services/director-v2/src/simcore_service_director_v2/core/application.py +++ b/services/director-v2/src/simcore_service_director_v2/core/application.py @@ -1,7 +1,12 @@ import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI, HTTPException, status from fastapi.exceptions import RequestValidationError +from fastapi_lifespan_manager import LifespanManager +from servicelib.fastapi.lifespan_utils import Lifespan +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from servicelib.fastapi.openapi import ( get_common_oas_options, override_fastapi_openapi_method, @@ -11,7 +16,6 @@ initialize_fastapi_app_tracing, setup_tracing, ) -from servicelib.logging_utils import config_all_loggers from .._meta import API_VERSION, API_VTAG, APP_NAME, PROJECT_NAME, SUMMARY from ..api.entrypoints import api_router @@ -49,6 +53,13 @@ _logger = logging.getLogger(__name__) +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aio_pika", + "aiormq", + "httpcore", + "httpx", +) + def _set_exception_handlers(app: FastAPI): app.add_exception_handler(HTTPException, http_error_handler) @@ -94,57 +105,65 @@ def _set_exception_handlers(app: FastAPI): ) -_LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -_NOISY_LOGGERS = ( - "aio_pika", - "aiormq", - "httpcore", - "httpx", -) +def create_app_lifespan(logging_lifespan: Lifespan | None = None) -> LifespanManager: + app_lifespan = LifespanManager() + if logging_lifespan: + app_lifespan.add(logging_lifespan) + return app_lifespan -def create_base_app(settings: AppSettings | None = None) -> FastAPI: - if settings is None: - settings = AppSettings.create_from_envs() - assert settings # nosec +def create_base_app( + app_settings: AppSettings | None = None, +) -> FastAPI: + if app_settings is None: + app_settings = AppSettings.create_from_envs() - logging.basicConfig(level=settings.LOG_LEVEL.value) - logging.root.setLevel(settings.LOG_LEVEL.value) - config_all_loggers( - log_format_local_dev_enabled=settings.DIRECTOR_V2_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=settings.DIRECTOR_V2_LOG_FILTER_MAPPING, - tracing_settings=settings.DIRECTOR_V2_TRACING, + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.DIRECTOR_V2_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.DIRECTOR_V2_LOG_FILTER_MAPPING, + tracing_settings=app_settings.DIRECTOR_V2_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, ) - _logger.debug(settings.model_dump_json(indent=2)) - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + _LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), ) - for name in _NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) + assert app_settings # nosec - assert settings.SC_BOOT_MODE # nosec + assert app_settings.SC_BOOT_MODE # nosec app = FastAPI( - debug=settings.SC_BOOT_MODE.is_devel_mode(), + debug=app_settings.SC_BOOT_MODE.is_devel_mode(), title=PROJECT_NAME, description=SUMMARY, version=API_VERSION, openapi_url=f"/api/{API_VTAG}/openapi.json", - **get_common_oas_options(is_devel_mode=settings.SC_BOOT_MODE.is_devel_mode()), + **get_common_oas_options( + is_devel_mode=app_settings.SC_BOOT_MODE.is_devel_mode() + ), ) override_fastapi_openapi_method(app) - app.state.settings = settings + app.state.settings = app_settings app.include_router(api_router) + + app.add_event_handler("shutdown", logging_shutdown_event) + return app -def init_app(settings: AppSettings | None = None) -> FastAPI: +def create_app( # noqa: C901, PLR0912 + settings: AppSettings | None = None, +) -> FastAPI: app = create_base_app(settings) if settings is None: settings = app.state.settings + _logger.info( + "Application settings: %s", + json_dumps(settings, indent=2, sort_keys=True), + ) assert settings # nosec substitutions.setup(app) @@ -202,7 +221,9 @@ def init_app(settings: AppSettings | None = None) -> FastAPI: socketio.setup(app) notifier.setup(app) - if settings.DIRECTOR_V2_COMPUTATIONAL_BACKEND.COMPUTATIONAL_BACKEND_DASK_CLIENT_ENABLED: + if ( + settings.DIRECTOR_V2_COMPUTATIONAL_BACKEND.COMPUTATIONAL_BACKEND_DASK_CLIENT_ENABLED + ): dask_clients_pool.setup(app, settings.DIRECTOR_V2_COMPUTATIONAL_BACKEND) if computational_backend_enabled: diff --git a/services/director-v2/src/simcore_service_director_v2/main.py b/services/director-v2/src/simcore_service_director_v2/main.py index 245fb26285e..d0ecfb8b16a 100644 --- a/services/director-v2/src/simcore_service_director_v2/main.py +++ b/services/director-v2/src/simcore_service_director_v2/main.py @@ -1,7 +1,12 @@ -"""Main application to be deployed in for example uvicorn. -""" +"""Main application to be deployed in for example uvicorn.""" + +import logging + from fastapi import FastAPI -from simcore_service_director_v2.core.application import init_app +from simcore_service_director_v2.core.application import create_app + +_logger = logging.getLogger(__name__) + -# SINGLETON FastAPI app -the_app: FastAPI = init_app() +def app_factory() -> FastAPI: + return create_app() diff --git a/services/director-v2/tests/conftest.py b/services/director-v2/tests/conftest.py index c2b2ea89ac2..831b34e286c 100644 --- a/services/director-v2/tests/conftest.py +++ b/services/director-v2/tests/conftest.py @@ -32,7 +32,7 @@ from pytest_simcore.helpers.typing_env import EnvVarsDict from servicelib.rabbitmq import RabbitMQRPCClient from settings_library.rabbit import RabbitSettings -from simcore_service_director_v2.core.application import init_app +from simcore_service_director_v2.core.application import create_app from simcore_service_director_v2.core.settings import AppSettings from starlette.testclient import ASGI3App, TestClient @@ -47,6 +47,7 @@ "pytest_simcore.faker_products_data", "pytest_simcore.faker_projects_data", "pytest_simcore.faker_users_data", + "pytest_simcore.logging", "pytest_simcore.minio_service", "pytest_simcore.postgres_service", "pytest_simcore.pydantic_models", @@ -201,7 +202,7 @@ def mock_env( @pytest.fixture() async def initialized_app(mock_env: EnvVarsDict) -> AsyncIterable[FastAPI]: settings = AppSettings.create_from_envs() - app = init_app(settings) + app = create_app(settings) print("Application settings\n", settings.model_dump_json(indent=2)) async with LifespanManager(app): yield app @@ -212,7 +213,7 @@ async def client(mock_env: EnvVarsDict) -> AsyncIterator[TestClient]: # NOTE: this way we ensure the events are run in the application # since it starts the app on a test server settings = AppSettings.create_from_envs() - app = init_app(settings) + app = create_app(settings) # NOTE: we cannot use the initialized_app fixture here as the TestClient also creates it print("Application settings\n", settings.model_dump_json(indent=2)) with TestClient(app, raise_server_exceptions=True) as test_client: diff --git a/services/director-v2/tests/integration/02/test_dynamic_services_routes.py b/services/director-v2/tests/integration/02/test_dynamic_services_routes.py index 07c24d10fe4..a6800131007 100644 --- a/services/director-v2/tests/integration/02/test_dynamic_services_routes.py +++ b/services/director-v2/tests/integration/02/test_dynamic_services_routes.py @@ -36,7 +36,7 @@ ) from settings_library.rabbit import RabbitSettings from settings_library.redis import RedisSettings -from simcore_service_director_v2.core.application import init_app +from simcore_service_director_v2.core.application import create_app from simcore_service_director_v2.core.settings import AppSettings from tenacity.asyncio import AsyncRetrying from tenacity.retry import retry_if_exception_type @@ -197,7 +197,7 @@ async def director_v2_client( settings = AppSettings.create_from_envs() - app = init_app(settings) + app = create_app(settings) async with TestClient(app) as client: yield client diff --git a/services/director-v2/tests/unit/test_modules_dask_clients_pool.py b/services/director-v2/tests/unit/test_modules_dask_clients_pool.py index b0c982647dd..3bd19025251 100644 --- a/services/director-v2/tests/unit/test_modules_dask_clients_pool.py +++ b/services/director-v2/tests/unit/test_modules_dask_clients_pool.py @@ -22,7 +22,7 @@ ) from pytest_mock.plugin import MockerFixture from pytest_simcore.helpers.typing_env import EnvVarsDict -from simcore_service_director_v2.core.application import init_app +from simcore_service_director_v2.core.application import create_app from simcore_service_director_v2.core.errors import ( ConfigurationError, DaskClientAcquisisitonError, @@ -54,7 +54,7 @@ def test_dask_clients_pool_missing_raises_configuration_error( ): monkeypatch.setenv("COMPUTATIONAL_BACKEND_DASK_CLIENT_ENABLED", "0") settings = AppSettings.create_from_envs() - app = init_app(settings) + app = create_app(settings) with TestClient(app, raise_server_exceptions=True): # noqa: SIM117 with pytest.raises(ConfigurationError): @@ -70,7 +70,7 @@ def test_dask_clients_pool_properly_setup_and_deleted( ) mocked_dask_clients_pool.create.return_value = mocked_dask_clients_pool settings = AppSettings.create_from_envs() - app = init_app(settings) + app = create_app(settings) with TestClient(app, raise_server_exceptions=True): mocked_dask_clients_pool.create.assert_called_once() diff --git a/services/director/docker/boot.sh b/services/director/docker/boot.sh index 67298472d0e..38ad83b661f 100755 --- a/services/director/docker/boot.sh +++ b/services/director/docker/boot.sh @@ -51,7 +51,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/director/src/simcore_service_director && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DIRECTOR_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DIRECTOR_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -59,7 +61,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_director.main:the_app \ + exec uvicorn \ + --factory simcore_service_director.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/director/docker/entrypoint.sh b/services/director/docker/entrypoint.sh index 1071a664b92..651a1ea875f 100755 --- a/services/director/docker/entrypoint.sh +++ b/services/director/docker/entrypoint.sh @@ -26,6 +26,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/director/src/simcore_service_director/cli.py b/services/director/src/simcore_service_director/cli.py index f2e16f6b97e..1a797d76d0b 100644 --- a/services/director/src/simcore_service_director/cli.py +++ b/services/director/src/simcore_service_director/cli.py @@ -21,6 +21,6 @@ def run(): """Runs application""" typer.secho("Sorry, this entrypoint is intentionally disabled. Use instead") typer.secho( - "$ uvicorn simcore_service_director.main:the_app", + "$ uvicorn --factory simcore_service_director.main:app_factory", fg=typer.colors.BLUE, ) diff --git a/services/director/src/simcore_service_director/core/application.py b/services/director/src/simcore_service_director/core/application.py index e20c59554d1..eb28b0a9879 100644 --- a/services/director/src/simcore_service_director/core/application.py +++ b/services/director/src/simcore_service_director/core/application.py @@ -1,5 +1,4 @@ import logging -from typing import Final from fastapi import FastAPI from servicelib.async_utils import cancel_sequential_workers @@ -22,26 +21,10 @@ from ..registry_proxy import setup as setup_registry from .settings import ApplicationSettings -_LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -_NOISY_LOGGERS: Final[tuple[str, ...]] = ( - "httpcore", - "httpx", - "werkzeug", -) - _logger = logging.getLogger(__name__) def create_app(settings: ApplicationSettings) -> FastAPI: - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + _LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING - ) - for name in _NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) - - _logger.info("app settings: %s", settings.model_dump_json(indent=1)) - app = FastAPI( debug=settings.DIRECTOR_DEBUG, title=APP_NAME, diff --git a/services/director/src/simcore_service_director/core/settings.py b/services/director/src/simcore_service_director/core/settings.py index 5560de876fa..2cfea313918 100644 --- a/services/director/src/simcore_service_director/core/settings.py +++ b/services/director/src/simcore_service_director/core/settings.py @@ -1,10 +1,12 @@ import datetime import warnings +from functools import cached_property from typing import cast from fastapi import FastAPI from models_library.basic_types import LogLevel, PortInt, VersionTag from pydantic import AliasChoices, Field, NonNegativeInt, PositiveInt, field_validator +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.application import BaseApplicationSettings from settings_library.docker_registry import RegistrySettings @@ -27,7 +29,7 @@ class ApplicationSettings(BaseApplicationSettings, MixinLoggingSettings): ) DIRECTOR_REMOTE_DEBUG_PORT: PortInt = 3000 - DIRECTOR_LOGLEVEL: LogLevel = Field( + DIRECTOR_LOG_LEVEL: LogLevel = Field( ..., validation_alias=AliasChoices("DIRECTOR_LOGLEVEL", "LOG_LEVEL", "LOGLEVEL") ) DIRECTOR_LOG_FORMAT_LOCAL_DEV_ENABLED: bool = Field( @@ -143,10 +145,10 @@ def _validate_substitutions(cls, v): return v - @field_validator("DIRECTOR_LOGLEVEL", mode="before") - @classmethod - def _valid_log_level(cls, value: str) -> str: - return cls.validate_log_level(value) + @cached_property + def log_level(self) -> LogLevelInt: + """override""" + return cast(LogLevelInt, self.DIRECTOR_LOG_LEVEL) def get_application_settings(app: FastAPI) -> ApplicationSettings: diff --git a/services/director/src/simcore_service_director/main.py b/services/director/src/simcore_service_director/main.py index da0c480065f..5ad1c4b03d9 100644 --- a/services/director/src/simcore_service_director/main.py +++ b/services/director/src/simcore_service_director/main.py @@ -1,24 +1,37 @@ -"""Main application to be deployed by uvicorn (or equivalent) server - -""" +"""Main application to be deployed by uvicorn (or equivalent) server""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_director.core.application import create_app from simcore_service_director.core.settings import ApplicationSettings -_the_settings = ApplicationSettings.create_from_envs() +_logger = logging.getLogger(__name__) -# SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 -logging.basicConfig(level=_the_settings.DIRECTOR_LOGLEVEL) -logging.root.setLevel(_the_settings.DIRECTOR_LOGLEVEL) -config_all_loggers( - log_format_local_dev_enabled=_the_settings.DIRECTOR_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=_the_settings.DIRECTOR_LOG_FILTER_MAPPING, - tracing_settings=_the_settings.DIRECTOR_TRACING, +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "httpcore", + "httpx", + "werkzeug", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(_the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.DIRECTOR_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.DIRECTOR_LOG_FILTER_MAPPING, + tracing_settings=app_settings.DIRECTOR_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/director/tests/unit/conftest.py b/services/director/tests/unit/conftest.py index 71e373f5f16..68c20076f76 100644 --- a/services/director/tests/unit/conftest.py +++ b/services/director/tests/unit/conftest.py @@ -28,6 +28,7 @@ "pytest_simcore.environment_configs", "pytest_simcore.faker_projects_data", "pytest_simcore.faker_users_data", + "pytest_simcore.logging", "pytest_simcore.repository_paths", "pytest_simcore.simcore_service_library_fixtures", ] diff --git a/services/docker-api-proxy/tests/integration/conftest.py b/services/docker-api-proxy/tests/integration/conftest.py index 10878c70d57..09d5ec3cb9a 100644 --- a/services/docker-api-proxy/tests/integration/conftest.py +++ b/services/docker-api-proxy/tests/integration/conftest.py @@ -23,6 +23,7 @@ "pytest_simcore.docker_api_proxy", "pytest_simcore.docker_compose", "pytest_simcore.docker_swarm", + "pytest_simcore.logging", "pytest_simcore.repository_paths", "pytest_simcore.simcore_services", ] diff --git a/services/docker-compose.yml b/services/docker-compose.yml index cb92ec8b43c..b9c3c08abd2 100644 --- a/services/docker-compose.yml +++ b/services/docker-compose.yml @@ -1255,6 +1255,7 @@ services: STORAGE_MONITORING_ENABLED: 1 STORAGE_PROFILING: ${STORAGE_PROFILING} STORAGE_PORT: ${STORAGE_PORT} + STORAGE_TRACING: ${STORAGE_TRACING} TRACING_OPENTELEMETRY_COLLECTOR_PORT: ${TRACING_OPENTELEMETRY_COLLECTOR_PORT} TRACING_OPENTELEMETRY_COLLECTOR_ENDPOINT: ${TRACING_OPENTELEMETRY_COLLECTOR_ENDPOINT} networks: &storage_networks diff --git a/services/dynamic-scheduler/Makefile b/services/dynamic-scheduler/Makefile index f46337a7667..4d98e392aa3 100644 --- a/services/dynamic-scheduler/Makefile +++ b/services/dynamic-scheduler/Makefile @@ -15,4 +15,4 @@ openapi.json: .env-ignore ## produces openapi.json @set -o allexport; \ source $<; \ set +o allexport; \ - python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(the_app.openapi(), indent=2) )" > $@ + python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ diff --git a/services/dynamic-scheduler/docker/boot.sh b/services/dynamic-scheduler/docker/boot.sh index 89e85223aa6..382bfd14d01 100755 --- a/services/dynamic-scheduler/docker/boot.sh +++ b/services/dynamic-scheduler/docker/boot.sh @@ -52,7 +52,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/dynamic-scheduler/src/simcore_service_dynamic_scheduler && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DYNAMIC_SCHEDULER_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DYNAMIC_SCHEDULER_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -60,7 +62,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_dynamic_scheduler.main:the_app \ + exec uvicorn \ + --factory simcore_service_dynamic_scheduler.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/dynamic-scheduler/docker/entrypoint.sh b/services/dynamic-scheduler/docker/entrypoint.sh index b55d4bc7716..357d8b604d9 100755 --- a/services/dynamic-scheduler/docker/entrypoint.sh +++ b/services/dynamic-scheduler/docker/entrypoint.sh @@ -19,6 +19,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/application.py b/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/application.py index 9f59f29859e..a2617cec567 100644 --- a/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/application.py +++ b/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/application.py @@ -1,4 +1,5 @@ from fastapi import FastAPI +from servicelib.fastapi.lifespan_utils import Lifespan from servicelib.fastapi.monitoring import ( initialize_prometheus_instrumentation, ) @@ -13,7 +14,10 @@ from .settings import ApplicationSettings -def create_app(settings: ApplicationSettings | None = None) -> FastAPI: +def create_app( + settings: ApplicationSettings | None = None, + logging_lifespan: Lifespan | None = None, +) -> FastAPI: app_settings = settings or ApplicationSettings.create_from_envs() app = FastAPI( @@ -25,7 +29,9 @@ def create_app(settings: ApplicationSettings | None = None) -> FastAPI: "/doc" if app_settings.DYNAMIC_SCHEDULER_SWAGGER_API_DOC_ENABLED else None ), redoc_url=None, - lifespan=events.create_app_lifespan(settings=app_settings), + lifespan=events.create_app_lifespan( + settings=app_settings, logging_lifespan=logging_lifespan + ), ) override_fastapi_openapi_method(app) diff --git a/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/events.py b/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/events.py index 492834a99e3..1c293e78e71 100644 --- a/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/events.py +++ b/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/events.py @@ -6,6 +6,7 @@ create_remote_docker_client_input_state, remote_docker_client_lifespan, ) +from servicelib.fastapi.lifespan_utils import Lifespan from servicelib.fastapi.monitoring import ( create_prometheus_instrumentationmain_input_state, prometheus_instrumentation_lifespan, @@ -51,8 +52,12 @@ async def _settings_lifespan(app: FastAPI) -> AsyncIterator[State]: } -def create_app_lifespan(settings: ApplicationSettings) -> LifespanManager: +def create_app_lifespan( + settings: ApplicationSettings, logging_lifespan: Lifespan | None +) -> LifespanManager: app_lifespan = LifespanManager() + if logging_lifespan: + app_lifespan.add(logging_lifespan) app_lifespan.add(_settings_lifespan) if settings.DYNAMIC_SCHEDULER_TRACING: diff --git a/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/settings.py b/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/settings.py index f1ce9b13d33..8405a419536 100644 --- a/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/settings.py +++ b/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/core/settings.py @@ -1,8 +1,10 @@ import datetime -from typing import Annotated +from functools import cached_property +from typing import Annotated, cast from common_library.basic_types import DEFAULT_FACTORY from pydantic import AliasChoices, Field, SecretStr, TypeAdapter, field_validator +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.application import BaseApplicationSettings from settings_library.basic_types import LogLevel, VersionTag @@ -105,6 +107,10 @@ class _BaseApplicationSettings(BaseApplicationSettings, MixinLoggingSettings): ), ] = False + @cached_property + def log_level(self) -> LogLevelInt: + return cast(LogLevelInt, self.DYNAMIC_SCHEDULER_LOGLEVEL) + @field_validator("DYNAMIC_SCHEDULER_LOGLEVEL", mode="before") @classmethod def _validate_log_level(cls, value: str) -> str: diff --git a/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/main.py b/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/main.py index ab726883237..bf1f22e27e6 100644 --- a/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/main.py +++ b/services/dynamic-scheduler/src/simcore_service_dynamic_scheduler/main.py @@ -1,22 +1,39 @@ -"""Main application to be deployed by uvicorn (or equivalent) server - -""" +"""Main application to be deployed by uvicorn (or equivalent) server""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import ( + create_logging_lifespan, +) from simcore_service_dynamic_scheduler.core.application import create_app from simcore_service_dynamic_scheduler.core.settings import ApplicationSettings -_the_settings = ApplicationSettings.create_from_envs() -logging.basicConfig(level=_the_settings.DYNAMIC_SCHEDULER_LOGLEVEL.value) -logging.root.setLevel(_the_settings.DYNAMIC_SCHEDULER_LOGLEVEL.value) -config_all_loggers( - log_format_local_dev_enabled=_the_settings.DYNAMIC_SCHEDULER_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=_the_settings.DYNAMIC_SCHEDULER_LOG_FILTER_MAPPING, - tracing_settings=_the_settings.DYNAMIC_SCHEDULER_TRACING, +_logger = logging.getLogger(__name__) + +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aiobotocore", + "aio_pika", + "aiormq", + "botocore", + "werkzeug", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(_the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_lifespan = create_logging_lifespan( + log_format_local_dev_enabled=app_settings.DYNAMIC_SCHEDULER_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.DYNAMIC_SCHEDULER_LOG_FILTER_MAPPING, + tracing_settings=app_settings.DYNAMIC_SCHEDULER_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + return create_app(settings=app_settings, logging_lifespan=logging_lifespan) diff --git a/services/dynamic-scheduler/tests/conftest.py b/services/dynamic-scheduler/tests/conftest.py index 4a4aaf8c501..5543ad0665d 100644 --- a/services/dynamic-scheduler/tests/conftest.py +++ b/services/dynamic-scheduler/tests/conftest.py @@ -28,6 +28,7 @@ "pytest_simcore.environment_configs", "pytest_simcore.faker_projects_data", "pytest_simcore.faker_users_data", + "pytest_simcore.logging", "pytest_simcore.postgres_service", "pytest_simcore.rabbit_service", "pytest_simcore.redis_service", diff --git a/services/dynamic-sidecar/docker/boot.sh b/services/dynamic-sidecar/docker/boot.sh index cb209e00cc9..984ef554a3b 100755 --- a/services/dynamic-sidecar/docker/boot.sh +++ b/services/dynamic-sidecar/docker/boot.sh @@ -53,7 +53,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/dynamic-sidecar/src/simcore_service_dynamic_sidecar && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DYNAMIC_SIDECAR_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${DYNAMIC_SIDECAR_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -61,7 +63,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_dynamic_sidecar.main:the_app \ + exec uvicorn \ + --factory simcore_service_dynamic_sidecar.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/dynamic-sidecar/docker/entrypoint.sh b/services/dynamic-sidecar/docker/entrypoint.sh index 74eb8867b74..8f5a3799d78 100755 --- a/services/dynamic-sidecar/docker/entrypoint.sh +++ b/services/dynamic-sidecar/docker/entrypoint.sh @@ -27,6 +27,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/cli.py b/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/cli.py index def22092390..8b7b9086ef1 100644 --- a/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/cli.py +++ b/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/cli.py @@ -95,5 +95,5 @@ async def _async_outputs_push() -> None: # # NOTE: We intentionally did NOT create a command to run the application -# Use instead $ uvicorn simcore_service_dynamic_sidecar.main:the_app +# Use instead $ uvicorn --factory simcore_service_dynamic_sidecar.main:app_factory # diff --git a/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/core/application.py b/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/core/application.py index b141e7ca236..dad8f18dd59 100644 --- a/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/core/application.py +++ b/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/core/application.py @@ -2,9 +2,11 @@ from asyncio import Lock from typing import Any, ClassVar +from common_library.json_serialization import json_dumps from fastapi import FastAPI from servicelib.async_utils import cancel_sequential_workers from servicelib.fastapi import long_running_tasks +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from servicelib.fastapi.openapi import ( get_common_oas_options, override_fastapi_openapi_method, @@ -13,7 +15,6 @@ initialize_fastapi_app_tracing, setup_tracing, ) -from servicelib.logging_utils import config_all_loggers from simcore_sdk.node_ports_common.exceptions import NodeNotFound from .._meta import API_VERSION, API_VTAG, PROJECT_NAME, SUMMARY, __version__ @@ -40,7 +41,6 @@ from .settings import ApplicationSettings from .utils import volumes_fix_permissions -_LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR _NOISY_LOGGERS = ( "aio_pika", "aiormq", @@ -115,42 +115,36 @@ def compose_spec(self) -> str | None: return self._shared_store.compose_spec -def setup_logger(settings: ApplicationSettings): - # SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 - logging.basicConfig(level=settings.log_level) - logging.root.setLevel(settings.log_level) - config_all_loggers( - log_format_local_dev_enabled=settings.DY_SIDECAR_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=settings.DY_SIDECAR_LOG_FILTER_MAPPING, - tracing_settings=settings.DYNAMIC_SIDECAR_TRACING, - ) - - def create_base_app() -> FastAPI: - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + _LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING + # settings + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.DY_SIDECAR_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.DY_SIDECAR_LOG_FILTER_MAPPING, + tracing_settings=app_settings.DYNAMIC_SIDECAR_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, ) - for name in _NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) - # settings - settings = ApplicationSettings.create_from_envs() - setup_logger(settings) - logger.debug(settings.model_dump_json(indent=2)) + logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) # minimal - assert settings.SC_BOOT_MODE # nosec + assert app_settings.SC_BOOT_MODE # nosec app = FastAPI( - debug=settings.SC_BOOT_MODE.is_devel_mode(), + debug=app_settings.SC_BOOT_MODE.is_devel_mode(), title=PROJECT_NAME, description=SUMMARY, version=API_VERSION, openapi_url=f"/api/{API_VTAG}/openapi.json", - **get_common_oas_options(is_devel_mode=settings.SC_BOOT_MODE.is_devel_mode()), + **get_common_oas_options( + is_devel_mode=app_settings.SC_BOOT_MODE.is_devel_mode() + ), ) override_fastapi_openapi_method(app) - app.state.settings = settings + app.state.settings = app_settings long_running_tasks.server.setup(app) @@ -158,10 +152,11 @@ def create_base_app() -> FastAPI: setup_reserved_space(app) + app.add_event_handler("shutdown", logging_shutdown_event) return app -def create_app(): +def create_app() -> FastAPI: """ Creates the application from using the env vars as a context Also stores inside the state all instances of classes diff --git a/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/main.py b/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/main.py index 52c91f22837..b710b504785 100644 --- a/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/main.py +++ b/services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/main.py @@ -1,8 +1,12 @@ -"""Main application to be deployed in for example uvicorn. -""" +"""Main application to be deployed in for example uvicorn.""" from fastapi import FastAPI from simcore_service_dynamic_sidecar.core.application import create_app -# SINGLETON FastAPI app -the_app: FastAPI = create_app() + +def app_factory() -> FastAPI: + """Factory function to create the FastAPI app instance. + + This is used by uvicorn or other ASGI servers to run the application. + """ + return create_app() diff --git a/services/dynamic-sidecar/tests/conftest.py b/services/dynamic-sidecar/tests/conftest.py index bb6820d2df7..c85d29105a9 100644 --- a/services/dynamic-sidecar/tests/conftest.py +++ b/services/dynamic-sidecar/tests/conftest.py @@ -40,6 +40,7 @@ "pytest_simcore.docker_registry", "pytest_simcore.docker_swarm", "pytest_simcore.faker_users_data", + "pytest_simcore.logging", "pytest_simcore.minio_service", "pytest_simcore.postgres_service", "pytest_simcore.pytest_global_environs", diff --git a/services/dynamic-sidecar/tests/integration/conftest.py b/services/dynamic-sidecar/tests/integration/conftest.py index 8c9f5426bd3..98ba076f260 100644 --- a/services/dynamic-sidecar/tests/integration/conftest.py +++ b/services/dynamic-sidecar/tests/integration/conftest.py @@ -8,6 +8,7 @@ pytest_plugins = [ "pytest_simcore.asyncio_event_loops", + "pytest_simcore.logging", "pytest_simcore.postgres_service", "pytest_simcore.simcore_storage_service", "pytest_simcore.rabbit_service", diff --git a/services/dynamic-sidecar/tests/unit/test_cli.py b/services/dynamic-sidecar/tests/unit/test_cli.py index 9caf2316347..a06fc698efc 100644 --- a/services/dynamic-sidecar/tests/unit/test_cli.py +++ b/services/dynamic-sidecar/tests/unit/test_cli.py @@ -50,12 +50,12 @@ def test_list_state_dirs(cli_runner: CliRunner, mock_data_manager: None): def test_outputs_push_interface(cli_runner: CliRunner, mock_data_manager: None): result = cli_runner.invoke(main, ["state-save"]) assert result.exit_code == os.EX_OK, _format_cli_error(result) - assert result.stdout == "state save finished successfully\n" + assert "state save finished successfully\n" in result.stdout print(result) def test_state_save_interface(cli_runner: CliRunner, mock_nodeports: None): result = cli_runner.invoke(main, ["outputs-push"]) assert result.exit_code == os.EX_OK, _format_cli_error(result) - assert result.stdout == "output ports push finished successfully\n" + assert "output ports push finished successfully\n" in result.stdout print(result) diff --git a/services/efs-guardian/docker/boot.sh b/services/efs-guardian/docker/boot.sh index 317ee312459..904aace5c91 100755 --- a/services/efs-guardian/docker/boot.sh +++ b/services/efs-guardian/docker/boot.sh @@ -52,7 +52,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/efs-guardian/src/simcore_service_efs_guardian && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${EFS_GUARDIAN_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${EFS_GUARDIAN_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -60,7 +62,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_efs_guardian.main:the_app \ + exec uvicorn \ + --factory simcore_service_efs_guardian.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/efs-guardian/docker/entrypoint.sh b/services/efs-guardian/docker/entrypoint.sh index a1b9ea0137d..b3083ac06cd 100755 --- a/services/efs-guardian/docker/entrypoint.sh +++ b/services/efs-guardian/docker/entrypoint.sh @@ -26,6 +26,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/efs-guardian/src/simcore_service_efs_guardian/cli.py b/services/efs-guardian/src/simcore_service_efs_guardian/cli.py index 77d18015ec0..3b64a7663ef 100644 --- a/services/efs-guardian/src/simcore_service_efs_guardian/cli.py +++ b/services/efs-guardian/src/simcore_service_efs_guardian/cli.py @@ -19,6 +19,6 @@ def run(): """Runs application""" typer.secho("Sorry, this entrypoint is intentionally disabled. Use instead") typer.secho( - "$ uvicorn simcore_service_efs_guardian.main:the_app", + "$ uvicorn --factory simcore_service_efs_guardian.main:app_factory", fg=typer.colors.BLUE, ) diff --git a/services/efs-guardian/src/simcore_service_efs_guardian/core/application.py b/services/efs-guardian/src/simcore_service_efs_guardian/core/application.py index 7c68ba3f0e4..d44dea34414 100644 --- a/services/efs-guardian/src/simcore_service_efs_guardian/core/application.py +++ b/services/efs-guardian/src/simcore_service_efs_guardian/core/application.py @@ -31,8 +31,6 @@ def create_app(settings: ApplicationSettings | None = None) -> FastAPI: app_settings = settings or ApplicationSettings.create_from_envs() - logger.info("app settings: %s", app_settings.model_dump_json(indent=1)) - app = FastAPI( debug=app_settings.EFS_GUARDIAN_DEBUG, title=APP_NAME, diff --git a/services/efs-guardian/src/simcore_service_efs_guardian/core/settings.py b/services/efs-guardian/src/simcore_service_efs_guardian/core/settings.py index ab5377a82d3..cda71422f9e 100644 --- a/services/efs-guardian/src/simcore_service_efs_guardian/core/settings.py +++ b/services/efs-guardian/src/simcore_service_efs_guardian/core/settings.py @@ -6,6 +6,7 @@ from fastapi import FastAPI from models_library.basic_types import LogLevel, VersionTag from pydantic import AliasChoices, ByteSize, Field, TypeAdapter, field_validator +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.application import BaseApplicationSettings from settings_library.efs import AwsEfsSettings @@ -116,8 +117,8 @@ class ApplicationSettings(BaseApplicationSettings, MixinLoggingSettings): ] @cached_property - def LOG_LEVEL(self) -> LogLevel: # noqa: N802 - return self.EFS_GUARDIAN_LOGLEVEL + def log_level(self) -> LogLevelInt: + return cast(LogLevelInt, self.EFS_GUARDIAN_LOGLEVEL) @field_validator("EFS_GUARDIAN_LOGLEVEL", mode="before") @classmethod diff --git a/services/efs-guardian/src/simcore_service_efs_guardian/main.py b/services/efs-guardian/src/simcore_service_efs_guardian/main.py index 711d32d83ee..230016b548c 100644 --- a/services/efs-guardian/src/simcore_service_efs_guardian/main.py +++ b/services/efs-guardian/src/simcore_service_efs_guardian/main.py @@ -1,22 +1,39 @@ -"""Main application to be deployed by uvicorn (or equivalent) server - -""" +"""Main application to be deployed by uvicorn (or equivalent) server""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_efs_guardian.core.application import create_app from simcore_service_efs_guardian.core.settings import ApplicationSettings -the_settings = ApplicationSettings.create_from_envs() -logging.basicConfig(level=the_settings.log_level) -logging.root.setLevel(the_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=the_settings.EFS_GUARDIAN_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=the_settings.EFS_GUARDIAN_LOG_FILTER_MAPPING, - tracing_settings=the_settings.EFS_GUARDIAN_TRACING, +_logger = logging.getLogger(__name__) + +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aiobotocore", + "aio_pika", + "aiormq", + "botocore", + "werkzeug", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.EFS_GUARDIAN_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.EFS_GUARDIAN_LOG_FILTER_MAPPING, + tracing_settings=app_settings.EFS_GUARDIAN_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/efs-guardian/tests/conftest.py b/services/efs-guardian/tests/conftest.py index 6cdf23bdc23..8a3e48d2325 100644 --- a/services/efs-guardian/tests/conftest.py +++ b/services/efs-guardian/tests/conftest.py @@ -24,6 +24,7 @@ "pytest_simcore.faker_users_data", "pytest_simcore.faker_products_data", "pytest_simcore.faker_projects_data", + "pytest_simcore.logging", "pytest_simcore.pydantic_models", "pytest_simcore.pytest_global_environs", "pytest_simcore.rabbit_service", diff --git a/services/efs-guardian/tests/unit/test_main.py b/services/efs-guardian/tests/unit/test_main.py index bbdb41096c8..26b0fa6af39 100644 --- a/services/efs-guardian/tests/unit/test_main.py +++ b/services/efs-guardian/tests/unit/test_main.py @@ -7,6 +7,6 @@ def test_main_app(app_environment: EnvVarsDict): - from simcore_service_efs_guardian.main import the_app, the_settings + from simcore_service_efs_guardian.main import app_factory - assert the_app.state.settings == the_settings + app_factory() diff --git a/services/invitations/Makefile b/services/invitations/Makefile index f7a9b88fe72..7550b36a91a 100644 --- a/services/invitations/Makefile +++ b/services/invitations/Makefile @@ -17,7 +17,7 @@ openapi.json: .env-ignore ## produces openapi.json @set -o allexport; \ source $<; \ set +o allexport; \ - python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(the_app.openapi(), indent=2) )" > $@ + python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ # diff --git a/services/invitations/docker/boot.sh b/services/invitations/docker/boot.sh index 99afa6e1a75..fb1e2687586 100755 --- a/services/invitations/docker/boot.sh +++ b/services/invitations/docker/boot.sh @@ -52,7 +52,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/invitations/src/simcore_service_invitations && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${INVITATIONS_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${INVITATIONS_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -60,7 +62,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_invitations.main:the_app \ + exec uvicorn \ + --factory simcore_service_invitations.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/invitations/docker/entrypoint.sh b/services/invitations/docker/entrypoint.sh index b55d4bc7716..357d8b604d9 100755 --- a/services/invitations/docker/entrypoint.sh +++ b/services/invitations/docker/entrypoint.sh @@ -19,6 +19,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/invitations/requirements/_test.in b/services/invitations/requirements/_test.in index 040fb5659da..5fdd0bcf70b 100644 --- a/services/invitations/requirements/_test.in +++ b/services/invitations/requirements/_test.in @@ -18,6 +18,7 @@ hypothesis pytest pytest-asyncio pytest-cov +pytest-mock pytest-runner pytest-sugar python-dotenv diff --git a/services/invitations/requirements/_test.txt b/services/invitations/requirements/_test.txt index e9436a09449..518d2664fdb 100644 --- a/services/invitations/requirements/_test.txt +++ b/services/invitations/requirements/_test.txt @@ -58,11 +58,14 @@ pytest==8.4.1 # -r requirements/_test.in # pytest-asyncio # pytest-cov + # pytest-mock # pytest-sugar pytest-asyncio==1.0.0 # via -r requirements/_test.in pytest-cov==6.2.1 # via -r requirements/_test.in +pytest-mock==3.14.1 + # via -r requirements/_test.in pytest-runner==6.0.1 # via -r requirements/_test.in pytest-sugar==1.0.0 diff --git a/services/invitations/src/simcore_service_invitations/core/settings.py b/services/invitations/src/simcore_service_invitations/core/settings.py index 2df10527929..44ab579cbc7 100644 --- a/services/invitations/src/simcore_service_invitations/core/settings.py +++ b/services/invitations/src/simcore_service_invitations/core/settings.py @@ -1,9 +1,10 @@ from functools import cached_property -from typing import Annotated +from typing import Annotated, cast from common_library.basic_types import DEFAULT_FACTORY from models_library.products import ProductName from pydantic import AliasChoices, Field, HttpUrl, SecretStr, field_validator +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.application import BaseApplicationSettings from settings_library.basic_types import LogLevel, VersionTag @@ -55,8 +56,8 @@ class _BaseApplicationSettings(BaseApplicationSettings, MixinLoggingSettings): ] = DEFAULT_FACTORY @cached_property - def LOG_LEVEL(self): - return self.INVITATIONS_LOGLEVEL + def log_level(self) -> LogLevelInt: + return cast(LogLevelInt, self.INVITATIONS_LOGLEVEL) @field_validator("INVITATIONS_LOGLEVEL", mode="before") @classmethod diff --git a/services/invitations/src/simcore_service_invitations/main.py b/services/invitations/src/simcore_service_invitations/main.py index 4a21e994b31..d59e54918a0 100644 --- a/services/invitations/src/simcore_service_invitations/main.py +++ b/services/invitations/src/simcore_service_invitations/main.py @@ -1,24 +1,36 @@ -"""Main application to be deployed by uvicorn (or equivalent) server - -""" +"""Main application to be deployed by uvicorn (or equivalent) server""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_invitations.core.application import create_app from simcore_service_invitations.core.settings import ApplicationSettings -the_settings = ApplicationSettings.create_from_envs() +_logger = logging.getLogger(__name__) -# SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 -logging.basicConfig(level=the_settings.log_level) # NOSONAR -logging.root.setLevel(the_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=the_settings.INVITATIONS_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=the_settings.INVITATIONS_LOG_FILTER_MAPPING, - tracing_settings=the_settings.INVITATIONS_TRACING, +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aio_pika", + "aiormq", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.INVITATIONS_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.INVITATIONS_LOG_FILTER_MAPPING, + tracing_settings=app_settings.INVITATIONS_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/invitations/src/simcore_service_invitations/web_server.py b/services/invitations/src/simcore_service_invitations/web_server.py index 92015153841..55c291e7825 100644 --- a/services/invitations/src/simcore_service_invitations/web_server.py +++ b/services/invitations/src/simcore_service_invitations/web_server.py @@ -7,9 +7,10 @@ def start( log_level: Literal["info", "debug", "warning", "error"], *, reload: bool = False ): uvicorn.run( - "simcore_service_invitations.web_main:the_app", + "simcore_service_invitations.web_main:app_factory", host="0.0.0.0", # nosec port=8000, log_level=log_level, reload=reload, + factory=True, ) diff --git a/services/invitations/tests/unit/conftest.py b/services/invitations/tests/unit/conftest.py index e7a12b0426c..414062b9f94 100644 --- a/services/invitations/tests/unit/conftest.py +++ b/services/invitations/tests/unit/conftest.py @@ -17,6 +17,7 @@ pytest_plugins = [ "pytest_simcore.asyncio_event_loops", + "pytest_simcore.logging", "pytest_simcore.cli_runner", "pytest_simcore.repository_paths", ] diff --git a/services/invitations/tests/unit/test_core_settings.py b/services/invitations/tests/unit/test_core_settings.py index cb89e8183ac..150f904ab09 100644 --- a/services/invitations/tests/unit/test_core_settings.py +++ b/services/invitations/tests/unit/test_core_settings.py @@ -43,4 +43,4 @@ def test_valid_application_settings(app_environment: EnvVarsDict): assert settings == ApplicationSettings.create_from_envs() - assert settings.LOG_LEVEL == "INFO" + assert settings.INVITATIONS_LOGLEVEL == "INFO" diff --git a/services/migration/docker/entrypoint.sh b/services/migration/docker/entrypoint.sh index 3b639e936ed..05671ccd2c7 100755 --- a/services/migration/docker/entrypoint.sh +++ b/services/migration/docker/entrypoint.sh @@ -12,6 +12,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" echo "$INFO ${SC_USER_NAME} rights : $(id "$SC_USER_NAME")" echo "$INFO local dir : $(ls -al)" diff --git a/services/migration/tests/conftest.py b/services/migration/tests/conftest.py index 2ad21378f67..eb8c5b1c743 100644 --- a/services/migration/tests/conftest.py +++ b/services/migration/tests/conftest.py @@ -2,5 +2,6 @@ "pytest_simcore.docker_compose", "pytest_simcore.docker_registry", "pytest_simcore.docker_swarm", + "pytest_simcore.logging", "pytest_simcore.repository_paths", ] diff --git a/services/notifications/Makefile b/services/notifications/Makefile index bc14e6354c1..13474cf2701 100644 --- a/services/notifications/Makefile +++ b/services/notifications/Makefile @@ -15,4 +15,4 @@ openapi.json: .env-ignore ## produces openapi.json @set -o allexport; \ source $<; \ set +o allexport; \ - python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(the_app.openapi(), indent=2) )" > $@ + python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ diff --git a/services/notifications/docker/boot.sh b/services/notifications/docker/boot.sh index 8aae19c2f8e..dbae76238cd 100755 --- a/services/notifications/docker/boot.sh +++ b/services/notifications/docker/boot.sh @@ -52,7 +52,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/notifications/src/simcore_service_notifications && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${NOTIFICATIONS_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${NOTIFICATIONS_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --port 8000 \ --reload \ @@ -61,7 +63,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_notifications.main:the_app \ + exec uvicorn \ + --factory simcore_service_notifications.main:app_factory \ --host 0.0.0.0 \ --port 8000 \ --log-level "${SERVER_LOG_LEVEL}" \ diff --git a/services/notifications/docker/entrypoint.sh b/services/notifications/docker/entrypoint.sh index b55d4bc7716..357d8b604d9 100755 --- a/services/notifications/docker/entrypoint.sh +++ b/services/notifications/docker/entrypoint.sh @@ -19,6 +19,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/notifications/src/simcore_service_notifications/core/application.py b/services/notifications/src/simcore_service_notifications/core/application.py index 5f3245d9d52..63517b52d5b 100644 --- a/services/notifications/src/simcore_service_notifications/core/application.py +++ b/services/notifications/src/simcore_service_notifications/core/application.py @@ -1,6 +1,7 @@ import logging from fastapi import FastAPI +from servicelib.fastapi.lifespan_utils import Lifespan from servicelib.fastapi.monitoring import ( initialize_prometheus_instrumentation, ) @@ -12,7 +13,6 @@ initialize_fastapi_app_tracing, setup_tracing, ) -from servicelib.logging_utils import config_all_loggers from .._meta import API_VTAG, APP_NAME, SUMMARY, VERSION from ..api.rest.routing import initialize_rest_api @@ -22,22 +22,11 @@ _logger = logging.getLogger(__name__) -def _initialise_logger(settings: ApplicationSettings): - # SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 - logging.basicConfig(level=settings.LOG_LEVEL.value) # NOSONAR - logging.root.setLevel(settings.LOG_LEVEL.value) - config_all_loggers( - log_format_local_dev_enabled=settings.NOTIFICATIONS_VOLUMES_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=settings.NOTIFICATIONS_VOLUMES_LOG_FILTER_MAPPING, - tracing_settings=settings.NOTIFICATIONS_TRACING, - ) - - -def create_app() -> FastAPI: - settings = ApplicationSettings.create_from_envs() - _logger.debug(settings.model_dump_json(indent=2)) - - _initialise_logger(settings) +def create_app( + settings: ApplicationSettings | None = None, + logging_lifespan: Lifespan | None = None, +) -> FastAPI: + settings = settings or ApplicationSettings.create_from_envs() assert settings.SC_BOOT_MODE # nosec app = FastAPI( @@ -46,7 +35,7 @@ def create_app() -> FastAPI: description=SUMMARY, version=f"{VERSION}", openapi_url=f"/api/{API_VTAG}/openapi.json", - lifespan=events.create_app_lifespan(), + lifespan=events.create_app_lifespan(logging_lifespan=logging_lifespan), **get_common_oas_options(is_devel_mode=settings.SC_BOOT_MODE.is_devel_mode()), ) override_fastapi_openapi_method(app) diff --git a/services/notifications/src/simcore_service_notifications/core/events.py b/services/notifications/src/simcore_service_notifications/core/events.py index 879582575c0..2660e2f426c 100644 --- a/services/notifications/src/simcore_service_notifications/core/events.py +++ b/services/notifications/src/simcore_service_notifications/core/events.py @@ -2,6 +2,7 @@ from fastapi import FastAPI from fastapi_lifespan_manager import LifespanManager, State +from servicelib.fastapi.lifespan_utils import Lifespan from servicelib.fastapi.monitoring import ( create_prometheus_instrumentationmain_input_state, prometheus_instrumentation_lifespan, @@ -35,9 +36,13 @@ async def _settings_lifespan(app: FastAPI) -> AsyncIterator[State]: } -def create_app_lifespan(): +def create_app_lifespan( + logging_lifespan: Lifespan | None = None, +) -> LifespanManager[FastAPI]: # WARNING: order matters app_lifespan = LifespanManager() + if logging_lifespan: + app_lifespan.add(logging_lifespan) app_lifespan.add(_settings_lifespan) # - postgres diff --git a/services/notifications/src/simcore_service_notifications/main.py b/services/notifications/src/simcore_service_notifications/main.py index 8b2e0ed3196..cda95f9dd9f 100644 --- a/services/notifications/src/simcore_service_notifications/main.py +++ b/services/notifications/src/simcore_service_notifications/main.py @@ -1,3 +1,34 @@ +import logging +from typing import Final + +from common_library.json_serialization import json_dumps +from fastapi import FastAPI +from servicelib.fastapi.logging_lifespan import create_logging_lifespan from simcore_service_notifications.core.application import create_app +from simcore_service_notifications.core.settings import ( + ApplicationSettings, +) + +_logger = logging.getLogger(__name__) + +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aio_pika", + "aiormq", +) + + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_lifespan = create_logging_lifespan( + log_format_local_dev_enabled=app_settings.NOTIFICATIONS_VOLUMES_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.NOTIFICATIONS_VOLUMES_LOG_FILTER_MAPPING, + tracing_settings=app_settings.NOTIFICATIONS_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) -the_app = create_app() + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + return create_app(settings=app_settings, logging_lifespan=logging_lifespan) diff --git a/services/notifications/tests/conftest.py b/services/notifications/tests/conftest.py index 422f58a9122..6091f50b9de 100644 --- a/services/notifications/tests/conftest.py +++ b/services/notifications/tests/conftest.py @@ -13,6 +13,7 @@ "pytest_simcore.docker_compose", "pytest_simcore.docker_swarm", "pytest_simcore.environment_configs", + "pytest_simcore.logging", "pytest_simcore.postgres_service", "pytest_simcore.rabbit_service", "pytest_simcore.repository_paths", diff --git a/services/payments/Makefile b/services/payments/Makefile index cf361c3c10e..a5d4d241e1f 100644 --- a/services/payments/Makefile +++ b/services/payments/Makefile @@ -15,7 +15,7 @@ openapi.json: .env-ignore ## produces openapi.json @set -o allexport; \ source $<; \ set +o allexport; \ - python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(the_app.openapi(), indent=2) )" > $@ + python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ # NOTE: Create using `ln -s path/to/osparc-config/repo.config .env-secret` diff --git a/services/payments/docker/boot.sh b/services/payments/docker/boot.sh index 740e8ff1e17..e2d5b5f7d21 100755 --- a/services/payments/docker/boot.sh +++ b/services/payments/docker/boot.sh @@ -52,7 +52,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/payments/src/simcore_service_payments && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${PAYMENTS_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${PAYMENTS_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -60,7 +62,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_payments.main:the_app \ + exec uvicorn \ + --factory simcore_service_payments.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/payments/docker/entrypoint.sh b/services/payments/docker/entrypoint.sh index b55d4bc7716..357d8b604d9 100755 --- a/services/payments/docker/entrypoint.sh +++ b/services/payments/docker/entrypoint.sh @@ -19,6 +19,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/payments/src/simcore_service_payments/core/settings.py b/services/payments/src/simcore_service_payments/core/settings.py index 5d9c69d861b..67932ac466d 100644 --- a/services/payments/src/simcore_service_payments/core/settings.py +++ b/services/payments/src/simcore_service_payments/core/settings.py @@ -1,6 +1,6 @@ from decimal import Decimal from functools import cached_property -from typing import Annotated +from typing import Annotated, cast from common_library.basic_types import DEFAULT_FACTORY from models_library.basic_types import NonNegativeDecimal @@ -14,6 +14,7 @@ TypeAdapter, field_validator, ) +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.application import BaseApplicationSettings from settings_library.basic_types import LogLevel, VersionTag @@ -66,8 +67,8 @@ class _BaseApplicationSettings(BaseApplicationSettings, MixinLoggingSettings): ] = DEFAULT_FACTORY @cached_property - def LOG_LEVEL(self): # noqa: N802 - return self.PAYMENTS_LOGLEVEL + def log_level(self) -> LogLevelInt: + return cast(LogLevelInt, self.PAYMENTS_LOGLEVEL) @field_validator("PAYMENTS_LOGLEVEL", mode="before") @classmethod diff --git a/services/payments/src/simcore_service_payments/main.py b/services/payments/src/simcore_service_payments/main.py index 53e19bd22a1..604d4adaa1b 100644 --- a/services/payments/src/simcore_service_payments/main.py +++ b/services/payments/src/simcore_service_payments/main.py @@ -1,24 +1,39 @@ -"""Main application to be deployed by uvicorn (or equivalent) server - -""" +"""Main application to be deployed by uvicorn (or equivalent) server""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_payments.core.application import create_app from simcore_service_payments.core.settings import ApplicationSettings -_the_settings = ApplicationSettings.create_from_envs() +_logger = logging.getLogger(__name__) -# SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 -logging.basicConfig(level=_the_settings.log_level) # NOSONAR -logging.root.setLevel(_the_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=_the_settings.PAYMENTS_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=_the_settings.PAYMENTS_LOG_FILTER_MAPPING, - tracing_settings=_the_settings.PAYMENTS_TRACING, +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aiobotocore", + "aio_pika", + "aiormq", + "botocore", + "werkzeug", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(_the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.PAYMENTS_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.PAYMENTS_LOG_FILTER_MAPPING, + tracing_settings=app_settings.PAYMENTS_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/payments/tests/conftest.py b/services/payments/tests/conftest.py index 39608fe4e70..45b36d3262a 100644 --- a/services/payments/tests/conftest.py +++ b/services/payments/tests/conftest.py @@ -24,6 +24,7 @@ "pytest_simcore.faker_products_data", "pytest_simcore.faker_users_data", "pytest_simcore.httpbin_service", + "pytest_simcore.logging", "pytest_simcore.postgres_service", "pytest_simcore.socketio", "pytest_simcore.rabbit_service", diff --git a/services/payments/tests/unit/test_cli.py b/services/payments/tests/unit/test_cli.py index 1fb1db4eded..4701f992ede 100644 --- a/services/payments/tests/unit/test_cli.py +++ b/services/payments/tests/unit/test_cli.py @@ -55,6 +55,6 @@ def test_list_settings(cli_runner: CliRunner, app_environment: EnvVarsDict): def test_main(app_environment: EnvVarsDict): - from simcore_service_payments.main import the_app + from simcore_service_payments.main import app_factory - assert the_app + app_factory() diff --git a/services/payments/tests/unit/test_core_settings.py b/services/payments/tests/unit/test_core_settings.py index 343a4507871..3c7810c73f7 100644 --- a/services/payments/tests/unit/test_core_settings.py +++ b/services/payments/tests/unit/test_core_settings.py @@ -13,4 +13,4 @@ def test_valid_application_settings(app_environment: EnvVarsDict): assert settings == ApplicationSettings.create_from_envs() - assert app_environment["PAYMENTS_LOGLEVEL"] == settings.LOG_LEVEL + assert app_environment["PAYMENTS_LOGLEVEL"] == settings.PAYMENTS_LOGLEVEL diff --git a/services/resource-usage-tracker/Makefile b/services/resource-usage-tracker/Makefile index d6d8745bc13..cb0bbe708f5 100644 --- a/services/resource-usage-tracker/Makefile +++ b/services/resource-usage-tracker/Makefile @@ -10,4 +10,4 @@ include ../../scripts/common-service.Makefile openapi-specs: openapi.json openapi.json: ## produces openapi.json # generating openapi specs file (need to have the environment set for this) - @python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(the_app.openapi(), indent=2) )" > $@ + @python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ diff --git a/services/resource-usage-tracker/docker/boot.sh b/services/resource-usage-tracker/docker/boot.sh index b1863b10308..372e0f0d730 100755 --- a/services/resource-usage-tracker/docker/boot.sh +++ b/services/resource-usage-tracker/docker/boot.sh @@ -52,7 +52,9 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then exec sh -c " cd services/resource-usage-tracker/src/simcore_service_resource_usage_tracker && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${RESOURCE_USAGE_TRACKER_REMOTE_DEBUGGING_PORT} -m uvicorn main:the_app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${RESOURCE_USAGE_TRACKER_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --reload \ $reload_dir_packages \ @@ -60,7 +62,8 @@ if [ "${SC_BOOT_MODE}" = "debug" ]; then --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_resource_usage_tracker.main:the_app \ + exec uvicorn \ + --factory simcore_service_resource_usage_tracker.main:app_factory \ --host 0.0.0.0 \ --log-level "${SERVER_LOG_LEVEL}" fi diff --git a/services/resource-usage-tracker/docker/entrypoint.sh b/services/resource-usage-tracker/docker/entrypoint.sh index c1697b74b85..a319c6824d7 100755 --- a/services/resource-usage-tracker/docker/entrypoint.sh +++ b/services/resource-usage-tracker/docker/entrypoint.sh @@ -19,6 +19,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" # # DEVELOPMENT MODE diff --git a/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/core/application.py b/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/core/application.py index 2aacbfb4990..fb3bdf2d1e8 100644 --- a/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/core/application.py +++ b/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/core/application.py @@ -35,8 +35,6 @@ def create_app(settings: ApplicationSettings) -> FastAPI: - _logger.info("app settings: %s", settings.model_dump_json(indent=1)) - app = FastAPI( debug=settings.RESOURCE_USAGE_TRACKER_DEBUG, title=f"{PROJECT_NAME} web API", diff --git a/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/core/settings.py b/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/core/settings.py index 3a534b692dc..3590c3847b9 100644 --- a/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/core/settings.py +++ b/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/core/settings.py @@ -1,8 +1,10 @@ import datetime from functools import cached_property +from typing import cast from models_library.basic_types import BootModeEnum from pydantic import AliasChoices, Field, PositiveInt, field_validator +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.base import BaseCustomSettings from settings_library.basic_types import BuildTargetEnum, LogLevel, VersionTag @@ -76,8 +78,8 @@ class _BaseApplicationSettings(BaseCustomSettings, MixinLoggingSettings): ) @cached_property - def LOG_LEVEL(self) -> LogLevel: # noqa: N802 - return self.RESOURCE_USAGE_TRACKER_LOGLEVEL + def log_level(self) -> LogLevelInt: + return cast(LogLevelInt, self.RESOURCE_USAGE_TRACKER_LOGLEVEL) @field_validator("RESOURCE_USAGE_TRACKER_LOGLEVEL", mode="before") @classmethod diff --git a/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/main.py b/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/main.py index 079ba5cdf79..42d3184f155 100644 --- a/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/main.py +++ b/services/resource-usage-tracker/src/simcore_service_resource_usage_tracker/main.py @@ -1,24 +1,39 @@ -"""Main application to be deployed by uvicorn (or equivalent) server - -""" +"""Main application to be deployed by uvicorn (or equivalent) server""" import logging +from typing import Final +from common_library.json_serialization import json_dumps from fastapi import FastAPI -from servicelib.logging_utils import config_all_loggers +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_resource_usage_tracker.core.application import create_app from simcore_service_resource_usage_tracker.core.settings import ApplicationSettings -the_settings = ApplicationSettings.create_from_envs() +_logger = logging.getLogger(__name__) -# SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 -logging.basicConfig(level=the_settings.log_level) # NOSONAR -logging.root.setLevel(the_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=the_settings.RESOURCE_USAGE_TRACKER_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=the_settings.RESOURCE_USAGE_TRACKER_LOG_FILTER_MAPPING, - tracing_settings=the_settings.RESOURCE_USAGE_TRACKER_TRACING, +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aiobotocore", + "aio_pika", + "aiormq", + "botocore", + "werkzeug", ) -# SINGLETON FastAPI app -the_app: FastAPI = create_app(the_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.RESOURCE_USAGE_TRACKER_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.RESOURCE_USAGE_TRACKER_LOG_FILTER_MAPPING, + tracing_settings=app_settings.RESOURCE_USAGE_TRACKER_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/resource-usage-tracker/tests/unit/conftest.py b/services/resource-usage-tracker/tests/unit/conftest.py index a2e1b67a169..7269ffae009 100644 --- a/services/resource-usage-tracker/tests/unit/conftest.py +++ b/services/resource-usage-tracker/tests/unit/conftest.py @@ -35,6 +35,7 @@ "pytest_simcore.environment_configs", "pytest_simcore.faker_projects_data", "pytest_simcore.faker_products_data", + "pytest_simcore.logging", "pytest_simcore.postgres_service", "pytest_simcore.pydantic_models", "pytest_simcore.pytest_global_environs", diff --git a/services/resource-usage-tracker/tests/unit/test_core_settings.py b/services/resource-usage-tracker/tests/unit/test_core_settings.py index f99239cc06b..4569bcae7fa 100644 --- a/services/resource-usage-tracker/tests/unit/test_core_settings.py +++ b/services/resource-usage-tracker/tests/unit/test_core_settings.py @@ -24,7 +24,7 @@ def test_valid_cli_application_settings(app_environment: EnvVarsDict): assert settings.RESOURCE_USAGE_TRACKER_POSTGRES assert settings.RESOURCE_USAGE_TRACKER_REDIS assert settings.RESOURCE_USAGE_TRACKER_RABBITMQ - assert settings.LOG_LEVEL + assert settings.RESOURCE_USAGE_TRACKER_LOGLEVEL def test_valid_web_application_settings(app_environment: EnvVarsDict): @@ -34,4 +34,4 @@ def test_valid_web_application_settings(app_environment: EnvVarsDict): assert settings.RESOURCE_USAGE_TRACKER_POSTGRES assert settings.RESOURCE_USAGE_TRACKER_REDIS assert settings.RESOURCE_USAGE_TRACKER_RABBITMQ - assert settings.LOG_LEVEL + assert settings.RESOURCE_USAGE_TRACKER_LOGLEVEL diff --git a/services/resource-usage-tracker/tests/unit/test_main.py b/services/resource-usage-tracker/tests/unit/test_main.py index 6d9addd8ee2..7fe4c95cbc2 100644 --- a/services/resource-usage-tracker/tests/unit/test_main.py +++ b/services/resource-usage-tracker/tests/unit/test_main.py @@ -7,6 +7,6 @@ def test_main_app(app_environment: EnvVarsDict): - from simcore_service_resource_usage_tracker.main import the_app, the_settings + from simcore_service_resource_usage_tracker.main import app_factory - assert the_app.state.settings == the_settings + app_factory() diff --git a/services/storage/Makefile b/services/storage/Makefile index ef350cae091..3627250ce98 100644 --- a/services/storage/Makefile +++ b/services/storage/Makefile @@ -12,7 +12,7 @@ openapi.json: .env @set -o allexport; \ source $<; \ set +o allexport; \ - python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app.openapi(), indent=2) )" > $@ + python3 -c "import json; from $(APP_PACKAGE_NAME).main import *; print( json.dumps(app_factory().openapi(), indent=2) )" > $@ # validates OAS file: $@ $(call validate_openapi_specs,$@) diff --git a/services/storage/docker/boot.sh b/services/storage/docker/boot.sh index 3e1fff945d1..6dd4e72f8e6 100755 --- a/services/storage/docker/boot.sh +++ b/services/storage/docker/boot.sh @@ -76,7 +76,9 @@ else exec sh -c " cd services/storage/src/simcore_service_storage && \ - python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${STORAGE_REMOTE_DEBUGGING_PORT} -m uvicorn main:app \ + python -Xfrozen_modules=off -m debugpy --listen 0.0.0.0:${STORAGE_REMOTE_DEBUGGING_PORT} -m \ + uvicorn \ + --factory main:app_factory \ --host 0.0.0.0 \ --port ${STORAGE_PORT} \ --reload \ @@ -85,9 +87,10 @@ else --log-level \"${SERVER_LOG_LEVEL}\" " else - exec uvicorn simcore_service_storage.main:app \ + exec uvicorn \ + --factory simcore_service_storage.main:app_factory \ --host 0.0.0.0 \ - --port ${STORAGE_PORT} \ + --port "${STORAGE_PORT}" \ --log-level "${SERVER_LOG_LEVEL}" fi fi diff --git a/services/storage/docker/entrypoint.sh b/services/storage/docker/entrypoint.sh index 8511f90e1d7..ad8718d5716 100755 --- a/services/storage/docker/entrypoint.sh +++ b/services/storage/docker/entrypoint.sh @@ -27,6 +27,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" if [ "${SC_BUILD_TARGET}" = "development" ]; then echo "$INFO" "development mode detected..." diff --git a/services/storage/src/simcore_service_storage/cli.py b/services/storage/src/simcore_service_storage/cli.py index bcf4086f4aa..f81e7cd8a38 100644 --- a/services/storage/src/simcore_service_storage/cli.py +++ b/services/storage/src/simcore_service_storage/cli.py @@ -31,7 +31,7 @@ def run(): """Runs application""" typer.secho("Sorry, this entrypoint is intentionally disabled. Use instead") typer.secho( - f"$ uvicorn {PROJECT_NAME}.main:the_app", + f"$ uvicorn --factory {PROJECT_NAME}.main:app_factory", fg=typer.colors.BLUE, ) diff --git a/services/storage/src/simcore_service_storage/core/application.py b/services/storage/src/simcore_service_storage/core/application.py index 2a1fe8246fb..9dbbbd9c181 100644 --- a/services/storage/src/simcore_service_storage/core/application.py +++ b/services/storage/src/simcore_service_storage/core/application.py @@ -44,29 +44,10 @@ from ..modules.s3 import setup_s3 from .settings import ApplicationSettings -_LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -_NOISY_LOGGERS = ( - "aio_pika", - "aiobotocore", - "aiormq", - "botocore", - "httpcore", - "urllib3", - "werkzeug", -) _logger = logging.getLogger(__name__) def create_app(settings: ApplicationSettings) -> FastAPI: # noqa: C901 - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + _LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING - ) - for name in _NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) - - _logger.info("app settings: %s", settings.model_dump_json(indent=1)) - app = FastAPI( debug=settings.SC_BOOT_MODE in [BootModeEnum.DEBUG, BootModeEnum.DEVELOPMENT, BootModeEnum.LOCAL], diff --git a/services/storage/src/simcore_service_storage/main.py b/services/storage/src/simcore_service_storage/main.py index a37ead2cefc..f2282decaa5 100644 --- a/services/storage/src/simcore_service_storage/main.py +++ b/services/storage/src/simcore_service_storage/main.py @@ -1,20 +1,41 @@ """Main application to be deployed in for example uvicorn.""" import logging +from typing import Final -from servicelib.logging_utils import config_all_loggers +from common_library.json_serialization import json_dumps +from fastapi import FastAPI +from servicelib.fastapi.logging_lifespan import create_logging_shutdown_event from simcore_service_storage.core.application import create_app from simcore_service_storage.core.settings import ApplicationSettings -_settings = ApplicationSettings.create_from_envs() +_logger = logging.getLogger(__name__) -# SEE https://github.com/ITISFoundation/osparc-simcore/issues/3148 -logging.basicConfig(level=_settings.log_level) # NOSONAR -logging.root.setLevel(_settings.log_level) -config_all_loggers( - log_format_local_dev_enabled=_settings.STORAGE_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=_settings.STORAGE_LOG_FILTER_MAPPING, - tracing_settings=_settings.STORAGE_TRACING, +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( + "aio_pika", + "aiobotocore", + "aiormq", + "botocore", + "httpcore", + "urllib3", + "werkzeug", ) -app = create_app(_settings) + +def app_factory() -> FastAPI: + app_settings = ApplicationSettings.create_from_envs() + logging_shutdown_event = create_logging_shutdown_event( + log_format_local_dev_enabled=app_settings.STORAGE_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.STORAGE_LOG_FILTER_MAPPING, + tracing_settings=app_settings.STORAGE_TRACING, + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + ) + + _logger.info( + "Application settings: %s", + json_dumps(app_settings, indent=2, sort_keys=True), + ) + app = create_app(settings=app_settings) + app.add_event_handler("shutdown", logging_shutdown_event) + return app diff --git a/services/storage/src/simcore_service_storage/modules/celery/worker_main.py b/services/storage/src/simcore_service_storage/modules/celery/worker_main.py index ebd9832b9e1..396ed37accf 100644 --- a/services/storage/src/simcore_service_storage/modules/celery/worker_main.py +++ b/services/storage/src/simcore_service_storage/modules/celery/worker_main.py @@ -1,6 +1,5 @@ """Main application to be deployed in for example uvicorn.""" -import logging from functools import partial from celery.signals import worker_init, worker_shutdown # type: ignore[import-untyped] @@ -10,7 +9,7 @@ on_worker_shutdown, ) from servicelib.fastapi.celery.app_server import FastAPIAppServer -from servicelib.logging_utils import config_all_loggers +from servicelib.logging_utils import setup_loggers from ...api._worker_tasks.tasks import setup_worker_tasks from ...core.application import create_app @@ -18,12 +17,12 @@ _settings = ApplicationSettings.create_from_envs() -logging.basicConfig(level=_settings.log_level) # NOSONAR -logging.root.setLevel(_settings.log_level) -config_all_loggers( +setup_loggers( log_format_local_dev_enabled=_settings.STORAGE_LOG_FORMAT_LOCAL_DEV_ENABLED, logger_filter_mapping=_settings.STORAGE_LOG_FILTER_MAPPING, tracing_settings=_settings.STORAGE_TRACING, + log_base_level=_settings.log_level, + noisy_loggers=None, ) diff --git a/services/storage/tests/conftest.py b/services/storage/tests/conftest.py index 8fbf7c550e9..32813640197 100644 --- a/services/storage/tests/conftest.py +++ b/services/storage/tests/conftest.py @@ -98,6 +98,7 @@ "pytest_simcore.environment_configs", "pytest_simcore.file_extra", "pytest_simcore.httpbin_service", + "pytest_simcore.logging", "pytest_simcore.openapi_specs", "pytest_simcore.postgres_service", "pytest_simcore.pytest_global_environs", diff --git a/services/web/server/docker/entrypoint.sh b/services/web/server/docker/entrypoint.sh index 9e7e1a2bc2e..184ea4e00a1 100755 --- a/services/web/server/docker/entrypoint.sh +++ b/services/web/server/docker/entrypoint.sh @@ -27,6 +27,7 @@ echo "$INFO" "Workdir : $(pwd)" echo "$INFO" "User : $(id scu)" echo "$INFO" "python : $(command -v python)" echo "$INFO" "pip : $(command -v pip)" +echo "$INFO" "UV : $(command -v uv)" if [ "${SC_BUILD_TARGET}" = "development" ]; then echo "$INFO" "development mode detected..." diff --git a/services/web/server/src/simcore_service_webserver/application_settings.py b/services/web/server/src/simcore_service_webserver/application_settings.py index 72aefe6a363..af7c4c79ed8 100644 --- a/services/web/server/src/simcore_service_webserver/application_settings.py +++ b/services/web/server/src/simcore_service_webserver/application_settings.py @@ -15,6 +15,7 @@ model_validator, ) from pydantic.fields import Field +from servicelib.logging_utils import LogLevelInt from servicelib.logging_utils_filtering import LoggerName, MessageSubstring from settings_library.application import BaseApplicationSettings from settings_library.email import SMTPSettings @@ -462,8 +463,8 @@ def _get_healthcheck_timeout_in_seconds(cls, v): # HELPERS -------------------------------------------------------- @cached_property - def log_level(self) -> int: - level: int = getattr(logging, self.WEBSERVER_LOGLEVEL.upper()) + def log_level(self) -> LogLevelInt: + level: LogLevelInt = getattr(logging, self.WEBSERVER_LOGLEVEL.upper()) return level def is_enabled(self, field_name: str) -> bool: diff --git a/services/web/server/src/simcore_service_webserver/cli.py b/services/web/server/src/simcore_service_webserver/cli.py index 67dd2b445bc..de59ad46ddf 100644 --- a/services/web/server/src/simcore_service_webserver/cli.py +++ b/services/web/server/src/simcore_service_webserver/cli.py @@ -72,20 +72,14 @@ async def app_factory() -> web.Application: "Using application factory: %s", app_settings.WEBSERVER_APP_FACTORY_NAME ) - setup_logging( - level=app_settings.log_level, - slow_duration=app_settings.AIODEBUG_SLOW_DURATION_SECS, - log_format_local_dev_enabled=app_settings.WEBSERVER_LOG_FORMAT_LOCAL_DEV_ENABLED, - logger_filter_mapping=app_settings.WEBSERVER_LOG_FILTER_MAPPING, - tracing_settings=app_settings.WEBSERVER_TRACING, - ) + logging_lifespan_cleanup_event = setup_logging(app_settings) if app_settings.WEBSERVER_APP_FACTORY_NAME == "WEBSERVER_AUTHZ_APP_FACTORY": - app = create_application_auth() else: app, _ = _setup_app_from_settings(app_settings) + app.on_cleanup.append(logging_lifespan_cleanup_event) return app diff --git a/services/web/server/src/simcore_service_webserver/log.py b/services/web/server/src/simcore_service_webserver/log.py index b8d3ba328b3..271c28bd7b9 100644 --- a/services/web/server/src/simcore_service_webserver/log.py +++ b/services/web/server/src/simcore_service_webserver/log.py @@ -1,14 +1,17 @@ """Configuration and utilities for service logging""" import logging +from collections.abc import Awaitable, Callable +from contextlib import AsyncExitStack +from typing import Final, TypeAlias from aiodebug import log_slow_callbacks # type: ignore[import-untyped] +from aiohttp import web from aiohttp.log import access_logger -from servicelib.logging_utils import config_all_loggers -from settings_library.tracing import TracingSettings +from servicelib.logging_utils import async_loggers +from simcore_service_webserver.application_settings import ApplicationSettings -LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR -NOISY_LOGGERS = ( +_NOISY_LOGGERS: Final[tuple[str, ...]] = ( "aio_pika", "aiormq", "engineio", @@ -22,24 +25,21 @@ "sqlalchemy", ) +_logger = logging.getLogger(__name__) -def setup_logging( - *, - level: str | int, - slow_duration: float | None = None, - log_format_local_dev_enabled: bool, - logger_filter_mapping: dict, - tracing_settings: TracingSettings | None, -): - # service log level - logging.basicConfig(level=level) +CleanupEvent: TypeAlias = Callable[[web.Application], Awaitable[None]] - # root - logging.root.setLevel(level) - config_all_loggers( - log_format_local_dev_enabled=log_format_local_dev_enabled, - logger_filter_mapping=logger_filter_mapping, - tracing_settings=tracing_settings, + +def setup_logging(app_settings: ApplicationSettings) -> CleanupEvent: + exit_stack = AsyncExitStack() + exit_stack.enter_context( + async_loggers( + log_base_level=app_settings.log_level, + noisy_loggers=_NOISY_LOGGERS, + log_format_local_dev_enabled=app_settings.WEBSERVER_LOG_FORMAT_LOCAL_DEV_ENABLED, + logger_filter_mapping=app_settings.WEBSERVER_LOG_FILTER_MAPPING, + tracing_settings=app_settings.WEBSERVER_TRACING, + ) ) # Enforces same log-level to aiohttp & gunicorn access loggers @@ -50,17 +50,16 @@ def setup_logging( # they are not applied globally but only upon setup_logging ... # gunicorn_access_log = logging.getLogger("gunicorn.access") - access_logger.setLevel(level) - gunicorn_access_log.setLevel(level) + access_logger.setLevel(app_settings.log_level) + gunicorn_access_log.setLevel(app_settings.log_level) - # keep mostly quiet noisy loggers - quiet_level: int = max( - min(logging.root.level + LOG_LEVEL_STEP, logging.CRITICAL), logging.WARNING - ) + if app_settings.AIODEBUG_SLOW_DURATION_SECS: + # NOTE: Every task blocking > AIODEBUG_SLOW_DURATION_SECS secs is considered slow and logged as warning + log_slow_callbacks.enable(abs(app_settings.AIODEBUG_SLOW_DURATION_SECS)) - for name in NOISY_LOGGERS: - logging.getLogger(name).setLevel(quiet_level) + async def _cleanup_event(app: web.Application) -> None: + assert app # nosec + _logger.info("Cleaning up application resources") + await exit_stack.aclose() - if slow_duration: - # NOTE: Every task blocking > AIODEBUG_SLOW_DURATION_SECS secs is considered slow and logged as warning - log_slow_callbacks.enable(abs(slow_duration)) + return _cleanup_event diff --git a/services/web/server/tests/conftest.py b/services/web/server/tests/conftest.py index 3a8917a7898..b6c62eae17b 100644 --- a/services/web/server/tests/conftest.py +++ b/services/web/server/tests/conftest.py @@ -74,6 +74,7 @@ "pytest_simcore.environment_configs", "pytest_simcore.faker_users_data", "pytest_simcore.hypothesis_type_strategies", + "pytest_simcore.logging", "pytest_simcore.openapi_specs", "pytest_simcore.postgres_service", "pytest_simcore.pydantic_models", diff --git a/services/web/server/tests/unit/with_dbs/04/studies_dispatcher/conftest.py b/services/web/server/tests/unit/with_dbs/04/studies_dispatcher/conftest.py index cdae2960c74..1b4b8e20ff2 100644 --- a/services/web/server/tests/unit/with_dbs/04/studies_dispatcher/conftest.py +++ b/services/web/server/tests/unit/with_dbs/04/studies_dispatcher/conftest.py @@ -4,12 +4,9 @@ # pylint: disable=too-many-arguments -import logging - import pytest from pytest_simcore.helpers.monkeypatch_envs import setenvs_from_dict from pytest_simcore.helpers.typing_env import EnvVarsDict -from simcore_service_webserver.log import setup_logging from simcore_service_webserver.studies_dispatcher.settings import ( StudiesDispatcherSettings, ) @@ -50,14 +47,6 @@ def app_environment(app_environment: EnvVarsDict, monkeypatch: pytest.MonkeyPatc }, ) - # NOTE: To see logs, use pytest -s --log-cli-level=DEBUG - setup_logging( - level=logging.DEBUG, - log_format_local_dev_enabled=True, - logger_filter_mapping={}, - tracing_settings=None, - ) - plugin_settings = StudiesDispatcherSettings.create_from_envs() print(plugin_settings.model_dump_json(indent=1))