Merge pull request #260 from labthings/get_logs

Allow an action to get a copy of the logs raised during the action.

Author: julianstirling

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)

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))
 

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

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,13 +21,29 @@
 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
     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"