♻️🐛Properly configure socketio/engineio log output (#8057)

Author: sanderegg

.env-devel

@@ -161,7 +161,7 @@ INVITATIONS_USERNAME=admin
 INVITATIONS_TRACING=null
 
 LOG_FORMAT_LOCAL_DEV_ENABLED=1
-LOG_FILTER_MAPPING='{}'
+LOG_FILTER_MAPPING='{"gunicorn.access":[" /v0/ ", " /v0/health "], "uvicorn.access":[" / "]}'
 
 NOTIFICATIONS_LOGLEVEL=INFO
 NOTIFICATIONS_TRACING=null

services/director-v2/src/simcore_service_director_v2/core/application.py

@@ -99,6 +99,7 @@ def _set_exception_handlers(app: FastAPI):
     "aio_pika",
     "aiormq",
     "httpcore",
+    "httpx",
 )
 
 
@@ -201,9 +202,7 @@ 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:

services/director/src/simcore_service_director/core/application.py

@@ -22,7 +22,11 @@
 from .settings import ApplicationSettings
 
 _LOG_LEVEL_STEP = logging.CRITICAL - logging.ERROR
-_NOISY_LOGGERS: Final[tuple[str]] = ("werkzeug",)
+_NOISY_LOGGERS: Final[tuple[str, ...]] = (
+    "httpcore",
+    "httpx",
+    "werkzeug",
+)
 
 _logger = logging.getLogger(__name__)
 

services/payments/src/simcore_service_payments/api/rest/_health.py

@@ -23,9 +23,9 @@ class HealthCheckError(RuntimeError):
 async def healthcheck(
     rabbitmq_client: Annotated[
         RabbitMQClient, Depends(get_rabbitmq_client_from_request)
-    ]
+    ],
 ) -> str:
-    _logger.info("Checking rabbit health check %s", rabbitmq_client.healthy)
+    _logger.debug("Checking rabbit health check %s", rabbitmq_client.healthy)
     if not rabbitmq_client.healthy:
         raise HealthCheckError(RABBITMQ_CLIENT_UNHEALTHY_MSG)
 

services/web/server/src/simcore_service_webserver/log.py

@@ -1,6 +1,4 @@
-""" Configuration and utilities for service logging
-
-"""
+"""Configuration and utilities for service logging"""
 
 import logging
 
@@ -14,13 +12,14 @@
     "aio_pika",
     "aiormq",
     "engineio",
+    "engineio.server",
     "inotify.adapters",
-    "gunicorn.access",
     "openapi_spec_validator",
     "servicelib.aiohttp.monitoring",
+    "socketio",
+    "socketio.server",
     "sqlalchemy.engine",
     "sqlalchemy",
-    "socketio",
 )
 
 
@@ -30,7 +29,7 @@ def setup_logging(
     slow_duration: float | None = None,
     log_format_local_dev_enabled: bool,
     logger_filter_mapping: dict,
-    tracing_settings: TracingSettings | None
+    tracing_settings: TracingSettings | None,
 ):
     # service log level
     logging.basicConfig(level=level)

services/web/server/src/simcore_service_webserver/socketio/_handlers.py

@@ -74,11 +74,6 @@ async def _handler(request: web.Request) -> tuple[UserID, ProductName, str]:
 
         # REDIS wrapper
         with managed_resource(user_id, client_session_id, app) as resource_registry:
-            _logger.info(
-                "socketio connection from user %s",
-                user_id,
-                extra=get_log_record_extra(user_id=user_id),
-            )
             await resource_registry.set_socket_id(socket_id)
 
         return user_id, product.name, client_session_id
@@ -129,10 +124,16 @@ async def connect(
         user_id, product_name, client_session_id = await auth_user_handler(
             environ["aiohttp.request"]
         )
+        _logger.info(
+            "%s successfully connected with %s",
+            f"{user_id=}",
+            f"{client_session_id=}",
+            extra=get_log_record_extra(user_id=user_id),
+        )
 
         await _set_user_in_group_rooms(app, user_id, socket_id)
 
-        _logger.info("Sending set_heartbeat_emit_interval with %s", _EMIT_INTERVAL_S)
+        _logger.debug("Sending set_heartbeat_emit_interval with %s", _EMIT_INTERVAL_S)
 
         await emit(
             app, "SIGNAL_USER_CONNECTED", user_id, app, product_name, client_session_id
@@ -170,7 +171,7 @@ async def disconnect(socket_id: SocketID, app: web.Application) -> None:
             with log_context(
                 _logger,
                 logging.INFO,
-                "disconnection of %s for %s",
+                "disconnection of %s with %s",
                 f"{user_id=}",
                 f"{client_session_id=}",
             ):

services/web/server/src/simcore_service_webserver/socketio/messages.py

@@ -54,7 +54,7 @@ async def _safe_emit(
             room=room,
             ignore_queue=ignore_queue,
         )
-        _logger.info("emitted socketio event '%s' to room '%s'", event, room)
+        _logger.debug("emitted socketio event '%s' to room '%s'", event, room)
 
 
 async def send_message_to_user(

services/web/server/src/simcore_service_webserver/socketio/server.py

@@ -19,17 +19,12 @@
 
 
 async def _socketio_server_cleanup_ctx(app: web.Application) -> AsyncIterator[None]:
-    use_logger: bool | logging.Logger = _logger
-
     # SEE https://github.com/miguelgrinberg/python-socketio/blob/v4.6.1/docs/server.rst#aiohttp
-    server_manager = AsyncAioPikaManager(
-        url=get_rabbitmq_settings(app).dsn,
-        logger=use_logger,
-    )
+    server_manager = AsyncAioPikaManager(url=get_rabbitmq_settings(app).dsn)
     sio_server = AsyncServer(
         async_mode="aiohttp",
-        logger=use_logger,
-        engineio_logger=False,
+        logger=True,
+        engineio_logger=True,
         client_manager=server_manager,
         json=JsonNamespace,
     )