Logging improvements

docs/source/public_api.rst

@@ -401,10 +401,24 @@ This page summarises the parts of the LabThings API that should be most frequent
    .. autoattribute:: labthings_fastapi.server.config_model.ThingServerConfig.enable_global_lock
         :no-index:
 
+   .. autoattribute:: labthings_fastapi.server.config_model.ThingServerConfig.global_lock_log_level
+        :no-index:
+
    .. autoattribute:: labthings_fastapi.server.config_model.ThingServerConfig.application_config
         :no-index:
 
 
+.. py:function:: get_thing_logger(thing_name: str | None = None) -> logging.Logger
+
+    Return the parent logger of all the `~lt.Thing.logger` instances, or a child of it.
+
+    This logger is where invocation logs are collected, so if you are writing code that
+    is not part of a `~lt.Thing` but still wants to show up in the log associated with
+    a particular invocation, you should create a child of this logger.
+
+    :param thing_name: if supplied, a child logger will be created using this name.
+
+
 .. py:class:: ThingClient
 
    A client for a LabThings-FastAPI Thing, alias of `labthings_fastapi.client.ThingClient`

src/labthings_fastapi/__init__.py

@@ -33,6 +33,7 @@
     cancellable_sleep,
     raise_if_cancelled,
 )
+from labthings_fastapi.logs import get_thing_logger
 from labthings_fastapi.outputs import blob
 from labthings_fastapi.properties import DataProperty, DataSetting, property, setting
 from labthings_fastapi.server import ThingServer, cli
@@ -64,6 +65,7 @@
     "cancellable_sleep",
     "cli",
     "endpoint",
+    "get_thing_logger",
     "outputs",
     "property",
     "raise_if_cancelled",

src/labthings_fastapi/actions.py

@@ -389,8 +389,13 @@
                     and self._status == InvocationStatus.PENDING
                 ):
                     # The global lock timed out before the function started.
-                    # In this case, don't print a traceback.
-                    logger.warning(f"Global lock was busy: didn't run {action.name}.")
+                    # In this case, don't print a traceback, and log at the level.
+                    # specified by the server.
+                    server = thing._thing_server_interface._get_server()
+                    logger.log(
+                        server.global_lock_log_level,
+                        f"Global lock was busy: didn't run {action.name}.",
+                    )
                 else:
                     # Other exceptions show up in the log with a traceback
                     logger.exception(e)
@@ -590,8 +595,8 @@
             with self._invocations_lock:
                 try:
                     invocation: Any = self._invocations[id]
                 except KeyError as e:
                     raise HTTPException(
                         status_code=404,
                         detail="No action invocation found with ID {id}",
                     ) from e
