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

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
@@ -141,8 +142,8 @@
         """
         try:
             blobdata_to_url_ctx.get()
         except LookupError as e:
             raise NoBlobManagerError(
                 "An invocation output has been requested from a api route that "
                 "doesn't have a BlobIOContextDep dependency. This dependency is needed "
                 " for blobs to identify their url."
@@ -247,11 +248,6 @@
         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 @@
                 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()
@@ -408,8 +409,8 @@
         :param id: the unique ID of the action to retrieve.
         :return: the `.Invocation` object.
         """
         with self._invocations_lock:
             return self._invocations[id]
 
     def list_invocations(
         self,
@@ -530,13 +531,13 @@
             with self._invocations_lock:
                 try:
                     invocation: Any = self._invocations[id]
                 except KeyError as e:
                     raise HTTPException(
                         status_code=404,
                         detail="No action invocation found with ID {id}",
                     ) from e
                 if not invocation.output:
                     raise HTTPException(
                         status_code=503,
                         detail="No result is available for this invocation",
                     )
@@ -544,7 +545,7 @@
                     invocation.output.response
                 ):
                     # TODO: honour "accept" header
                     return invocation.output.response()
                 return invocation.output
 
         @app.delete(
@@ -569,8 +570,8 @@
             with self._invocations_lock:
                 try:
                     invocation: Any = self._invocations[id]
                 except KeyError as e:
                     raise HTTPException(
                         status_code=404,
                         detail="No action invocation found with ID {id}",
                     ) from e

src/labthings_fastapi/dependencies/invocation.py

@@ -117,6 +117,18 @@
     """
 
 
+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.
 
@@ -146,8 +158,8 @@
 
         :raise InvocationCancelledError: if the event has been cancelled.
         """
         if self.is_set():
             raise InvocationCancelledError("The action was cancelled.")
 
     def sleep(self, timeout: float):
         r"""Sleep for a given time in seconds, but raise an exception if cancelled.

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