Merge pull request #186 from tiqi-group/175-add-support-for-enhanced-client-information-logging-in-socketio-server

feat: add support for enhanced client information logging in socketio server

docs/user-guide/Logging.md

@@ -0,0 +1,55 @@
+## Logging in pydase
+
+The `pydase` library organizes its loggers per module, mirroring the Python package hierarchy. This structured approach allows for granular control over logging levels and behaviour across different parts of the library. Logs can also include details about client identification based on headers sent by the client or proxy, providing additional context for debugging or auditing.
+
+### Changing the Log Level
+
+You have two primary ways to adjust the log levels in `pydase`:
+
+1. **Directly targeting `pydase` loggers**
+
+   You can set the log level for any `pydase` logger directly in your code. This method is useful for fine-tuning logging levels for specific modules within `pydase`. For instance, if you want to change the log level of the main `pydase` logger or target a submodule like `pydase.data_service`, you can do so as follows:
+
+   ```python
+   # <your_script.py>
+   import logging
+
+   # Set the log level for the main pydase logger
+   logging.getLogger("pydase").setLevel(logging.INFO)
+
+   # Optionally, target a specific submodule logger
+   # logging.getLogger("pydase.data_service").setLevel(logging.DEBUG)
+
+   # Your logger for the current script
+   logging.basicConfig(level=logging.INFO)
+   logger = logging.getLogger(__name__)
+   logger.info("My info message.")
+   ```
+
+   This approach allows for specific control over different parts of the `pydase` library, depending on your logging needs.
+
+2. **Using the `ENVIRONMENT` environment variable**
+
+   For a more global setting that affects the entire `pydase` library, you can utilize the `ENVIRONMENT` environment variable. Setting this variable to `"production"` will configure all `pydase` loggers to only log messages of level `"INFO"` and above, filtering out more verbose logging. This is particularly useful for production environments where excessive logging can be overwhelming or unnecessary.
+
+   ```bash
+   ENVIRONMENT="production" python -m <module_using_pydase>
+   ```
+
+   In the absence of this setting, the default behavior is to log everything of level `"DEBUG"` and above, suitable for development environments where more detailed logs are beneficial.
+
+### Client Identification in Logs
+
+The logging system in `pydase` includes information about clients based on headers sent by the client or a proxy. The priority for identifying the client is fixed and as follows:
+
+1. **`Remote-User` Header**: This header is typically set by authentication servers like [Authelia](https://www.authelia.com/). While it can be set manually by users, its primary purpose is to provide client information authenticated through such servers.
+2. **`X-Client-ID` Header**: This header is intended for use by Python clients to pass custom client identification information. It acts as a fallback when the `Remote-User` header is not available.
+3. **Default Socket.IO Session ID**: If neither of the above headers is present, the system falls back to the default Socket.IO session ID to identify the client.
+
+For example, a log entries might include the following details based on the available headers:
+
+```plaintext
+2025-01-20 06:47:50.940 | INFO     | pydase.server.web_server.api.v1.application:_get_value:36 - Client [id=This is me!] is getting the value of 'property_attr'
+
+2025-01-20 06:48:13.710 | INFO     | pydase.server.web_server.api.v1.application:_get_value:36 - Client [user=Max Muster] is getting the value of 'property_attr'
+```

mkdocs.yml

@@ -12,6 +12,7 @@ nav:
     - Understanding Units: user-guide/Understanding-Units.md
     - Validating Property Setters: user-guide/Validating-Property-Setters.md
     - Configuring pydase: user-guide/Configuration.md
+    - Logging in pydase: user-guide/Logging.md
     - Advanced:
         - Deploying behind a Reverse Proxy: user-guide/advanced/Reverse-Proxy.md
   - Developer Guide: 

src/pydase/server/web_server/api/v1/application.py

@@ -5,6 +5,7 @@ from typing import TYPE_CHECKING
 
 import aiohttp.web
 import aiohttp_middlewares.error
+import click
 
 from pydase.data_service.state_manager import StateManager
 from pydase.server.web_server.api.v1.endpoints import (
@@ -28,10 +29,12 @@ STATUS_FAILED = 400
 async def _get_value(
     request: aiohttp.web.Request, state_manager: StateManager
 ) -> aiohttp.web.Response:
-    logger.info("Handle api request: %s", request)
+    log_id = get_log_id(request)
 
     access_path = request.rel_url.query["access_path"]
 
+    logger.info("Client [%s] is getting the value of '%s'", log_id, access_path)
+
     status = STATUS_OK
     try:
         result = get_value(state_manager, access_path)
@@ -45,8 +48,14 @@ async def _get_value(
 async def _update_value(
     request: aiohttp.web.Request, state_manager: StateManager
 ) -> aiohttp.web.Response:
+    log_id = get_log_id(request)
+
     data: UpdateDict = await request.json()
 
+    logger.info(
+        "Client [%s] is updating the value of '%s'", log_id, data["access_path"]
+    )
+
     try:
         update_value(state_manager, data)
 
@@ -59,9 +68,15 @@ async def _update_value(
 async def _trigger_method(
     request: aiohttp.web.Request, state_manager: StateManager
 ) -> aiohttp.web.Response:
+    log_id = get_log_id(request)
+
     data: TriggerMethodDict = await request.json()
 
-    method = get_object_attr_from_path(state_manager.service, data["access_path"])
+    access_path = data["access_path"]
+
+    logger.info("Client [%s] is triggering the method '%s'", log_id, access_path)
+
+    method = get_object_attr_from_path(state_manager.service, access_path)
 
     try:
         if inspect.iscoroutinefunction(method):
@@ -78,6 +93,20 @@ async def _trigger_method(
         return aiohttp.web.json_response(dump(e), status=STATUS_FAILED)
 
 
+def get_log_id(request: aiohttp.web.Request) -> str:
+    client_id_header = request.headers.get("x-client-id", None)
+    remote_username_header = request.headers.get("remote-user", None)
+
+    if remote_username_header is not None:
+        log_id = f"user={click.style(remote_username_header, fg='cyan')}"
+    elif client_id_header is not None:
+        log_id = f"id={click.style(client_id_header, fg='cyan')}"
+    else:
+        log_id = f"id={click.style(None, fg='cyan')}"
+
+    return log_id
+
+
 def create_api_application(state_manager: StateManager) -> aiohttp.web.Application:
     api_application = aiohttp.web.Application(
         middlewares=(aiohttp_middlewares.error.error_middleware(),)

src/pydase/server/web_server/sio_setup.py

@@ -141,22 +141,41 @@ def setup_sio_server(
 def setup_sio_events(sio: socketio.AsyncServer, state_manager: StateManager) -> None:  # noqa: C901
     @sio.event  # type: ignore
     async def connect(sid: str, environ: Any) -> None:
-        logger.debug("Client [%s] connected", click.style(str(sid), fg="cyan"))
+        client_id_header = environ.get("HTTP_X_CLIENT_ID", None)
+        remote_username_header = environ.get("HTTP_REMOTE_USER", None)
+
+        if remote_username_header is not None:
+            log_id = f"user={click.style(remote_username_header, fg='cyan')}"
+        elif client_id_header is not None:
+            log_id = f"id={click.style(client_id_header, fg='cyan')}"
+        else:
+            log_id = f"sid={click.style(sid, fg='cyan')}"
+
+        async with sio.session(sid) as session:
+            session["client_id"] = log_id
+            logger.info("Client [%s] connected", session["client_id"])
 
     @sio.event  # type: ignore
     async def disconnect(sid: str) -> None:
-        logger.debug("Client [%s] disconnected", click.style(str(sid), fg="cyan"))
+        async with sio.session(sid) as session:
+            logger.info("Client [%s] disconnected", session["client_id"])
 
     @sio.event  # type: ignore
     async def service_serialization(sid: str) -> SerializedObject:
-        logger.debug(
+        async with sio.session(sid) as session:
-            "Client [%s] requested service serialization",
+            logger.info(
-            click.style(str(sid), fg="cyan"),
+                "Client [%s] requested service serialization", session["client_id"]
             )
         return state_manager.cache_manager.cache
 
     @sio.event
     async def update_value(sid: str, data: UpdateDict) -> SerializedObject | None:
+        async with sio.session(sid) as session:
+            logger.info(
+                "Client [%s] is updating the value of '%s'",
+                session["client_id"],
+                data["access_path"],
+            )
         try:
             endpoints.update_value(state_manager=state_manager, data=data)
         except Exception as e:
@@ -166,6 +185,12 @@ def setup_sio_events(sio: socketio.AsyncServer, state_manager: StateManager) ->
 
     @sio.event
     async def get_value(sid: str, access_path: str) -> SerializedObject:
+        async with sio.session(sid) as session:
+            logger.info(
+                "Client [%s] is getting the value of '%s'",
+                session["client_id"],
+                access_path,
+            )
         try:
             return endpoints.get_value(
                 state_manager=state_manager, access_path=access_path
@@ -176,9 +201,16 @@ def setup_sio_events(sio: socketio.AsyncServer, state_manager: StateManager) ->
 
     @sio.event
     async def trigger_method(sid: str, data: TriggerMethodDict) -> Any:
-        method = get_object_attr_from_path(state_manager.service, data["access_path"])
+        async with sio.session(sid) as session:
-
+            logger.debug(
+                "Client [%s] is triggering the method '%s'",
+                session["client_id"],
+                data["access_path"],
+            )
         try:
+            method = get_object_attr_from_path(
+                state_manager.service, data["access_path"]
+            )
             if inspect.iscoroutinefunction(method):
                 return await endpoints.trigger_async_method(
                     state_manager=state_manager, data=data

tests/server/web_server/api/v1/test_endpoints.py

@@ -185,6 +185,7 @@ async def test_update_value(
     new_value: dict[str, Any],
     ok: bool,
     pydase_server: pydase.DataService,
+    caplog: pytest.LogCaptureFixture,
 ) -> None:
     async with aiohttp.ClientSession("http://localhost:9998") as session:
         resp = await session.put(
@@ -250,3 +251,43 @@ async def test_trigger_method(
         if resp.ok:
             content = Deserializer.deserialize(json.loads(await resp.text()))
             assert content == expected
+
+
+@pytest.mark.parametrize(
+    "headers, log_id",
+    [
+        ({}, "id=None"),
+        (
+            {
+                "X-Client-Id": "client-header",
+            },
+            "id=client-header",
+        ),
+        (
+            {
+                "Remote-User": "Remote User",
+            },
+            "user=Remote User",
+        ),
+        (
+            {
+                "X-Client-Id": "client-header",
+                "Remote-User": "Remote User",
+            },
+            "user=Remote User",
+        ),
+    ],
+)
+@pytest.mark.asyncio()
+async def test_client_information_logging(
+    headers: dict[str, str],
+    log_id: str,
+    pydase_server: pydase.DataService,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    async with aiohttp.ClientSession("http://localhost:9998") as session:
+        await session.get(
+            "/api/v1/get_value?access_path=readonly_attr", headers=headers
+        )
+
+    assert log_id in caplog.text

tests/server/web_server/test_sio_setup.py

@@ -0,0 +1,312 @@
+import threading
+from collections.abc import Generator
+from typing import Any
+
+import pydase
+import pytest
+import socketio
+from pydase.utils.serialization.deserializer import Deserializer
+
+
+@pytest.fixture()
+def pydase_server() -> Generator[None, None, None]:
+    class SubService(pydase.DataService):
+        name = "SubService"
+
+    subservice_instance = SubService()
+
+    class MyService(pydase.DataService):
+        def __init__(self) -> None:
+            super().__init__()
+            self._readonly_attr = "MyService"
+            self._my_property = 12.1
+            self.sub_service = SubService()
+            self.list_attr = [1, 2]
+            self.dict_attr = {
+                "foo": subservice_instance,
+                "dotted.key": subservice_instance,
+            }
+
+        @property
+        def my_property(self) -> float:
+            return self._my_property
+
+        @my_property.setter
+        def my_property(self, value: float) -> None:
+            self._my_property = value
+
+        @property
+        def readonly_attr(self) -> str:
+            return self._readonly_attr
+
+        def my_method(self, input_str: str) -> str:
+            return f"{input_str}: my_method"
+
+        async def my_async_method(self, input_str: str) -> str:
+            return f"{input_str}: my_async_method"
+
+    server = pydase.Server(MyService(), web_port=9997)
+    thread = threading.Thread(target=server.run, daemon=True)
+    thread.start()
+
+    yield
+
+
+@pytest.mark.parametrize(
+    "access_path, expected",
+    [
+        (
+            "readonly_attr",
+            {
+                "full_access_path": "readonly_attr",
+                "doc": None,
+                "readonly": False,
+                "type": "str",
+                "value": "MyService",
+            },
+        ),
+        (
+            "sub_service.name",
+            {
+                "full_access_path": "sub_service.name",
+                "doc": None,
+                "readonly": False,
+                "type": "str",
+                "value": "SubService",
+            },
+        ),
+        (
+            "list_attr[0]",
+            {
+                "full_access_path": "list_attr[0]",
+                "doc": None,
+                "readonly": False,
+                "type": "int",
+                "value": 1,
+            },
+        ),
+        (
+            'dict_attr["foo"]',
+            {
+                "full_access_path": 'dict_attr["foo"]',
+                "doc": None,
+                "name": "SubService",
+                "readonly": False,
+                "type": "DataService",
+                "value": {
+                    "name": {
+                        "doc": None,
+                        "full_access_path": 'dict_attr["foo"].name',
+                        "readonly": False,
+                        "type": "str",
+                        "value": "SubService",
+                    }
+                },
+            },
+        ),
+    ],
+)
+@pytest.mark.asyncio()
+async def test_get_value(
+    access_path: str,
+    expected: dict[str, Any],
+    pydase_server: None,
+) -> None:
+    client = socketio.AsyncClient()
+    await client.connect(
+        "http://localhost:9997", socketio_path="/ws/socket.io", transports=["websocket"]
+    )
+    response = await client.call("get_value", access_path)
+    assert response == expected
+    await client.disconnect()
+
+
+@pytest.mark.parametrize(
+    "access_path, new_value, ok",
+    [
+        (
+            "sub_service.name",
+            {
+                "full_access_path": "sub_service.name",
+                "doc": None,
+                "readonly": False,
+                "type": "str",
+                "value": "New Name",
+            },
+            True,
+        ),
+        (
+            "list_attr[0]",
+            {
+                "full_access_path": "list_attr[0]",
+                "doc": None,
+                "readonly": False,
+                "type": "int",
+                "value": 11,
+            },
+            True,
+        ),
+        (
+            'dict_attr["foo"].name',
+            {
+                "full_access_path": 'dict_attr["foo"].name',
+                "doc": None,
+                "readonly": False,
+                "type": "str",
+                "value": "foo name",
+            },
+            True,
+        ),
+        (
+            "readonly_attr",
+            {
+                "full_access_path": "readonly_attr",
+                "doc": None,
+                "readonly": True,
+                "type": "str",
+                "value": "Other Name",
+            },
+            False,
+        ),
+        (
+            "invalid_attribute",
+            {
+                "full_access_path": "invalid_attribute",
+                "doc": None,
+                "readonly": False,
+                "type": "float",
+                "value": 12.0,
+            },
+            False,
+        ),
+    ],
+)
+@pytest.mark.asyncio()
+async def test_update_value(
+    access_path: str,
+    new_value: dict[str, Any],
+    ok: bool,
+    pydase_server: None,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    client = socketio.AsyncClient()
+    await client.connect(
+        "http://localhost:9997", socketio_path="/ws/socket.io", transports=["websocket"]
+    )
+    response = await client.call(
+        "update_value",
+        {"access_path": access_path, "value": new_value},
+    )
+
+    if ok:
+        assert response is None
+    else:
+        assert response["type"] == "Exception"
+
+    await client.disconnect()
+
+
+@pytest.mark.parametrize(
+    "access_path, expected, ok",
+    [
+        (
+            "my_method",
+            "Hello from function: my_method",
+            True,
+        ),
+        (
+            "my_async_method",
+            "Hello from function: my_async_method",
+            True,
+        ),
+        (
+            "invalid_method",
+            None,
+            False,
+        ),
+    ],
+)
+@pytest.mark.asyncio()
+async def test_trigger_method(
+    access_path: str,
+    expected: Any,
+    ok: bool,
+    pydase_server: pydase.DataService,
+) -> None:
+    client = socketio.AsyncClient()
+    await client.connect(
+        "http://localhost:9997", socketio_path="/ws/socket.io", transports=["websocket"]
+    )
+    response = await client.call(
+        "trigger_method",
+        {
+            "access_path": access_path,
+            "kwargs": {
+                "full_access_path": "",
+                "type": "dict",
+                "value": {
+                    "input_str": {
+                        "docs": None,
+                        "full_access_path": "",
+                        "readonly": False,
+                        "type": "str",
+                        "value": "Hello from function",
+                    },
+                },
+            },
+        },
+    )
+
+    if ok:
+        content = Deserializer.deserialize(response)
+        assert content == expected
+    else:
+        assert response["type"] == "Exception"
+
+    await client.disconnect()
+
+
+@pytest.mark.parametrize(
+    "headers, log_id",
+    [
+        ({}, "sid="),
+        (
+            {
+                "X-Client-Id": "client-header",
+            },
+            "id=client-header",
+        ),
+        (
+            {
+                "Remote-User": "Remote User",
+            },
+            "user=Remote User",
+        ),
+        (
+            {
+                "X-Client-Id": "client-header",
+                "Remote-User": "Remote User",
+            },
+            "user=Remote User",
+        ),
+    ],
+)
+@pytest.mark.asyncio()
+async def test_client_information_logging(
+    headers: dict[str, str],
+    log_id: str,
+    pydase_server: pydase.DataService,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    client = socketio.AsyncClient()
+    await client.connect(
+        "http://localhost:9997",
+        socketio_path="/ws/socket.io",
+        transports=["websocket"],
+        headers=headers,
+    )
+    await client.call("get_value", "readonly_attr")
+
+    assert log_id in caplog.text
+
+    await client.disconnect()