@@ -604,7 +609,7 @@
                     invocation.output.response
                 ):
                     # TODO: honour "accept" header
                     return invocation.output.response()
                 try:
                     return serialise_from_user_code(
                         model_instance=invocation.output_model_instance,
@@ -640,8 +645,8 @@
             with self._invocations_lock:
                 try:
                     invocation: Any = self._invocations[id]
                 except KeyError as e:
                     raise HTTPException(
                         status_code=404,
                         detail="No action invocation found with ID {id}",
                     ) from e
@@ -836,7 +841,7 @@
         """
         super().__set_name__(owner, name)
         if self.name != self.func.__name__:
             raise ValueError(
                 f"Action name '{self.name}' does not match function name "
                 f"'{self.func.__name__}'",
             )
@@ -947,9 +952,9 @@
                     status_code=201,
                     code=self.func,
                 )
             except InvalidReturnValueError as e:
                 thing.logger.error(e)
                 raise HTTPException(status_code=500, detail=str(e)) from e
 
         if issubclass(self.input_model, EmptyInput):
             annotation = Body(default_factory=StrictEmptyInput)
@@ -980,14 +985,14 @@
         try:
             responses[200]["model"] = self.output_model
             pass
         except AttributeError:
             print(f"Failed to generate response model for action {self.name}")
         # Add an additional media type if we may return a file
         if hasattr(self.output_model, "media_type"):
             responses[200]["content"][self.output_model.media_type] = {}
         # Now we can add the endpoint to the app.
         if thing.path is None:
             raise NotConnectedToServerError(
                 "Can't add the endpoint without thing.path!"
             )
         app.post(
@@ -1035,7 +1040,7 @@
         """
         path = path or thing.path
         if path is None:
             raise NotConnectedToServerError("Can't generate forms without a path!")
         forms = [
             Form[ActionOp](href=path + self.name, op=[ActionOp.invokeaction]),
         ]

src/labthings_fastapi/logs.py

@@ -2,19 +2,98 @@
 
 This module currently contains code that allows us to filter out logs by invocaton
 ID, so that they may be returned when invocations are queried.
+
+It also defines the `USER` loglevel, which should be used for messages that are
+intended to be visible to the user in e.g. a graphical interface.
 """
 
 import logging
 from collections.abc import MutableSequence
+from typing import TYPE_CHECKING, Any
 from uuid import UUID
 from weakref import WeakValueDictionary
 
 from labthings_fastapi.exceptions import LogConfigurationError, NoInvocationContextError
 from labthings_fastapi.invocation_contexts import get_invocation_id
 
+# Add the custom USER loglevel.
+USER = logging.INFO + 5
+logging.addLevelName(USER, "USER")
+
+
+# This allows mypy to work with a dynamic base class.
+# logging.getLoggerClass() should always return a subclass of logging.Logger
+# (and will usually return logging.Logger).
+# Using this dynamic base class means we're much less likely to break
+# customisations done to the logger by other code.
+if TYPE_CHECKING:
+    Logger = logging.Logger
+else:
+    Logger = logging.getLoggerClass()
+
+
+class LoggerWithUser(Logger):
+    """A subclass of `logging.Logger` with an extra `user` level."""
+
+    def user(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        r"""Log 'msg % args' with severity 'INFO'.
+
+        To pass exception information, use the keyword argument exc_info with
+        a true value, e.g.
+
+        .. code-block:: python
+
+            logger.info("Houston, we have a %s", "interesting problem", exc_info=1)
+
+        :param msg: The message to log, including `%` placeholders if desired.
+        :param \*args: Additional arguments can be used to customise ``msg``\ .
+        :param \**kwargs: Keyword arguments may be used to customise ``msg``\ .
+        """
+        if self.isEnabledFor(USER):
+            self._log(USER, msg, args, **kwargs)
+
+
+# We tell `logging` to use our new class, so `user` is available to all
+# loggers obtained with `logging.getLogger`
+# We do this before defining THING_LOGGER so that it gets the new level
+logging.setLoggerClass(LoggerWithUser)
+
+
+# Note that this is done **after** defining the new level, so that it's
+# of the correct class.
 THING_LOGGER = logging.getLogger("labthings_fastapi.things")
 
 
+def get_thing_logger(thing_name: str | None = None) -> LoggerWithUser:
+    r"""Return the Thing Logger, or a child logger.
+
+    `lt.Thing.logger` will return a child of this logger, and any messages
+    logged to this logger will be picked up by invocation logs, if they are
+    logged from an invocation thread/context.
+
+    :param thing_name: the name of a `lt.Thing`\ . If supplied, we will get a child
+        logger (i.e. ``labthings_fastapi.things.{thing_name}``). By default,
+        the root Thing logger (``labthings_fastapi.things``) is returned.
+    :return: the parent logger of all the `lt.Thing.logger` instances.
+    :raises TypeError: if the logger is missing the ``user`` level.
+    """
+    if thing_name:
+        logger = THING_LOGGER.getChild(thing_name)
+    else:
+        logger = THING_LOGGER
+    if not isinstance(logger, LoggerWithUser):
+        msg = (
+            "Customisations to the logger class have been lost. "
+            "This probably means that `logging.setLoggerClass()` has been "
+            "called, and the new class was not a subclass of the old one. \n\n"
+            "To customise the logger without breaking the `USER` level added "
+            "by LabThings, you should call `logging.getLoggerClass()` and "
+            "subclass it when creating a new logger class."
+        )
+        raise TypeError(msg)
+    return logger
+
+
 def inject_invocation_id(record: logging.LogRecord) -> bool:
     r"""Add the invocation ID to records.
 
@@ -39,7 +118,7 @@ class DequeByInvocationIDHandler(logging.Handler):
 
     def __init__(
         self,
-        level: int = logging.INFO,
+        level: int = logging.NOTSET,
     ) -> None:
         """Set up a log handler that appends messages to a deque.
 
@@ -48,8 +127,10 @@ def __init__(
             the list. It's best to use a `deque` with a finite capacity
             to avoid memory leaks.
 
-        :param level: sets the level of the logger. For most invocations,
-            a log level of `logging.INFO` is appropriate.
+        :param level: sets the level of the handler. Usually
+            a log level of `logging.NOTSET` is appropriate. This does not
+            do any extra filtering, and so will use the log level of the
+            logger to which it is attached.
         """
         super().__init__()
         self.setLevel(level)

src/labthings_fastapi/server/__init__.py

@@ -258,7 +258,7 @@
         async def serialisation_error_handler(
             request: Request, exc: PydanticSerializationError
         ) -> JSONResponse:
             LOGGER.error(
                 f"Couldn't serialise response to {request.url} because of error: \n"
                 f"{exc}"
             )
@@ -307,6 +307,14 @@
         """
         return self._config.api_prefix
 
+    @property
+    def global_lock_log_level(self) -> int:
+        """The level at which to log when the global lock is busy."""
+        # Note that the config entry below is validated by the config
+        # model, to be one of DEBUG, INFO, WARNING or ERROR.
+        levelname = self._config.global_lock_log_level
+        return getattr(logging, levelname)
+
     ThingInstance = TypeVar("ThingInstance", bound=Thing)
 
     def things_by_class(self, cls: type[ThingInstance]) -> Sequence[ThingInstance]:

src/labthings_fastapi/server/config_model.py

@@ -8,7 +8,7 @@
 """
 
 from collections.abc import Iterable, Mapping, Sequence
-from typing import Annotated, Any, TypeAlias
+from typing import Annotated, Any, Literal, TypeAlias
 
 from pydantic import (
     AfterValidator,
@@ -236,6 +236,14 @@ def thing_configs(self) -> Mapping[ThingName, ThingConfig]:
         ),
     )
 
