Merge pull request #157 from labthings/cleaner-logs-for-errors

Add InvocationError for an error without traceback. Log cancel at info.

Author: rwb27

docs/source/actions.rst

@@ -57,3 +57,13 @@ The first is ``self`` (the first positional argument), which is always the
 :ref:`dependencies`, which use annotated type hints to tell LabThings to
 supply resources needed by the action. Most often, this is a way of accessing
 other `.Things` on the same server.
+
+Raising exceptions
+------------------
+If an action raises an unhandled exception, the action will terminate with an Error
+status and LabThings will log the error and the traceback.
+
+In the case where the error has been handled, but the job needs to terminate the action
+should raise an InvocationError (or a error which subclasses this). The message from
+this exceptions will be logged, but the full traceback will not be logged as this error
+has been handled.

src/labthings_fastapi/actions/__init__.py

@@ -33,6 +33,7 @@
 from ..dependencies.invocation import (
     CancelHook,
     InvocationCancelledError,
+    InvocationError,
     invocation_logger,
 )
 from ..outputs.blob import BlobIOContextDep, blobdata_to_url_ctx
@@ -247,11 +248,6 @@ def run(self) -> None:
         stored. The status is then set to ERROR and the thread terminates.
 
         See `.Invocation.status` for status values.
-
-        :raise Exception: any exception raised in the action function will
-            propagate through this method. Usually, this will just cause the
-            thread to terminate after setting ``status`` to ``ERROR`` and
-            saving the exception to ``self._exception``.
         """
         try:
             self.action.emit_changed_event(self.thing, self._status)
@@ -280,17 +276,22 @@ def run(self) -> None:
                 self._status = InvocationStatus.COMPLETED
                 self.action.emit_changed_event(self.thing, self._status)
         except InvocationCancelledError:
-            logger.error(f"Invocation {self.id} was cancelled.")
+            logger.info(f"Invocation {self.id} was cancelled.")
             with self._status_lock:
                 self._status = InvocationStatus.CANCELLED
                 self.action.emit_changed_event(self.thing, self._status)
         except Exception as e:  # skipcq: PYL-W0703
-            logger.exception(e)
+            # First log
+            if isinstance(e, InvocationError):
+                # Log without traceback
+                logger.error(e)
+            else:
+                logger.exception(e)
+            # Then set status
             with self._status_lock:
                 self._status = InvocationStatus.ERROR
                 self._exception = e
                 self.action.emit_changed_event(self.thing, self._status)
-            raise e
         finally:
             with self._status_lock:
                 self._end_time = datetime.datetime.now()

src/labthings_fastapi/dependencies/invocation.py

@@ -117,6 +117,18 @@ class InvocationCancelledError(BaseException):
     """
 
 
+class InvocationError(RuntimeError):
+    """The invocation ended in an anticipated error state.
+
+    When this error is raised, action execution stops as expected. The exception will be
+    logged at error level without a traceback, and the invocation will return with
+    error status.
+
+    Subclass this error for errors that do not need further traceback information
+    to be provided with the error message in logs.
+    """
+
+
 class CancelEvent(threading.Event):
     """An Event subclass that enables cancellation of actions.
 

src/labthings_fastapi/exceptions.py

@@ -7,6 +7,7 @@
 from .dependencies.invocation import (
     InvocationCancelledError as InvocationCancelledError,
 )
+from .dependencies.invocation import InvocationError as InvocationError
 
 
 class NotConnectedToServerError(RuntimeError):

tests/test_action_logging.py

@@ -9,32 +9,73 @@
 from labthings_fastapi.actions.invocation_model import LogRecordModel
 
 
-class ThingOne(lt.Thing):
+class ThingThatLogsAndErrors(lt.Thing):
     LOG_MESSAGES = [
         "message 1",
         "message 2",
     ]
 
     @lt.thing_action
-    def action_one(self, logger: lt.deps.InvocationLogger):
+    def action_that_logs(self, logger: lt.deps.InvocationLogger):
         for m in self.LOG_MESSAGES:
             logger.info(m)
 
+    @lt.thing_action
+    def action_with_unhandled_error(self, logger: lt.deps.InvocationLogger):
+        raise RuntimeError("I was asked to raise this error.")
+
+    @lt.thing_action
+    def action_with_invocation_error(self, logger: lt.deps.InvocationLogger):
+        raise lt.exceptions.InvocationError("This is an error, but I handled it!")
+
 
 def test_invocation_logging(caplog):
-    caplog.set_level(logging.INFO)
-    server = lt.ThingServer()
-    server.add_thing(ThingOne(), "/thing_one")
-    with TestClient(server.app) as client:
-        r = client.post("/thing_one/action_one")
-        r.raise_for_status()
-        invocation = poll_task(client, r.json())
-        assert invocation["status"] == "completed"
-        assert len(invocation["log"]) == len(ThingOne.LOG_MESSAGES)
-        for expected, entry in zip(
-            ThingOne.LOG_MESSAGES, invocation["log"], strict=True
-        ):
-            assert entry["message"] == expected
+    with caplog.at_level(logging.INFO, logger="labthings.action"):
+        server = lt.ThingServer()
+        server.add_thing(ThingThatLogsAndErrors(), "/log_and_error_thing")
+        with TestClient(server.app) as client:
+            r = client.post("/log_and_error_thing/action_that_logs")
+            r.raise_for_status()
+            invocation = poll_task(client, r.json())
+            assert invocation["status"] == "completed"
+            assert len(invocation["log"]) == len(ThingThatLogsAndErrors.LOG_MESSAGES)
+            assert len(invocation["log"]) == len(caplog.records)
+            for expected, entry in zip(
+                ThingThatLogsAndErrors.LOG_MESSAGES, invocation["log"], strict=True
+            ):
+                assert entry["message"] == expected
+
+
+def test_unhandled_error_logs(caplog):
+    """Check that a log with a traceback is raised if there is an unhandled error."""
+    with caplog.at_level(logging.INFO, logger="labthings.action"):
+        server = lt.ThingServer()
+        server.add_thing(ThingThatLogsAndErrors(), "/log_and_error_thing")
+        with TestClient(server.app) as client:
+            r = client.post("/log_and_error_thing/action_with_unhandled_error")
+            r.raise_for_status()
+            invocation = poll_task(client, r.json())
+            assert invocation["status"] == "error"
+            assert len(invocation["log"]) == len(caplog.records) == 1
+            assert caplog.records[0].levelname == "ERROR"
+            # There is a traceback
+            assert caplog.records[0].exc_info is not None
+
+
+def test_invocation_error_logs(caplog):
+    """Check that a log with a traceback is raised if there is an unhandled error."""
+    with caplog.at_level(logging.INFO, logger="labthings.action"):
+        server = lt.ThingServer()
+        server.add_thing(ThingThatLogsAndErrors(), "/log_and_error_thing")
+        with TestClient(server.app) as client:
+            r = client.post("/log_and_error_thing/action_with_invocation_error")
+            r.raise_for_status()
+            invocation = poll_task(client, r.json())
+            assert invocation["status"] == "error"
+            assert len(invocation["log"]) == len(caplog.records) == 1
+            assert caplog.records[0].levelname == "ERROR"
+            # There is not a traceback
+            assert caplog.records[0].exc_info is None
 
 
 def test_logrecordmodel():