From 1f4304fed896015d674ec5ec47562a00aaf0517b Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Tue, 16 Jun 2026 12:32:31 +0100 Subject: [PATCH 1/3] Make the global lock log at a specified level When an action can't start because the global lock is busy, it used to log at level `WARNING`. This is now configurable. I'm not massively in love with the way this is done, but it works. There's one issue I need to fix, which is that if you set the loglevel to `DEBUG` and the server isn't in debug mode, it's not possible to find out from the client what happened, i.e. the error is simply "unknown". Along the way, I found that the handler that provides logs for each invocation was set to use `INFO` level, even if debug logging was enabled on the server. I've now removed the level, so that it will respect whatever the server's been set to. --- docs/source/public_api.rst | 3 +++ src/labthings_fastapi/actions.py | 9 +++++++-- src/labthings_fastapi/logs.py | 8 +++++--- src/labthings_fastapi/server/__init__.py | 8 ++++++++ src/labthings_fastapi/server/config_model.py | 10 +++++++++- tests/test_global_lock.py | 10 +++++++--- tests/test_logs.py | 2 +- 7 files changed, 40 insertions(+), 10 deletions(-) diff --git a/docs/source/public_api.rst b/docs/source/public_api.rst index 3038f3fd..f5734650 100644 --- a/docs/source/public_api.rst +++ b/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: diff --git a/src/labthings_fastapi/actions.py b/src/labthings_fastapi/actions.py index 35806e8d..bf1bad45 100644 --- a/src/labthings_fastapi/actions.py +++ b/src/labthings_fastapi/actions.py @@ -389,8 +389,13 @@ def run(self) -> None: 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) diff --git a/src/labthings_fastapi/logs.py b/src/labthings_fastapi/logs.py index 865247ac..090e968d 100644 --- a/src/labthings_fastapi/logs.py +++ b/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) diff --git a/src/labthings_fastapi/server/__init__.py b/src/labthings_fastapi/server/__init__.py index f29991a3..5d336198 100644 --- a/src/labthings_fastapi/server/__init__.py +++ b/src/labthings_fastapi/server/__init__.py @@ -307,6 +307,14 @@ def api_prefix(self) -> str: """ 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]: diff --git a/src/labthings_fastapi/server/config_model.py b/src/labthings_fastapi/server/config_model.py index a95b790d..abf05fce 100644 --- a/src/labthings_fastapi/server/config_model.py +++ b/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="DEBUG", + 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=( diff --git a/tests/test_global_lock.py b/tests/test_global_lock.py index 416a2cc4..ec2931e7 100644 --- a/tests/test_global_lock.py +++ b/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 diff --git a/tests/test_logs.py b/tests/test_logs.py index a3e5ed53..366342db 100644 --- a/tests/test_logs.py +++ b/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(), From d022155919a27e5d8f99323a35987787c7ef5d95 Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Mon, 29 Jun 2026 13:17:23 +0100 Subject: [PATCH 2/3] Log global lock errors at INFO by default. This ensures that code prior to !370 doesn't give an unknown error by default. --- src/labthings_fastapi/server/config_model.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/labthings_fastapi/server/config_model.py b/src/labthings_fastapi/server/config_model.py index abf05fce..c0ff491b 100644 --- a/src/labthings_fastapi/server/config_model.py +++ b/src/labthings_fastapi/server/config_model.py @@ -237,7 +237,7 @@ def thing_configs(self) -> Mapping[ThingName, ThingConfig]: ) global_lock_log_level: Literal["DEBUG", "INFO", "WARNING", "ERROR"] = Field( - default="DEBUG", + default="INFO", description=( "The log level to use when an action can't start due to the global lock " "being busy." From 6506961c8130c2cbd245751e8728a8eb8ab75eee Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Tue, 4 Aug 2026 18:31:58 +0100 Subject: [PATCH 3/3] Improve tests to handle DEBUG case better The tests now verify that the client will get the right error, even if the global lock is set not to show failures in the log. --- tests/test_global_lock.py | 37 ++++++++++++++++++++++++++++--------- 1 file changed, 28 insertions(+), 9 deletions(-) diff --git a/tests/test_global_lock.py b/tests/test_global_lock.py index ec2931e7..15c99e9e 100644 --- a/tests/test_global_lock.py +++ b/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( @@ -482,13 +482,29 @@ def test_reuse_of_action_callables(): @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.""" +@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, global_lock_log_level=loglevel, - debug=(loglevel == "DEBUG"), + debug=debug, ) with server.test_client() as client: checker = lt.ThingClient.from_url("/checker/", client=client) @@ -504,9 +520,12 @@ def test_global_lock_log(caplog, loglevel): ): 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 == getattr(logging, loglevel) - 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