+    global_lock_log_level: Literal["DEBUG", "INFO", "WARNING", "ERROR"] = Field(
+        default="INFO",
+        description=(
+            "The log level to use when an action can't start due to the global lock "
+            "being busy."
+        ),
+    )
+
     application_config: dict[str, Any] | None = Field(
         default=None,
         description=(

src/labthings_fastapi/testing.py

@@ -174,6 +174,7 @@ def create_thing_without_server(
     settings_folder: str | None = None,
     mock_all_slots: bool = False,
     enable_global_lock: bool = True,
+    name: str | None = None,
     **kwargs: Any,
 ) -> ThingSubclass:
     r"""Create a `~lt.Thing` and supply a mock ThingServerInterface.
@@ -193,6 +194,7 @@ def create_thing_without_server(
         to the slot. So if an optional slot has a default of `None`, no mock
         will be provided.
     :param enable_global_lock: Whether a global lock should be provided.
+    :param name: Optionally specify the name of the created `~lt.Thing` .
     :param \**kwargs: keyword arguments to ``__init__``.
 
     :returns: an instance of ``cls`` with a `.MockThingServerInterface`
@@ -201,7 +203,7 @@ def create_thing_without_server(
     :raises ValueError: if a keyword argument called 'thing_server_interface'
         is supplied, as this would conflict with the mock interface.
     """
-    name = cls.__name__.lower()
+    name = name or cls.__name__.lower()
     if "thing_server_interface" in kwargs:
         msg = "You may not supply a keyword argument called 'thing_server_interface'."
         raise ValueError(msg)

src/labthings_fastapi/thing.py

@@ -23,7 +23,7 @@
 from labthings_fastapi.actions import ActionCollection
 from labthings_fastapi.base_descriptor import OptionallyBoundDescriptor
 from labthings_fastapi.invocation_contexts import get_invocation_id
-from labthings_fastapi.logs import THING_LOGGER
+from labthings_fastapi.logs import LoggerWithUser, get_thing_logger
 from labthings_fastapi.properties import (
     PropertyCollection,
     SettingCollection,
@@ -143,9 +143,18 @@ def name(self) -> str:
         return self._thing_server_interface.name
 
     @property
-    def logger(self) -> logging.Logger:
-        """A logger, named after this Thing."""
-        return THING_LOGGER.getChild(self.name)
+    def logger(self) -> LoggerWithUser:
+        r"""A logger, named after this Thing.
+
+        This logger will have an extra ``user`` method, which logs at a level
+        called ``USER`` in between ``INFO`` and ``WARNING``\ .
+
+        LabThings will handle messages logged to this logger, including relaying
+        them to clients over the network.
+
+        This logger will be obtained with `~lt.get_thing_logger`\ .
+        """
+        return get_thing_logger(self.name)
 
     async def __aenter__(self) -> Self:
         """Context management is used to set up/close the thing.

tests/test_action_logging.py

@@ -12,6 +12,12 @@
 from tests.temp_client import poll_task
 
 
+def log_externally():
+    """A function that should show up in invocation logs."""
+    logger = lt.get_thing_logger("external")
+    logger.user("Take me to your user.")
+
+
 class ThingThatLogsAndErrors(lt.Thing):
     LOG_MESSAGES = [
         "message 1",
@@ -31,6 +37,11 @@ def action_with_unhandled_error(self):
     def action_with_invocation_error(self):
         raise lt.exceptions.InvocationError("This is an error, but I handled it!")
 
+    @lt.action
+    def action_that_logs_externally(self):
+        """This action calls code that uses `lt.get_thing_logger` to log."""
+        log_externally()
+
 
 @pytest.fixture
 def client():
@@ -56,6 +67,20 @@ def test_invocation_logging(caplog, client):
             assert entry["message"] == expected
 
 
+def test_external_invocaton_logging(caplog, client):
+    """Check that `lt.get_thing_logger` is picked up in invocation logs."""
+    with caplog.at_level(logging.INFO, logger=THING_LOGGER.name):
+        r = client.post("/log_and_error_thing/action_that_logs_externally")
+        r.raise_for_status()
+        invocation = poll_task(client, r.json())
+        assert invocation["status"] == "completed"
+        assert len(caplog.records) == 1
+        assert len(invocation["log"]) == 1
+        # The message should be picked up, even though it's not from
+        # `log_and_error_thing.logger`
+        assert invocation["log"][0]["message"] == "Take me to your user."
+
+
 def test_unhandled_error_logs(caplog, client):
     """Check that a log with a traceback is raised if there is an unhandled error."""
     with caplog.at_level(logging.INFO, logger=THING_LOGGER.name):

tests/test_global_lock.py

@@ -481,10 +481,14 @@ def test_reuse_of_action_callables():
             func()
 
 
-def test_global_lock_log(caplog):
+@pytest.mark.parametrize("loglevel", ["DEBUG", "INFO", "WARNING", "ERROR"])
+def test_global_lock_log(caplog, loglevel):
     """Test that we get sensible errors when the lock is busy."""
     server = lt.ThingServer.from_things(
-        {"checker": ConcurrencyChecker}, enable_global_lock=True
+        {"checker": ConcurrencyChecker},
+        enable_global_lock=True,
+        global_lock_log_level=loglevel,
+        debug=(loglevel == "DEBUG"),
     )
     with server.test_client() as client:
         checker = lt.ThingClient.from_url("/checker/", client=client)
@@ -501,7 +505,7 @@ def test_global_lock_log(caplog):
                 checker.increment_fprop2()
             matches = [r for r in caplog.records if "Global lock was busy" in r.message]
             assert len(matches) == 1
-            assert matches[0].levelno == logging.WARNING
+            assert matches[0].levelno == getattr(logging, loglevel)
             assert "Traceback" not in caplog.text
 
             # Next, try the same thing with an action that does