From 96bbdf1fbd18f303e9dff89677b3dd35b3f6d5f0 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Sun, 27 Jul 2025 23:45:39 +0100 Subject: [PATCH 1/7] Add InvocationError for an error without traceback. Alog cancel at info. --- src/labthings_fastapi/actions/__init__.py | 9 ++++++++- src/labthings_fastapi/dependencies/invocation.py | 14 ++++++++++++++ src/labthings_fastapi/exceptions.py | 1 + 3 files changed, 23 insertions(+), 1 deletion(-) diff --git a/src/labthings_fastapi/actions/__init__.py b/src/labthings_fastapi/actions/__init__.py index 56e251fa..0a50a156 100644 --- a/src/labthings_fastapi/actions/__init__.py +++ b/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 @@ -280,10 +281,16 @@ 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 InvocationError as e: + logger.error(e) + with self._status_lock: + self._status = InvocationStatus.ERROR + self._exception = e + self.action.emit_changed_event(self.thing, self._status) except Exception as e: # skipcq: PYL-W0703 logger.exception(e) with self._status_lock: diff --git a/src/labthings_fastapi/dependencies/invocation.py b/src/labthings_fastapi/dependencies/invocation.py index 000d55af..f8cf634d 100644 --- a/src/labthings_fastapi/dependencies/invocation.py +++ b/src/labthings_fastapi/dependencies/invocation.py @@ -117,6 +117,20 @@ 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. + + Unlike other types of unhandled error in a LabThings action this will not cause + ASGI traceback. The ASGI traceback provides useful debug information to be logged + for developers. However, for simple errors with known causes this is information + overload for an average user. + """ + + class CancelEvent(threading.Event): """An Event subclass that enables cancellation of actions. diff --git a/src/labthings_fastapi/exceptions.py b/src/labthings_fastapi/exceptions.py index 1a6a03cd..e9088841 100644 --- a/src/labthings_fastapi/exceptions.py +++ b/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): From c6583b8c3f9a9406e50482a1a068c1304e5b78a6 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Wed, 13 Aug 2025 12:16:09 +0100 Subject: [PATCH 2/7] Remove reraise of caught exeption in action as it has been logged and status set --- src/labthings_fastapi/actions/__init__.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/labthings_fastapi/actions/__init__.py b/src/labthings_fastapi/actions/__init__.py index 0a50a156..3c066a7a 100644 --- a/src/labthings_fastapi/actions/__init__.py +++ b/src/labthings_fastapi/actions/__init__.py @@ -297,7 +297,6 @@ def run(self) -> None: 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() From 2dd910025a781236c868e9506e2dcd2148db1094 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Wed, 13 Aug 2025 12:30:49 +0100 Subject: [PATCH 3/7] Improve docstring for InvocationError --- src/labthings_fastapi/dependencies/invocation.py | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/src/labthings_fastapi/dependencies/invocation.py b/src/labthings_fastapi/dependencies/invocation.py index f8cf634d..9777df40 100644 --- a/src/labthings_fastapi/dependencies/invocation.py +++ b/src/labthings_fastapi/dependencies/invocation.py @@ -124,10 +124,8 @@ class InvocationError(RuntimeError): logged at error level without a traceback, and the invocation will return with error status. - Unlike other types of unhandled error in a LabThings action this will not cause - ASGI traceback. The ASGI traceback provides useful debug information to be logged - for developers. However, for simple errors with known causes this is information - overload for an average user. + Subclass this error for errors that do not need further traceback information + to be provided with the error message in logs. """ From cb3575ed471bae807069c55028dae59a510e4505 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Wed, 13 Aug 2025 12:43:54 +0100 Subject: [PATCH 4/7] Remove code duplication --- src/labthings_fastapi/actions/__init__.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/src/labthings_fastapi/actions/__init__.py b/src/labthings_fastapi/actions/__init__.py index 3c066a7a..6a96ef19 100644 --- a/src/labthings_fastapi/actions/__init__.py +++ b/src/labthings_fastapi/actions/__init__.py @@ -285,14 +285,14 @@ def run(self) -> None: with self._status_lock: self._status = InvocationStatus.CANCELLED self.action.emit_changed_event(self.thing, self._status) - except InvocationError as e: - logger.error(e) - with self._status_lock: - self._status = InvocationStatus.ERROR - self._exception = e - 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 From 51e37a4ca3f64ac323d6bf938e9089c42ca1efd7 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Wed, 13 Aug 2025 12:50:00 +0100 Subject: [PATCH 5/7] Add some docs for InvocationError --- docs/source/actions.rst | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/docs/source/actions.rst b/docs/source/actions.rst index b0f834bd..ffad7b54 100644 --- a/docs/source/actions.rst +++ b/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. From fbad976c7f3cd8a81332e1ce1b5bc82728ed6991 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Wed, 13 Aug 2025 13:31:14 +0100 Subject: [PATCH 6/7] Add tests for error logs from actions --- tests/test_action_logging.py | 71 ++++++++++++++++++++++++++++-------- 1 file changed, 56 insertions(+), 15 deletions(-) diff --git a/tests/test_action_logging.py b/tests/test_action_logging.py index c526e574..3231dd4e 100644 --- a/tests/test_action_logging.py +++ b/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(): From b171f44f008d43e5ada045a1b1305887f618575f Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Wed, 13 Aug 2025 14:55:11 +0100 Subject: [PATCH 7/7] Fix out of date docstring --- src/labthings_fastapi/actions/__init__.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/src/labthings_fastapi/actions/__init__.py b/src/labthings_fastapi/actions/__init__.py index 6a96ef19..81e5c738 100644 --- a/src/labthings_fastapi/actions/__init__.py +++ b/src/labthings_fastapi/actions/__init__.py @@ -248,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)