From fbdea68ab7fc6f2a753896fff387d79fa7df237a Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Fri, 20 Feb 2026 16:03:08 +0000 Subject: [PATCH 1/6] Capture logs when scanning --- .../scan_directories.py | 21 ++++++- .../things/smart_scan.py | 6 ++ .../utilities.py | 56 +++++++++++++++++++ 3 files changed, 82 insertions(+), 1 deletion(-) diff --git a/src/openflexure_microscope_server/scan_directories.py b/src/openflexure_microscope_server/scan_directories.py index ac3c30b5..295c36dd 100644 --- a/src/openflexure_microscope_server/scan_directories.py +++ b/src/openflexure_microscope_server/scan_directories.py @@ -19,10 +19,15 @@ from pydantic import ( model_validator, ) +import labthings_fastapi as lt from labthings_fastapi.exceptions import InvocationError from openflexure_microscope_server.stitching import StitchingSettings -from openflexure_microscope_server.utilities import make_name_safe, requires_lock +from openflexure_microscope_server.utilities import ( + make_name_safe, + requires_lock, + save_invocation_logs, +) LOGGER = logging.getLogger(__name__) @@ -446,6 +451,7 @@ class ScanDirectory: :param name: the name of the scan (the scan directory basename). :param base_scan_dir: Path of the directory that holds all scans. """ + self._log_saved_at = 0.0 self._name = name self._base_scan_dir = base_scan_dir if not os.path.isdir(self.dir_path): @@ -625,6 +631,19 @@ class ScanDirectory: with open(self.scan_data_path, "w", encoding="utf-8") as f: f.write(scan_data.model_dump_json(indent=4)) + def save_scan_log(self, thing: lt.Thing) -> None: + """Save the scan log to file. + + :param thing: The SmartScanThing. This is needed to exxtract the logs from the + LabThings server. + """ + self._log_saved_at = save_invocation_logs( + filename=os.path.join(self.dir_path, "log.txt"), + thing=thing, + last_saved=self._log_saved_at, + append=True, + ) + def zip_files(self, final_version: bool = False) -> str: """Zips any images from the scan not yet zipped, return full path to zip. diff --git a/src/openflexure_microscope_server/things/smart_scan.py b/src/openflexure_microscope_server/things/smart_scan.py index 55e6443c..84143e25 100644 --- a/src/openflexure_microscope_server/things/smart_scan.py +++ b/src/openflexure_microscope_server/things/smart_scan.py @@ -263,6 +263,8 @@ class SmartScanThing(lt.Thing): self._ongoing_scan = self._scan_dir_manager.new_scan_dir(scan_name) self._latest_scan_name = self.ongoing_scan.name self._run_scan(workflow) + # Save any final messages. + self._ongoing_scan.save_scan_log(self) except Exception as e: # If _scan_data is set then scan started if self._scan_data is not None: @@ -273,6 +275,9 @@ class SmartScanThing(lt.Thing): "Attempting to stitch and archive the images acquired so far." ) self._perform_final_stitch() + if self._ongoing_scan is not None: + # Save any final messages even if there is an exception. + self._ongoing_scan.save_scan_log(self) # Error must be raised so UI gives correct output raise e finally: @@ -467,6 +472,7 @@ class SmartScanThing(lt.Thing): self.scan_data.image_count += 1 # Add it to the incremental zip self.ongoing_scan.zip_files() + self.ongoing_scan.save_scan_log(self) @_scan_running def _return_to_starting_position(self) -> None: diff --git a/src/openflexure_microscope_server/utilities.py b/src/openflexure_microscope_server/utilities.py index 8165a73b..552f2ad8 100644 --- a/src/openflexure_microscope_server/utilities.py +++ b/src/openflexure_microscope_server/utilities.py @@ -6,6 +6,7 @@ import os import re import sys import tomllib +from datetime import datetime from functools import wraps from importlib.metadata import version from typing import ( @@ -24,6 +25,7 @@ from typing import ( from pydantic import BaseModel import labthings_fastapi as lt +from labthings_fastapi.invocation_contexts import get_invocation_id T = TypeVar("T") P = ParamSpec("P") @@ -432,3 +434,57 @@ def coerce_thing_selector( # Final option is to return the first key return list(thing_mapping)[0] + + +def get_invocation_logs( + thing: lt.Thing, logged_since: float = 0.0 +) -> list[logging.LogRecord]: + """Get logs from an ongoing action invocation. + + This must be called from the action's context (thread). + + Note that only 1000 logs are stored in LabThings for very long tasks that + log regularly it may be good to periodically poll this and request only + the logs since the last log was created. + + :param thing: The thing that the action is called from. + :param logged_since: The timestamp that records must come after. This could be the + ``record.created`` time of the last log. + :return: A list of ``LogRecord`` objects. + """ + server = thing._thing_server_interface._server() + if server is None: + raise RuntimeError("Could not retrieve server from thing_server_interface.") + manager = server.action_manager + inv_id = get_invocation_id() + invocation = manager.get_invocation(inv_id) + + # Type ignore needed as LabThings incorrectly reports the type from invocation.log + # If pull request 260 on LabThings is merged we can remove this function. + return [record for record in invocation.log if record.created > logged_since] # type: ignore + + +def save_invocation_logs( + filename: str, thing: lt.Thing, last_saved: float = 0.0, append: bool = True +) -> float: + """Save the invocation logs from and ongoing action. + + This must be called from the action's context (thread). + + :param filename: The filename to write the logs to. + :param thing: The thing that the action is called from. + :param last_saved: The timestamp that records must come after. + :param append: If True (default) append to the file if it exists. + + :return: The timestamp of the most recent log. + """ + logs = get_invocation_logs(thing, last_saved) + mode = "a" if append else "w" + with open(filename, mode, encoding="utf-8") as log_file: + for record in logs: + level = record.levelname + dt = datetime.fromtimestamp(record.created) + date_str = dt.strftime("%Y-%m-%d %H:%M:%S") + msg = record.getMessage() + log_file.write(f"[{date_str}] [{level}] {msg}\n") + return 0.0 if not logs else logs[-1].created From 882414596d9ae5ce302cc07e60480c938b0658ce Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Fri, 20 Feb 2026 16:20:33 +0000 Subject: [PATCH 2/6] Fix smart scan tests --- tests/unit_tests/test_smart_scan.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tests/unit_tests/test_smart_scan.py b/tests/unit_tests/test_smart_scan.py index a41d96d5..f89010e3 100644 --- a/tests/unit_tests/test_smart_scan.py +++ b/tests/unit_tests/test_smart_scan.py @@ -324,6 +324,9 @@ def _run_only_outer_scan( assert smart_scan_thing._scan_lock.locked() mocker.patch.object(smart_scan_thing, "_run_scan", side_effect=check_locked) + mock_save_logs = mocker.patch( + "openflexure_microscope_server.scan_directories.save_invocation_logs" + ) if adjust_initial_state is not None: adjust_initial_state(smart_scan_thing) @@ -336,6 +339,7 @@ def _run_only_outer_scan( exec_info = e assert not smart_scan_thing._scan_lock.locked() + assert mock_save_logs.call_count >= 1 # Return the mock thing for further state testing, and the # exec_info of any uncaught exceptions that were raised From e5c490e295a9e2c37795d1dfc89828f57e5c8b63 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Fri, 20 Feb 2026 17:29:10 +0000 Subject: [PATCH 3/6] Move tests for thing selector into a more generic file for testin thing utilities --- tests/unit_tests/{test_thing_selector.py => test_thing_utils.py} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename tests/unit_tests/{test_thing_selector.py => test_thing_utils.py} (100%) diff --git a/tests/unit_tests/test_thing_selector.py b/tests/unit_tests/test_thing_utils.py similarity index 100% rename from tests/unit_tests/test_thing_selector.py rename to tests/unit_tests/test_thing_utils.py From 6db4e9394c48c12b85bc86f94de3911e81583a7a Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Fri, 20 Feb 2026 17:30:16 +0000 Subject: [PATCH 4/6] Write tests for things getting their invocation logs --- .../utilities.py | 4 +- tests/unit_tests/test_thing_utils.py | 149 +++++++++++++++++- 2 files changed, 150 insertions(+), 3 deletions(-) diff --git a/src/openflexure_microscope_server/utilities.py b/src/openflexure_microscope_server/utilities.py index 552f2ad8..0c3f2b6a 100644 --- a/src/openflexure_microscope_server/utilities.py +++ b/src/openflexure_microscope_server/utilities.py @@ -453,7 +453,9 @@ def get_invocation_logs( :return: A list of ``LogRecord`` objects. """ server = thing._thing_server_interface._server() - if server is None: + if server is None: # pragma: no cover + # This should be impossible to reach, but we require this line because the + # server is a weak_ref which MyPy says could return None. raise RuntimeError("Could not retrieve server from thing_server_interface.") manager = server.action_manager inv_id = get_invocation_id() diff --git a/tests/unit_tests/test_thing_utils.py b/tests/unit_tests/test_thing_utils.py index 36cf2767..dd8adb87 100644 --- a/tests/unit_tests/test_thing_utils.py +++ b/tests/unit_tests/test_thing_utils.py @@ -1,10 +1,22 @@ -"""Test selector coercion logic for Thing mappings.""" +"""Test utility functions for things.""" import logging +import os +import re +import tempfile +import time import pytest -from openflexure_microscope_server.utilities import coerce_thing_selector +import labthings_fastapi as lt + +from openflexure_microscope_server.utilities import ( + coerce_thing_selector, + get_invocation_logs, + save_invocation_logs, +) + +from ..shared_utils.lt_test_utils import LabThingsTestEnv @pytest.mark.parametrize( @@ -57,3 +69,136 @@ def test_coerce_with_populated_mapping( ) assert output == returned assert len(caplog.records) == warning_count + + +def simple_log_format(record: logging.LogRecord): + """Format a log as just "[LEVEL] message".""" + level = record.levelname + msg = record.getMessage() + return f"[{level}] {msg}\n" + + +class ThingThatLogs(lt.Thing): + """A thing that has has actions that log.""" + + @lt.action + def log_and_capture(self, msg: str) -> str: + """Log a message to the thing's logger.""" + self.logger.info(msg) + self.logger.warning(msg) + self.logger.error(msg) + logs = get_invocation_logs(self) + logging_str = "" + for record in logs: + logging_str += simple_log_format(record) + return logging_str + + @lt.action + def log_and_capture_some(self, msg: str) -> str: + """Log a message to the thing's logger.""" + self.logger.info(msg) + self.logger.warning(msg) + before_err = time.time() + self.logger.error(msg) + logs = get_invocation_logs(self, logged_since=before_err) + logging_str = "" + for record in logs: + logging_str += simple_log_format(record) + return logging_str + + @lt.action + def log_and_save(self, msg: str, filename: str, append: bool) -> float: + """Log a message to the thing's logger.""" + self.logger.info(msg) + self.logger.warning(msg) + self.logger.error(msg) + return save_invocation_logs( + filename=filename, + thing=self, + append=append, + ) + + +@pytest.fixture +def logging_thing_test_env(): + """Yield a test environment with ThingThatLogs.""" + thing_conf = {"logging_thing": ThingThatLogs} + with LabThingsTestEnv(things=thing_conf) as env: + yield env + + +def test_get_invocation_logs(logging_thing_test_env): + """Test that get_invocation_logs does return logs. + + This must be run in the invocation context to get the logs so the call + to the function under test is actually in ``ThingThatLogs``. + """ + client = logging_thing_test_env.get_thing_client("logging_thing") + thing = logging_thing_test_env.get_thing_by_name("logging_thing") + result = client.log_and_capture(msg="foobar") + expected_message = "[INFO] foobar\n[WARNING] foobar\n[ERROR] foobar\n" + assert result == expected_message + # Can't be called directly as it must be in an action thread to get log context. + with pytest.raises(lt.exceptions.NoInvocationContextError): + thing.log_and_capture(msg="foobar") + + +def test_get_some_invocation_logs(logging_thing_test_env): + """Test that get_invocation_logs does return logs with time filter.""" + client = logging_thing_test_env.get_thing_client("logging_thing") + result = client.log_and_capture_some(msg="foobar") + expected_message = "[ERROR] foobar\n" + assert result == expected_message + + +def _assert_file_contents_matches_regex(filename: str, regex: str) -> None: + """Assert that file contents matches a regex string.""" + with open(filename, "r") as file_obj: + content = file_obj.read() + + assert re.match(regex, content) is not None + + +DATE_REGEX = r"\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\]" + +INFO_REGEX = DATE_REGEX + r" \[INFO\] foobar\n" +WARN_REGEX = DATE_REGEX + r" \[WARNING\] foobar\n" +ERR_REGEX = DATE_REGEX + r" \[ERROR\] foobar\n" + + +def test_save_invocation_logs(logging_thing_test_env): + """Test that get_invocation_logs saves logs.""" + client = logging_thing_test_env.get_thing_client("logging_thing") + with tempfile.TemporaryDirectory() as tmpdir: + logpath = os.path.join(tmpdir, "log.txt") + save_time = client.log_and_save(msg="foobar", filename=logpath, append=True) + + # Check that the save time is now taking into account delays. + assert time.time() > save_time > time.time() - 0.1 + + # Check there are 3 messages an inf a warning and an error + _assert_file_contents_matches_regex( + logpath, + r"^" + INFO_REGEX + WARN_REGEX + ERR_REGEX + r"$", + ) + + # Run again with append=True and check that there are now 6 messages. + client.log_and_save(msg="foobar", filename=logpath, append=True) + _assert_file_contents_matches_regex( + logpath, + r"^" + + INFO_REGEX + + WARN_REGEX + + ERR_REGEX + + INFO_REGEX + + WARN_REGEX + + ERR_REGEX + + r"$", + ) + + # Run again with append=False and check that only 3 message now remain. + client.log_and_save(msg="foobar", filename=logpath, append=False) + _assert_file_contents_matches_regex( + logpath, + r"^" + INFO_REGEX + WARN_REGEX + ERR_REGEX + r"$", + ) From d7a27ee82f0f2caf0e6e6379d71798722378fed9 Mon Sep 17 00:00:00 2001 From: Joe Knapper Date: Mon, 23 Feb 2026 13:45:02 +0000 Subject: [PATCH 5/6] Apply suggestions from code review of branch scan-logs Co-authored-by: Julian Stirling --- tests/unit_tests/test_thing_utils.py | 20 +++++++++++++++++--- 1 file changed, 17 insertions(+), 3 deletions(-) diff --git a/tests/unit_tests/test_thing_utils.py b/tests/unit_tests/test_thing_utils.py index dd8adb87..a0757418 100644 --- a/tests/unit_tests/test_thing_utils.py +++ b/tests/unit_tests/test_thing_utils.py @@ -29,7 +29,11 @@ from ..shared_utils.lt_test_utils import LabThingsTestEnv ], ) def test_coerce_with_empty_mapping(selected, default, warning_count, caplog): - """Test None always returned for empty mappings, check warnings when appropriate.""" + """Test None always returned for empty mappings, check warnings when expected. + + We expect warnings if the code tries to set a selected value that is not None, + as None is the only valid answer. + """ with caplog.at_level(logging.WARNING): output = coerce_thing_selector( thing_mapping={}, selected=selected, default=default @@ -60,6 +64,16 @@ def test_coerce_with_populated_mapping( ): """Test coercion of selected key for a populated thing mapping. + The available things have names `a`, `b`, and `c`. These are the only valid + returns. + + * If `selected` has a valid value it will be returned. + * If `selected` is None `default` will be read, if `default` is a valid value + it will be returned. + * If `selected` or `default` have a non-`None` value that is not valid, then a + warning is logged, but the value is treated as `None`. + * Finally if no value is set, the first option in the mapping (`a`) is returned. + Check that warnings are raised when appropriate. """ thing_mapping = {"a": "Foo", "b": "Bar", "c": "FooBar"} @@ -83,7 +97,7 @@ class ThingThatLogs(lt.Thing): @lt.action def log_and_capture(self, msg: str) -> str: - """Log a message to the thing's logger.""" + """Log messages to the thing's logger, then capture and return them.""" self.logger.info(msg) self.logger.warning(msg) self.logger.error(msg) @@ -95,7 +109,7 @@ class ThingThatLogs(lt.Thing): @lt.action def log_and_capture_some(self, msg: str) -> str: - """Log a message to the thing's logger.""" + """Log messages to the thing's logger, capture the last one and return it.""" self.logger.info(msg) self.logger.warning(msg) before_err = time.time() From ff9c61bd650e909565f0e58ffd5082cc7d0bb046 Mon Sep 17 00:00:00 2001 From: Joe Knapper Date: Mon, 23 Feb 2026 13:48:15 +0000 Subject: [PATCH 6/6] Apply suggestions from code review of branch scan-logs --- src/openflexure_microscope_server/utilities.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/openflexure_microscope_server/utilities.py b/src/openflexure_microscope_server/utilities.py index 0c3f2b6a..d6df4df9 100644 --- a/src/openflexure_microscope_server/utilities.py +++ b/src/openflexure_microscope_server/utilities.py @@ -443,7 +443,7 @@ def get_invocation_logs( This must be called from the action's context (thread). - Note that only 1000 logs are stored in LabThings for very long tasks that + Note that only 1000 logs are stored in LabThings. For very long tasks that log regularly it may be good to periodically poll this and request only the logs since the last log was created.