diff --git a/src/labthings_fastapi/actions.py b/src/labthings_fastapi/actions.py index 5a4b5f24..edce6395 100644 --- a/src/labthings_fastapi/actions.py +++ b/src/labthings_fastapi/actions.py @@ -44,7 +44,7 @@ from .base_descriptor import BaseDescriptor from .logs import add_thing_log_destination from .utilities import model_to_dict, wrap_plain_types_in_rootmodel -from .invocations import InvocationModel, InvocationStatus, LogRecordModel +from .invocations import InvocationModel, InvocationStatus from .dependencies.invocation import NonWarningInvocationID from .exceptions import ( InvocationCancelledError, @@ -154,7 +154,7 @@ def output(self) -> Any: return self._return_value @property - def log(self) -> list[LogRecordModel]: + def log(self) -> list[logging.LogRecord]: """A list of log items generated by the Action.""" with self._status_lock: return list(self._log) diff --git a/src/labthings_fastapi/invocations.py b/src/labthings_fastapi/invocations.py index 21f156e2..403d1dd5 100644 --- a/src/labthings_fastapi/invocations.py +++ b/src/labthings_fastapi/invocations.py @@ -54,23 +54,26 @@ class LogRecordModel(BaseModel): def generate_message(cls, data: Any) -> Any: """Ensure LogRecord objects have constructed their message. - :param data: The LogRecord to process. + :param data: The LogRecord or serialised log record data to process. :return: The LogRecord, with a message constructed. """ + if not isinstance(data, logging.LogRecord): + return data + if not hasattr(data, "message"): - if isinstance(data, logging.LogRecord): - try: - data.message = data.getMessage() - except (ValueError, TypeError) as e: - # too many args causes an error - but errors - # in validation can be a problem for us: - # it will cause 500 errors when retrieving - # the invocation. - # This way, you can find and fix the source. - data.message = f"Error constructing message ({e}) from {data!r}." - - if data.exc_info: + try: + data.message = data.getMessage() + except (ValueError, TypeError) as e: + # too many args causes an error - but errors + # in validation can be a problem for us: + # it will cause 500 errors when retrieving + # the invocation. + # This way, you can find and fix the source. + data.message = f"Error constructing message ({e}) from {data!r}." + + # Also check data.exc_info[0] as sys.exc_info() can return (None, None, None). + if data.exc_info and data.exc_info[0] is not None: data.exception_type = data.exc_info[0].__name__ data.traceback = "\n".join(traceback.format_exception(*data.exc_info)) diff --git a/src/labthings_fastapi/thing.py b/src/labthings_fastapi/thing.py index 76981998..602fc40c 100644 --- a/src/labthings_fastapi/thing.py +++ b/src/labthings_fastapi/thing.py @@ -30,7 +30,7 @@ from .websockets import websocket_endpoint from .exceptions import PropertyNotObservableError from .thing_server_interface import ThingServerInterface - +from .invocation_contexts import get_invocation_id if TYPE_CHECKING: from .server import ThingServer @@ -383,3 +383,26 @@ def observe_action(self, action_name: str, stream: ObjectSendStream) -> None: raise KeyError(f"{action_name} is not an LabThings Action") observers = action._observers_set(self) observers.add(stream) + + def get_current_invocation_logs(self) -> list[logging.LogRecord]: + """Get the log records for an on going action. + + This is useful if an action wishes to save its logs alongside any data. + + Note that only the last 1000 logs are returned so for long running tasks that + log frequently this may want to be read periodically. + + This will error if it is called outside an action invocation. + + :return: a list of all logs from this action. + + :raises RuntimeError: If the server cannot be retrieved. This should never + happen. + """ + inv_id = get_invocation_id() + server = self._thing_server_interface._server() + if server is None: + raise RuntimeError("Could not get server from thing_server_interface") + action_manager = server.action_manager + this_invocation = action_manager.get_invocation(inv_id) + return this_invocation.log diff --git a/tests/test_logs.py b/tests/test_logs.py index 0e00f6cf..45af9d46 100644 --- a/tests/test_logs.py +++ b/tests/test_logs.py @@ -10,7 +10,9 @@ from types import EllipsisType import pytest from uuid import UUID, uuid4 +from fastapi.testclient import TestClient from labthings_fastapi import logs +from labthings_fastapi.invocations import LogRecordModel from labthings_fastapi.invocation_contexts import ( fake_invocation_context, set_invocation_id, @@ -19,6 +21,8 @@ from labthings_fastapi.exceptions import LogConfigurationError from labthings_fastapi.testing import create_thing_without_server +from .temp_client import poll_task + class ThingThatLogs(lt.Thing): @lt.action @@ -26,6 +30,20 @@ def log_a_message(self, msg: str): """Log a message to the thing's logger.""" self.logger.info(msg) + @lt.action + def log_and_capture(self, msg: str) -> str: + """Log a message to the thing's logger and retrieve it as a string.""" + self.logger.info(msg) + self.logger.warning(msg) + self.logger.error(msg) + logs = self.get_current_invocation_logs() + logging_str = "" + for record in logs: + level = record.levelname + msg = record.getMessage() + logging_str += f"[{level}] {msg}\n" + return logging_str + def reset_thing_logger(): """Remove all handlers from the THING_LOGGER to reset it.""" @@ -176,3 +194,38 @@ def test_add_thing_log_destination(): thing.log_a_message("Test Message.") assert len(dest) == 1 assert dest[0].getMessage() == "Test Message." + + +def _call_action_can_get_logs(): + """Run `log_and_capture` as an action, Return the final HTTP response.""" + server = lt.ThingServer({"logging_thing": ThingThatLogs}) + with TestClient(server.app) as client: + response = client.post("/logging_thing/log_and_capture", json={"msg": "foobar"}) + response.raise_for_status() + return poll_task(client, response.json()) + + +def test_action_can_get_logs(): + """Check that an action can get a copy of its own logs.""" + invocation = _call_action_can_get_logs() + assert invocation["status"] == "completed" + # Check the logs are returned by the action itself. + expected_message = "[INFO] foobar\n[WARNING] foobar\n[ERROR] foobar\n" + assert invocation["output"] == expected_message + + +def test_action_logs_over_http(): + """Check that the action logs are sent over HTTP in JSON.""" + invocation = _call_action_can_get_logs() + logs = invocation["log"] + assert isinstance(logs, list) + assert len(logs) == 3 + assert logs[0]["levelname"] == "INFO" + assert logs[0]["levelno"] == 20 + assert logs[1]["levelname"] == "WARNING" + assert logs[1]["levelno"] == 30 + assert logs[2]["levelname"] == "ERROR" + assert logs[2]["levelno"] == 40 + for log in logs: + log_as_model = LogRecordModel(**log) + assert log_as_model.message == "foobar"