Configurable global lock log level

docs/source/public_api.rst

@@ -401,6 +401,9 @@ 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:
 

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

@@ -39,7 +39,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 +48,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=(

tests/test_global_lock.py

@@ -1,7 +1,7 @@
 """Test code for the global lock."""
 
 import logging
-from collections.abc import Iterator
+from collections.abc import Generator
 from contextlib import contextmanager
 from threading import Event, Thread
 
@@ -183,7 +183,7 @@ def assert_changes(thing: ConcurrencyChecker):
 
 
 @contextmanager
-def assert_fails(thing: ConcurrencyChecker) -> Iterator[None]:
+def assert_fails(thing: ConcurrencyChecker) -> Generator[None]:
     """Assert that the code in a with block fails with an error.
 
     Currently, this will look for several exceptions, so that it works on both client
@@ -199,7 +199,7 @@ def assert_fails(thing: ConcurrencyChecker) -> Iterator[None]:
 
 
 @contextmanager
-def monitor_for_changes(thing: ConcurrencyChecker, hold_lock: bool) -> Iterator[None]:
+def monitor_for_changes(thing: ConcurrencyChecker, hold_lock: bool) -> Generator[None]:
     """Monitor for changes in a background thread"""
     # Start the background action that checks for changes.
     monitor_thread = Thread(
@@ -481,10 +481,30 @@ def test_reuse_of_action_callables():
             func()
 
 
-def test_global_lock_log(caplog):
-    """Test that we get sensible errors when the lock is busy."""
+@pytest.mark.parametrize("loglevel", ["DEBUG", "INFO", "WARNING", "ERROR"])
+@pytest.mark.parametrize("debug", [True, False])
+def test_global_lock_log(caplog, debug, loglevel):
+    """Test that we get sensible errors when the lock is busy.
+
+    This performs tests with and without DEBUG mode - if the lock is set to
+    log at DEBUG level and the server isn't configured to propagate DEBUG
+    logs, we don't expect anything to show up.
+
+    In that case, we do still want to check that the client raises the right
+    error: the lock error should be reported to the client even if it's not
+    logged.
+
+    We check that:
+    1. The client is informed that the global lock was busy (and thus it
+        raises a `GlobalLockBusyError`).
+    2. The lock error is recorded in the log, at the specified level, if
+        appropriate (i.e. DEBUG logs shouldn't show up if debug is False).
+    """
     server = lt.ThingServer.from_things(
-        {"checker": ConcurrencyChecker}, enable_global_lock=True
+        {"checker": ConcurrencyChecker},
+        enable_global_lock=True,
+        global_lock_log_level=loglevel,
+        debug=debug,
     )
     with server.test_client() as client:
         checker = lt.ThingClient.from_url("/checker/", client=client)
@@ -500,9 +520,12 @@ 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 "Traceback" not in caplog.text
+            if loglevel == "DEBUG" and debug is False:
+                assert len(matches) == 0
+            else:
+                assert len(matches) == 1
+                assert matches[0].levelno == getattr(logging, loglevel)
+                assert "Traceback" not in caplog.text
 
             # Next, try the same thing with an action that does
             # not hold the global lock, but calls a property that

tests/test_logs.py

@@ -130,7 +130,7 @@ def test_inject_invocation_id_withcontext():
 def test_dequebyinvocationidhandler():
     """Check the custom log handler works as expected."""
     handler = logs.DequeByInvocationIDHandler()
-    assert handler.level == logging.INFO
+    assert handler.level == logging.NOTSET
 
     destinations = {
         uuid4(): deque(),