⚗️Introduce asynchronous logging facilities (🚨) (#8064)

Author: sanderegg

.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={}

.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/*

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",

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",

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,

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)

packages/service-library/src/servicelib/fastapi/lifespan_utils.py

@@ -1,13 +1,15 @@
 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
 from fastapi_lifespan_manager import State
 
 from ..logging_utils import log_context
 
+Lifespan: TypeAlias = Callable[[FastAPI], AsyncIterator[None]]
+
 
 class LifespanError(OsparcErrorMixin, RuntimeError): ...
 

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