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..c0ff491b 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="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=( diff --git a/tests/test_global_lock.py b/tests/test_global_lock.py index 416a2cc4..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( @@ -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 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(),