From 62aac02d774ca8cb6f8b842b10357eee21cf445d Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Mon, 15 Jun 2026 22:10:39 +0100 Subject: [PATCH 1/8] Add an extra loglevel USER. This also adds a new module-level function get_thing_logger() which returns the THING_LOGGER from the logs module. I've typed both `get_thing_logger` and `Thing.logger` to include the new `user` method - this required some runtime type checks to keep mypy happy. --- docs/source/public_api.rst | 9 ++++++ src/labthings_fastapi/__init__.py | 2 ++ src/labthings_fastapi/logs.py | 53 +++++++++++++++++++++++++++++++ src/labthings_fastapi/thing.py | 15 ++++++--- 4 files changed, 75 insertions(+), 4 deletions(-) diff --git a/docs/source/public_api.rst b/docs/source/public_api.rst index 3038f3fd..bb051945 100644 --- a/docs/source/public_api.rst +++ b/docs/source/public_api.rst @@ -405,6 +405,15 @@ This page summarises the parts of the LabThings API that should be most frequent :no-index: +.. py:function:: get_thing_logger() -> logging.Logger + + Return the parent logger of all the `~lt.Thing.logger` instances. + + 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. + + .. py:class:: ThingClient A client for a LabThings-FastAPI Thing, alias of `labthings_fastapi.client.ThingClient` diff --git a/src/labthings_fastapi/__init__.py b/src/labthings_fastapi/__init__.py index 860b1fba..3dc99adc 100644 --- a/src/labthings_fastapi/__init__.py +++ b/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", diff --git a/src/labthings_fastapi/logs.py b/src/labthings_fastapi/logs.py index 865247ac..eb1b1585 100644 --- a/src/labthings_fastapi/logs.py +++ b/src/labthings_fastapi/logs.py @@ -2,19 +2,72 @@ 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 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") + + +class LoggerWithUser(logging.getLoggerClass()): + """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() -> LoggerWithUser: + """Return the Thing 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. + + :return: the parent logger of all the `lt.Thing.logger` instances. + :raises TypeError: if the logger is missing the ``user`` level. + """ + if not isinstance(THING_LOGGER, LoggerWithUser): + raise TypeError("Customisations to `logging.Logger` have been lost.") + return THING_LOGGER + + def inject_invocation_id(record: logging.LogRecord) -> bool: r"""Add the invocation ID to records. diff --git a/src/labthings_fastapi/thing.py b/src/labthings_fastapi/thing.py index 39d63b48..d3b34959 100644 --- a/src/labthings_fastapi/thing.py +++ b/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 THING_LOGGER, LoggerWithUser from labthings_fastapi.properties import ( PropertyCollection, SettingCollection, @@ -143,9 +143,16 @@ 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. + + :raises TypeError: if the logger is missing the ``user`` method to + log messages at a level between ``INFO`` and ``WARNING``\ . + """ + logger = THING_LOGGER.getChild(self.name) + if not isinstance(logger, LoggerWithUser): + raise TypeError("LabThings custom log level is missing!") + return logger async def __aenter__(self) -> Self: """Context management is used to set up/close the thing. From cae513de4f13b57e2345dc6281d8ca20d7fd36d6 Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Tue, 16 Jun 2026 12:32:31 +0100 Subject: [PATCH 2/8] 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 bb051945..3e9890ae 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 eb1b1585..0a7e8598 100644 --- a/src/labthings_fastapi/logs.py +++ b/src/labthings_fastapi/logs.py @@ -92,7 +92,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. @@ -101,8 +101,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 577ae0faec567daf41b5435325ca06d7e7b959c7 Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Wed, 24 Jun 2026 17:01:46 +0100 Subject: [PATCH 3/8] Fix typing of the modified logger. mypy doesn't understand dynamic base classes. mypy will now treat our modified logger subclass as having a static base class of logging.Logger. This is appropriate: the dynamic base class should always be a subclass of logging.Logger. --- src/labthings_fastapi/logs.py | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) diff --git a/src/labthings_fastapi/logs.py b/src/labthings_fastapi/logs.py index 0a7e8598..47776b4f 100644 --- a/src/labthings_fastapi/logs.py +++ b/src/labthings_fastapi/logs.py @@ -9,7 +9,7 @@ import logging from collections.abc import MutableSequence -from typing import Any +from typing import TYPE_CHECKING, Any from uuid import UUID from weakref import WeakValueDictionary @@ -21,7 +21,18 @@ logging.addLevelName(USER, "USER") -class LoggerWithUser(logging.getLoggerClass()): +# 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: From 5852f0bff83d1399d89c7ebf2ffbdac0c55bcb46 Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Mon, 29 Jun 2026 13:17:23 +0100 Subject: [PATCH 4/8] 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 65f5dd0c43956e9b670a97dc6c51e6f62b51652a Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Mon, 29 Jun 2026 13:44:59 +0100 Subject: [PATCH 5/8] Add more tests. This adds: * A test for the default values of `ThingServerConfig` so we have a double-check of these. * Tests that `Thing.logger` and the root Thing logger both have a `user` function. * Test that `lt.get_thing_logger` works, and shows up in invocation logs. --- tests/test_action_logging.py | 25 +++++++++++++++++++++ tests/test_logs.py | 37 +++++++++++++++++++++++++++++++ tests/test_server_config_model.py | 17 ++++++++++++++ 3 files changed, 79 insertions(+) diff --git a/tests/test_action_logging.py b/tests/test_action_logging.py index 4a4f900f..e0464f50 100644 --- a/tests/test_action_logging.py +++ b/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().getChild("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): diff --git a/tests/test_logs.py b/tests/test_logs.py index 366342db..9e96976a 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -302,3 +302,40 @@ def test_action_logs_over_http(): for log in logs: log_as_model = LogRecordModel(**log) assert log_as_model.message == "foobar" + + +def test_thing_logger_has_user_level(caplog): + """Check `Thing.logger` exposes a `user` function.""" + + class Dummy(lt.Thing): + pass + + server = lt.ThingServer.from_things({"dummy": Dummy}) + dummy = server.things["dummy"] + dummy.logger.user("Test message at USER level") + assert caplog.record_tuples == [ + ( + "labthings_fastapi.things.dummy", + logs.USER, + "Test message at USER level", + ), + ] + + +def test_get_thing_logger(caplog): + """Check `lt.get_thing_logger` works and has a `user` function.""" + logger = lt.get_thing_logger() + logger.user("Test message at USER level") + logger.getChild("child").user("Test message at USER level") + assert caplog.record_tuples == [ + ( + "labthings_fastapi.things", + logs.USER, + "Test message at USER level", + ), + ( + "labthings_fastapi.things.child", + logs.USER, + "Test message at USER level", + ), + ] diff --git a/tests/test_server_config_model.py b/tests/test_server_config_model.py index 837c6b5c..5576eec9 100644 --- a/tests/test_server_config_model.py +++ b/tests/test_server_config_model.py @@ -157,3 +157,20 @@ def test_unimportable_modules(import_string: str, message: str): # If a module is missing, the error should make that clear. # Note that the error message changed with Pydantic 2.13. ThingConfig(cls=import_string) + + +def test_defaults(): + """Check the default values. + + This test is intended as a double-check so that any change in default + values must be made both here and in the config model. + """ + config = ThingServerConfig(things={}) + assert config.things == {} + assert config.api_prefix == "" + assert config.application_config is None + assert config.enable_global_lock is False + assert config.global_lock_log_level == "INFO" + assert config.settings_folder is None + # Check there aren't any fields missing from this test + assert len(ThingServerConfig.model_fields) == 6 From 0c435b560486dc1e96eb14a3c6981ad289e6afe0 Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Mon, 29 Jun 2026 14:17:27 +0100 Subject: [PATCH 6/8] Add a test for the logger type checks. It turns out that it's remarkably hard to break the custom logger. This test goes to some length to do so, in order to ensure we cover the two lines that test it. --- tests/test_logs.py | 50 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 50 insertions(+) diff --git a/tests/test_logs.py b/tests/test_logs.py index 9e96976a..333d6b7d 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -339,3 +339,53 @@ def test_get_thing_logger(caplog): "Test message at USER level", ), ] + + +@pytest.fixture +def reset_custom_logger_class(): + """Undo customisation to the logger class.""" + old_class = logging.getLoggerClass() + logging.setLoggerClass(logging.Logger) # reset logger customisation + try: + yield + finally: + # restore customisation so we don't break future tests + logging.setLoggerClass(old_class) + + +def test_custom_logger_error(mocker, reset_custom_logger_class): + """Check the expected error is raised if logger customisation is broken. + + I can't see how this would happen given we get the logger immediately after + applying the customisation, but the `isinstance` check is helpful for `mypy` + checking, and thus wants to stay (and needs a test). + """ + # check new loggers are now missing `user` + assert "user" not in dir(logging.getLogger("unused_logger_name")) + assert "user" not in dir( + logging.getLogger(f"{logs.THING_LOGGER.name}.unused_logger_name") + ) + # This should not have broken `Thing.logger` because `THING_LOGGER` still has + # the correct class (it was created before we broke things) + thing = create_thing_without_server(ThingThatLogs) + assert "user" in dir(thing.logger) + + # If we really want to break things, + # we also need to mock the thing logger, otherwise it will keep using the + # (correct) customised class. + mocker.patch("labthings_fastapi.logs.THING_LOGGER", logging.getLogger("TEST")) + mocker.patch("labthings_fastapi.thing.THING_LOGGER", logging.getLogger("TEST")) + assert "user" not in dir(logs.THING_LOGGER) + # We should now have broken `lt.get_thing_logger` + with pytest.raises( + TypeError, + match="Customisations to `logging.Logger` have been lost.", + ): + lt.get_thing_logger() + # This should also break `Thing.logger` for new classes + thing2 = create_thing_without_server(ThingThatLogs) + with pytest.raises( + TypeError, + match="LabThings custom log level is missing!", + ): + _ = thing2.logger From ae0955513b75de94fb11fb86ff619a991230b897 Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Wed, 1 Jul 2026 13:01:50 +0100 Subject: [PATCH 7/8] Better errors if logger customisation fails. After much getting confused by the caching in `logging`, I have simplified the code that gets loggers, and now test it appropriately. I think this makes it clear what might go wrong and how to fix it. I think the error that occurs when a logger has the wrong type remains a very unlikely error to see! --- docs/source/public_api.rst | 6 ++- src/labthings_fastapi/logs.py | 25 +++++++++--- src/labthings_fastapi/testing.py | 4 +- src/labthings_fastapi/thing.py | 16 ++++---- tests/test_action_logging.py | 2 +- tests/test_logs.py | 65 ++++++++++++++------------------ 6 files changed, 66 insertions(+), 52 deletions(-) diff --git a/docs/source/public_api.rst b/docs/source/public_api.rst index 3e9890ae..b6143214 100644 --- a/docs/source/public_api.rst +++ b/docs/source/public_api.rst @@ -408,14 +408,16 @@ This page summarises the parts of the LabThings API that should be most frequent :no-index: -.. py:function:: get_thing_logger() -> logging.Logger +.. py:function:: get_thing_logger(thing_name: str) -> logging.Logger - Return the parent logger of all the `~lt.Thing.logger` instances. + 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 diff --git a/src/labthings_fastapi/logs.py b/src/labthings_fastapi/logs.py index 47776b4f..f376f4be 100644 --- a/src/labthings_fastapi/logs.py +++ b/src/labthings_fastapi/logs.py @@ -64,19 +64,34 @@ def user(self, msg: str, *args: Any, **kwargs: Any) -> None: THING_LOGGER = logging.getLogger("labthings_fastapi.things") -def get_thing_logger() -> LoggerWithUser: - """Return the Thing Logger. +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 not isinstance(THING_LOGGER, LoggerWithUser): - raise TypeError("Customisations to `logging.Logger` have been lost.") - return THING_LOGGER + 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: diff --git a/src/labthings_fastapi/testing.py b/src/labthings_fastapi/testing.py index 6dff2882..82add746 100644 --- a/src/labthings_fastapi/testing.py +++ b/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) diff --git a/src/labthings_fastapi/thing.py b/src/labthings_fastapi/thing.py index d3b34959..e7c76ff5 100644 --- a/src/labthings_fastapi/thing.py +++ b/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, LoggerWithUser +from labthings_fastapi.logs import LoggerWithUser, get_thing_logger from labthings_fastapi.properties import ( PropertyCollection, SettingCollection, @@ -146,13 +146,15 @@ def name(self) -> str: def logger(self) -> LoggerWithUser: r"""A logger, named after this Thing. - :raises TypeError: if the logger is missing the ``user`` method to - log messages at a level between ``INFO`` and ``WARNING``\ . + 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`\ . """ - logger = THING_LOGGER.getChild(self.name) - if not isinstance(logger, LoggerWithUser): - raise TypeError("LabThings custom log level is missing!") - return logger + return get_thing_logger(self.name) async def __aenter__(self) -> Self: """Context management is used to set up/close the thing. diff --git a/tests/test_action_logging.py b/tests/test_action_logging.py index e0464f50..6f32c656 100644 --- a/tests/test_action_logging.py +++ b/tests/test_action_logging.py @@ -14,7 +14,7 @@ def log_externally(): """A function that should show up in invocation logs.""" - logger = lt.get_thing_logger().getChild("external") + logger = lt.get_thing_logger("external") logger.user("Take me to your user.") diff --git a/tests/test_logs.py b/tests/test_logs.py index 333d6b7d..2e129d7c 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -341,6 +341,17 @@ def test_get_thing_logger(caplog): ] +def test_custom_logger_class_applied(): + """Check that we do get the custom logger class from `logging.getLogger()` .""" + assert logging.getLoggerClass() is logs.LoggerWithUser + assert isinstance(logging.getLogger("unused2"), logs.LoggerWithUser) + assert "user" in dir(logging.getLogger("unused2")) + assert isinstance(logs.get_thing_logger(), logs.LoggerWithUser) + assert isinstance(logs.get_thing_logger("unused3"), logs.LoggerWithUser) + thing = create_thing_without_server(ThingThatLogs, name="newthing1") + assert isinstance(thing.logger, logs.LoggerWithUser) + + @pytest.fixture def reset_custom_logger_class(): """Undo customisation to the logger class.""" @@ -353,39 +364,21 @@ def reset_custom_logger_class(): logging.setLoggerClass(old_class) -def test_custom_logger_error(mocker, reset_custom_logger_class): - """Check the expected error is raised if logger customisation is broken. - - I can't see how this would happen given we get the logger immediately after - applying the customisation, but the `isinstance` check is helpful for `mypy` - checking, and thus wants to stay (and needs a test). - """ - # check new loggers are now missing `user` - assert "user" not in dir(logging.getLogger("unused_logger_name")) - assert "user" not in dir( - logging.getLogger(f"{logs.THING_LOGGER.name}.unused_logger_name") - ) - # This should not have broken `Thing.logger` because `THING_LOGGER` still has - # the correct class (it was created before we broke things) - thing = create_thing_without_server(ThingThatLogs) - assert "user" in dir(thing.logger) - - # If we really want to break things, - # we also need to mock the thing logger, otherwise it will keep using the - # (correct) customised class. - mocker.patch("labthings_fastapi.logs.THING_LOGGER", logging.getLogger("TEST")) - mocker.patch("labthings_fastapi.thing.THING_LOGGER", logging.getLogger("TEST")) - assert "user" not in dir(logs.THING_LOGGER) - # We should now have broken `lt.get_thing_logger` - with pytest.raises( - TypeError, - match="Customisations to `logging.Logger` have been lost.", - ): - lt.get_thing_logger() - # This should also break `Thing.logger` for new classes - thing2 = create_thing_without_server(ThingThatLogs) - with pytest.raises( - TypeError, - match="LabThings custom log level is missing!", - ): - _ = thing2.logger +def test_logger_class_error(reset_custom_logger_class): + """Check that breaking our logger customisation produces an error.""" + # First, check that the fixture has reset the logger class + assert logging.getLoggerClass() is logging.Logger + assert not isinstance(logging.getLogger("unused4"), logs.LoggerWithUser) + assert "user" not in dir(logging.getLogger("unused4")) + # We won't affect loggers that have already been obtained + assert isinstance(logs.THING_LOGGER, logs.LoggerWithUser) + assert isinstance(logs.get_thing_logger(), logs.LoggerWithUser) + # New loggers will have the wrong type + assert not isinstance(logs.THING_LOGGER.getChild("unused5"), logs.LoggerWithUser) + # This should lead to errors when we call `get_thing_logger` + with pytest.raises(TypeError, match="Customisations to the logger class "): + logs.get_thing_logger("unusedchildname1") + # Those errors should propagate through `Thing.logger` as well + thing = create_thing_without_server(ThingThatLogs, name="newthing2") + with pytest.raises(TypeError, match="Customisations to the logger class "): + _ = thing.logger From b1f8543eec788a391f894165f73f482a1325fadd Mon Sep 17 00:00:00 2001 From: Richard Bowman Date: Mon, 6 Jul 2026 21:33:35 +0100 Subject: [PATCH 8/8] Fix signature in public API docs. --- docs/source/public_api.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/source/public_api.rst b/docs/source/public_api.rst index b6143214..f12d584b 100644 --- a/docs/source/public_api.rst +++ b/docs/source/public_api.rst @@ -408,7 +408,7 @@ This page summarises the parts of the LabThings API that should be most frequent :no-index: -.. py:function:: get_thing_logger(thing_name: str) -> logging.Logger +.. 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.