✨ Is3200/log user during login/logout (ITISFoundation#3205)

Author: pcrespov

packages/service-library/src/servicelib/logging_utils.py

@@ -1,5 +1,8 @@
 """
-This codes originates from this article (https://medium.com/swlh/add-log-decorators-to-your-python-project-84094f832181)
+This codes originates from this article
+    https://medium.com/swlh/add-log-decorators-to-your-python-project-84094f832181
+
+SEE also https://github.com/Delgan/loguru for a future alternative
 """
 import asyncio
 import functools
@@ -181,3 +184,15 @@ def log_catch(logger: logging.Logger, reraise: bool = True):
         logger.error("Unhandled exception: %s", f"{exc}", exc_info=True)
         if reraise:
             raise exc from exc
+
+
+un_capitalize = lambda s: s[:1].lower() + s[1:] if s else ""
+
+
+@contextmanager
+def log_context(logger: logging.Logger, level: int, msg: str, *args, **kwargs):
+    # NOTE: preserves original signature https://docs.python.org/3/library/logging.html#logging.Logger.log
+    msg = un_capitalize(msg.strip())
+    logger.log(level, "Starting " + msg + " ...", *args, **kwargs)
+    yield
+    logger.log(level, "Finished " + msg, *args, **kwargs)

services/web/server/src/simcore_service_webserver/login/handlers.py

@@ -1,9 +1,9 @@
 import logging
-from typing import Dict
 
 from aiohttp import web
 from servicelib import observer
 from servicelib.aiohttp.rest_utils import extract_and_validate
+from servicelib.logging_utils import log_context
 from yarl import URL
 
 from ..db_models import ConfirmationAction, UserRole, UserStatus
@@ -66,7 +66,7 @@ async def register(request: web.Request):
 
     await check_registration(email, password, confirm, db, cfg)
 
-    user: Dict = await db.create_user(
+    user: dict = await db.create_user(
         {
             "name": username,
             "email": email,
@@ -150,12 +150,17 @@ async def login(request: web.Request):
     assert user["status"] == ACTIVE, "db corrupted. Invalid status"  # nosec
     assert user["email"] == email, "db corrupted. Invalid email"  # nosec
 
-    # user logs in
-    identity = user["email"]
-    response = flash_response(cfg.MSG_LOGGED_IN, "INFO")
-
-    await remember(request, response, identity)
-    return response
+    with log_context(
+        log,
+        logging.INFO,
+        "login of user_id=%s with %s",
+        f"{user.get('id')}",
+        f"{email=}",
+    ):
+        identity = user["email"]
+        response = flash_response(cfg.MSG_LOGGED_IN, "INFO")
+        await remember(request, response, identity)
+        return response
 
 
 @login_required
@@ -168,8 +173,16 @@ async def logout(request: web.Request) -> web.Response:
     if request.can_read_body:
         body = await request.json()
         client_session_id = body.get("client_session_id", None)
-    await observer.emit("SIGNAL_USER_LOGOUT", user_id, client_session_id, request.app)
-    await forget(request, response)
+
+    # Keep log message: https://github.com/ITISFoundation/osparc-simcore/issues/3200
+    with log_context(
+        log, logging.INFO, "logout of %s for %s", f"{user_id=}", f"{client_session_id=}"
+    ):
+        await observer.emit(
+            "SIGNAL_USER_LOGOUT", user_id, client_session_id, request.app
+        )
+        await forget(request, response)
+
     return response
 
 

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

@@ -8,10 +8,11 @@
 
 import asyncio
 import logging
-from typing import Any, Dict, List, Optional
+from typing import Any, Optional
 
 from aiohttp import web
 from servicelib.aiohttp.application_keys import APP_FIRE_AND_FORGET_TASKS_KEY
+from servicelib.logging_utils import log_context
 from servicelib.observer import emit, observe
 from servicelib.utils import fire_and_forget_task, logged_gather
 from socketio import AsyncServer
@@ -31,7 +32,7 @@
 
 
 @register_socketio_handler
-async def connect(sid: str, environ: Dict, app: web.Application) -> bool:
+async def connect(sid: str, environ: dict, app: web.Application) -> bool:
     """socketio reserved handler for when the fontend connects through socket.io
 
     Arguments:
@@ -60,7 +61,7 @@ async def connect(sid: str, environ: Dict, app: web.Application) -> bool:
     log.info("Sending set_heartbeat_emit_interval with %s", emit_interval)
 
     user_id = request.get(RQT_USERID_KEY, ANONYMOUS_USER_ID)
-    heart_beat_messages: List[SocketMessageDict] = [
+    heart_beat_messages: list[SocketMessageDict] = [
         {
             "event_type": SOCKET_IO_HEARTBEAT_EVENT,
             "data": {"interval": emit_interval},
@@ -110,7 +111,7 @@ async def set_user_in_rooms(
         sio.enter_room(sid, f"{group['gid']}")
 
 
-async def disconnect_other_sockets(sio, sockets: List[str]) -> None:
+async def disconnect_other_sockets(sio, sockets: list[str]) -> None:
     log.debug("disconnecting sockets %s", sockets)
     logout_tasks = [
         sio.emit("logout", to=sid, data={"reason": "user logged out"})
@@ -170,13 +171,22 @@ async def disconnect(sid: str, app: web.Application) -> None:
     sio = get_socket_server(app)
     async with sio.session(sid) as socketio_session:
         if "user_id" in socketio_session:
+
             user_id = socketio_session["user_id"]
             client_session_id = socketio_session["client_session_id"]
-            with managed_resource(user_id, client_session_id, app) as rt:
-                log.debug("client %s disconnected from room %s", user_id, sid)
-                await rt.remove_socket_id()
-            # signal same user other clients if available
-            await emit("SIGNAL_USER_DISCONNECTED", user_id, client_session_id, app)
+
+            with log_context(
+                log,
+                logging.INFO,
+                "disconnection of %s for %s",
+                f"{user_id=}",
+                f"{client_session_id=}",
+            ):
+                with managed_resource(user_id, client_session_id, app) as rt:
+                    log.debug("client %s disconnected from room %s", user_id, sid)
+                    await rt.remove_socket_id()
+                # signal same user other clients if available
+                await emit("SIGNAL_USER_DISCONNECTED", user_id, client_session_id, app)
 
         else:
             # this should not happen!!