diff --git a/docs/source/public_api.rst b/docs/source/public_api.rst index 3038f3fd..f12d584b 100644 --- a/docs/source/public_api.rst +++ b/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` 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/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..f376f4be 100644 --- a/src/labthings_fastapi/logs.py +++ b/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) 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/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 39d63b48..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 +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. diff --git a/tests/test_action_logging.py b/tests/test_action_logging.py index 4a4f900f..6f32c656 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("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_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..2e129d7c 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(), @@ -302,3 +302,83 @@ 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", + ), + ] + + +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.""" + 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_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 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