🐛 Handles socketio exception on disconnect and fixes double logging of monitoring middleware (#8067)

Author: pcrespov

packages/service-library/src/servicelib/aiohttp/monitoring.py

@@ -25,7 +25,7 @@
 )
 from .typing_extension import Handler
 
-log = logging.getLogger(__name__)
+_logger = logging.getLogger(__name__)
 
 _PROMETHEUS_METRICS: Final[str] = f"{__name__}.prometheus_metrics"  # noqa: N816
 
@@ -59,7 +59,6 @@ def middleware_factory(
     async def middleware_handler(request: web.Request, handler: Handler):
         # See https://prometheus.io/docs/concepts/metric_types
 
-        log_exception: BaseException | None = None
         response: web.StreamResponse = web.HTTPInternalServerError()
 
         canonical_endpoint = request.path
@@ -68,7 +67,7 @@ async def middleware_handler(request: web.Request, handler: Handler):
         start_time = perf_counter()
         try:
             if enter_middleware_cb:
-                with log_catch(logger=log, reraise=False):
+                with log_catch(logger=_logger, reraise=False):
                     await enter_middleware_cb(request)
 
             metrics = request.app[_PROMETHEUS_METRICS]
@@ -92,16 +91,10 @@ async def middleware_handler(request: web.Request, handler: Handler):
 
         except web.HTTPServerError as exc:
             response = exc
-            log_exception = exc
             raise
 
         except web.HTTPException as exc:
             response = exc
-            log_exception = None
-            raise
-
-        except Exception as exc:  # pylint: disable=broad-except
-            log_exception = exc
             raise
 
         finally:
@@ -117,23 +110,9 @@ async def middleware_handler(request: web.Request, handler: Handler):
             )
 
             if exit_middleware_cb:
-                with log_catch(logger=log, reraise=False):
+                with log_catch(logger=_logger, reraise=False):
                     await exit_middleware_cb(request, response)
 
-            if log_exception:
-                log.error(
-                    'Unexpected server error "%s" from access: %s "%s %s" done '
-                    "in %3.2f secs. Responding with status %s",
-                    type(log_exception),
-                    request.remote,
-                    request.method,
-                    request.path,
-                    response_latency_seconds,
-                    response.status,
-                    exc_info=log_exception,
-                    stack_info=True,
-                )
-
         return response
 
     setattr(  # noqa: B010

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

@@ -4,6 +4,7 @@
 SEE http://python-socketio.readthedocs.io/en/latest/
 """
 
+import contextlib
 import logging
 from typing import Any
 
@@ -14,6 +15,7 @@
 from models_library.socketio import SocketMessageDict
 from models_library.users import UserID
 from servicelib.aiohttp.observer import emit
+from servicelib.logging_errors import create_troubleshootting_log_kwargs
 from servicelib.logging_utils import get_log_record_extra, log_context
 from servicelib.request_keys import RQT_USERID_KEY
 
@@ -162,37 +164,64 @@ async def connect(
 @register_socketio_handler
 async def disconnect(socket_id: SocketID, app: web.Application) -> None:
     """socketio reserved handler for when the socket.io connection is disconnected."""
-    sio = get_socket_server(app)
-    async with sio.session(socket_id) as socketio_session:
-        if user_id := socketio_session.get("user_id"):
+    async with contextlib.AsyncExitStack() as stack:
+
+        # retrieve the socket session
+        try:
+            socketio_session = await stack.enter_async_context(
+                get_socket_server(app).session(socket_id)
+            )
+
+        except KeyError as err:
+            _logger.warning(
+                **create_troubleshootting_log_kwargs(
+                    f"Socket session {socket_id} not found during disconnect, already cleaned up",
+                    error=err,
+                    error_context={"socket_id": socket_id},
+                )
+            )
+            return
+
+        # session is wel formed, we can access its data
+        try:
+
+            user_id = socketio_session["user_id"]
             client_session_id = socketio_session["client_session_id"]
             product_name = socketio_session["product_name"]
 
-            with log_context(
-                _logger,
-                logging.INFO,
-                "disconnection of %s with %s",
-                f"{user_id=}",
-                f"{client_session_id=}",
-            ):
-                with managed_resource(user_id, client_session_id, app) as user_session:
-                    await user_session.remove_socket_id()
-                # signal same user other clients if available
-                await emit(
-                    app,
-                    "SIGNAL_USER_DISCONNECTED",
-                    user_id,
-                    client_session_id,
-                    app,
-                    product_name,
+        except KeyError as err:
+            _logger.exception(
+                **create_troubleshootting_log_kwargs(
+                    f"Socket session {socket_id} does not have user_id or client_session_id during disconnect",
+                    error=err,
+                    error_context={
+                        "socket_id": socket_id,
+                        "socketio_session": socketio_session,
+                    },
+                    tip="Check if session is corrupted",
                 )
+            )
+            return
 
-        else:
-            # this should not happen!!
-            _logger.error(
-                "Unknown client diconnected sid: %s, session %s",
-                socket_id,
-                f"{socketio_session}",
+        # Disconnecting
+        with log_context(
+            _logger,
+            logging.INFO,
+            "disconnection of %s with %s",
+            f"{user_id=}",
+            f"{client_session_id=}",
+        ):
+            with managed_resource(user_id, client_session_id, app) as user_session:
+                await user_session.remove_socket_id()
+
+            # signal same user other clients if available
+            await emit(
+                app,
+                "SIGNAL_USER_DISCONNECTED",
+                user_id,
+                client_session_id,
+                app,
+                product_name,
             )