Merge pull request #282 from labthings/281-configurable-log-levels

Log Level Configuration

Author: julianstirling

src/labthings_fastapi/logs.py

@@ -79,11 +79,11 @@ def emit(self, record: logging.LogRecord) -> None:
                 pass  # If there's no destination for a particular log, ignore it.
 
 
-def configure_thing_logger() -> None:
+def configure_thing_logger(level: int | None = None) -> None:
     """Set up the logger for thing instances.
 
-    We always set the logger for thing instances to level INFO, as this
-    is currently used to relay progress to the client.
+    We always set the logger for thing instances to level INFO by default,
+    as this is currently used to relay progress to the client.
 
     This function will collect logs on a per-invocation
     basis by adding a `.DequeByInvocationIDHandler` to the log. Only one
@@ -93,8 +93,14 @@ def configure_thing_logger() -> None:
     a filter to add invocation ID is not possible. Instead, we attach a filter to
     the handler, which filters all the records that propagate to it (i.e. anything
     that starts with ``labthings_fastapi.things``).
+
+    :param level: the logging level to use. If not specified, we use INFO.
     """
-    THING_LOGGER.setLevel(logging.INFO)
+    if level is not None:
+        THING_LOGGER.setLevel(level)
+    else:
+        THING_LOGGER.setLevel(logging.INFO)
+
     if not any(
         isinstance(h, DequeByInvocationIDHandler) for h in THING_LOGGER.handlers
     ):

src/labthings_fastapi/server/__init__.py

@@ -10,6 +10,7 @@
 from typing import Any, AsyncGenerator, Optional, TypeVar
 from typing_extensions import Self
 import os
+import logging
 
 from fastapi import FastAPI, Request
 from fastapi.middleware.cors import CORSMiddleware
@@ -65,6 +66,7 @@ def __init__(
         things: ThingsConfig,
         settings_folder: Optional[str] = None,
         application_config: Optional[Mapping[str, Any]] = None,
+        debug: bool = False,
     ) -> None:
         r"""Initialise a LabThings server.
 
@@ -85,9 +87,12 @@ def __init__(
             application. This is not processed by LabThings. Each `.Thing` can access
             application. This is not processed by LabThings. Each `.Thing` can access
             this via the Thing-Server interface.
+        :param debug: If ``True``, set the log level for `.Thing` instances to
+                      DEBUG.
         """
         self.startup_failure: dict | None = None
-        configure_thing_logger()  # Note: this is safe to call multiple times.
+        # Note: this is safe to call multiple times.
+        configure_thing_logger(logging.DEBUG if debug else None)
         self._config = ThingServerConfig(
             things=things,
             settings_folder=settings_folder,
@@ -110,15 +115,17 @@ def __init__(
         self._attach_things_to_server()
 
     @classmethod
-    def from_config(cls, config: ThingServerConfig) -> Self:
+    def from_config(cls, config: ThingServerConfig, debug: bool = False) -> Self:
         r"""Create a ThingServer from a configuration model.
 
         This is equivalent to ``ThingServer(**dict(config))``\ .
 
         :param config: The configuration parameters for the server.
+        :param debug: If ``True``, set the log level for `.Thing` instances to
+                      DEBUG.
         :return: A `.ThingServer` configured as per the model.
         """
-        return cls(**dict(config))
+        return cls(**dict(config), debug=debug)
 
     def _set_cors_middleware(self) -> None:
         """Configure the server to allow requests from other origins.

src/labthings_fastapi/server/cli.py

@@ -56,6 +56,11 @@ def get_default_parser() -> ArgumentParser:
         default=5000,
         help="Bind socket to this port. If 0, an available port will be picked.",
     )
+    parser.add_argument(
+        "--debug",
+        action="store_true",
+        help="Enable debug logging.",
+    )
     return parser
 
 
@@ -149,10 +154,11 @@ def serve_from_cli(
         option is not specified.
     """
     args = parse_args(argv)
+
     try:
         config, server = None, None
         config = config_from_args(args)
-        server = ThingServer.from_config(config)
+        server = ThingServer.from_config(config, True if args.debug else False)
         if dry_run:
             return server
         uvicorn.run(server.app, host=args.host, port=args.port)

tests/test_logs.py

@@ -6,6 +6,7 @@
 """
 
 from collections import deque
+import json
 import logging
 from types import EllipsisType
 import pytest
@@ -20,6 +21,7 @@
 import labthings_fastapi as lt
 from labthings_fastapi.exceptions import LogConfigurationError
 from labthings_fastapi.testing import create_thing_without_server
+from labthings_fastapi.server.cli import serve_from_cli
 
 from .temp_client import poll_task
 
@@ -45,6 +47,12 @@ def log_and_capture(self, msg: str) -> str:
         return logging_str
 
 
+class ThingWithDebugInit(lt.Thing):
+    def __init__(self, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+        self.logger.debug("Debug message during __init__")
+
+
 def reset_thing_logger():
     """Remove all handlers from the THING_LOGGER to reset it."""
     logger = logs.THING_LOGGER
@@ -169,6 +177,66 @@ def test_configure_thing_logger():
         assert dest[0].msg == "Test"
 
 
+def test_cli_debug_flag():
+    """
+    Test that using the --debug flag sets the logger level to DEBUG,
+    and that not using it leaves the logger level at INFO.
+    """
+    # Reset logger level to INFO
+    reset_thing_logger()
+
+    # Then configure it
+    logs.configure_thing_logger()
+
+    # Run without --debug
+    # We use dry_run=True to avoid starting uvicorn
+    # We need a dummy config
+    dummy_json = '{"things": {}}'
+    serve_from_cli(["--json", dummy_json], dry_run=True)
+
+    assert logs.THING_LOGGER.level == logging.INFO
+
+    # Run with --debug
+    serve_from_cli(["--json", dummy_json, "--debug"], dry_run=True)
+
+    assert logs.THING_LOGGER.level == logging.DEBUG
+
+    # Reset back to INFO
+    reset_thing_logger()
+
+
+def test_cli_debug_flag_with_thing(caplog):
+    """
+    Test that using the --debug flag allows capturing debug logs during __init__.
+    """
+
+    # Reset logger level to INFO
+    reset_thing_logger()
+
+    # Define a config that uses ThingWithDebugInit
+    # We use the full path to the class so it can be imported by LabThings
+    config_json = json.dumps(
+        {"things": {"my_thing": {"cls": "tests.test_logs.ThingWithDebugInit"}}}
+    )
+
+    # Run without --debug and capture logs
+    with caplog.at_level(logging.DEBUG, logger="labthings_fastapi.things"):
+        serve_from_cli(["--json", config_json], dry_run=True)
+
+    # There are no logs
+    assert len(caplog.messages) == 0
+
+    # Run with --debug and capture logs
+    with caplog.at_level(logging.DEBUG, logger="labthings_fastapi.things"):
+        serve_from_cli(["--json", config_json, "--debug"], dry_run=True)
+
+    # Check that the debug message was captured
+    assert "Debug message during __init__" in caplog.text
+
+    # Reset back to INFO
+    reset_thing_logger()
+
+
 def test_add_thing_log_destination():
     """Check the module-level function to add an invocation log destination."""
     reset_thing_logger()