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..d6df4df9 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,59 @@ 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: # 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() + 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 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 diff --git a/tests/unit_tests/test_thing_selector.py b/tests/unit_tests/test_thing_selector.py deleted file mode 100644 index 36cf2767..00000000 --- a/tests/unit_tests/test_thing_selector.py +++ /dev/null @@ -1,59 +0,0 @@ -"""Test selector coercion logic for Thing mappings.""" - -import logging - -import pytest - -from openflexure_microscope_server.utilities import coerce_thing_selector - - -@pytest.mark.parametrize( - ("selected", "default", "warning_count"), - [ - ("a", "b", 1), - (None, "b", 0), - ("a", None, 1), - (None, None, 0), - ], -) -def test_coerce_with_empty_mapping(selected, default, warning_count, caplog): - """Test None always returned for empty mappings, check warnings when appropriate.""" - with caplog.at_level(logging.WARNING): - output = coerce_thing_selector( - thing_mapping={}, selected=selected, default=default - ) - assert output is None - assert len(caplog.records) == warning_count - - -@pytest.mark.parametrize( - ("selected", "default", "returned", "warning_count"), - [ - ("b", "b", "b", 0), - ("b", "a", "b", 0), - ("b", None, "b", 0), - ("b", "z", "b", 0), - (None, "b", "b", 0), - (None, "a", "a", 0), - (None, None, "a", 0), - (None, "z", "a", 1), - ("z", "b", "b", 1), - ("z", "a", "a", 1), - ("z", None, "a", 1), - ("z", "z", "a", 2), - ], -) -def test_coerce_with_populated_mapping( - selected, default, returned, warning_count, caplog -): - """Test coercion of selected key for a populated thing mapping. - - Check that warnings are raised when appropriate. - """ - thing_mapping = {"a": "Foo", "b": "Bar", "c": "FooBar"} - with caplog.at_level(logging.WARNING): - output = coerce_thing_selector( - thing_mapping=thing_mapping, selected=selected, default=default - ) - assert output == returned - assert len(caplog.records) == warning_count diff --git a/tests/unit_tests/test_thing_utils.py b/tests/unit_tests/test_thing_utils.py new file mode 100644 index 00000000..a0757418 --- /dev/null +++ b/tests/unit_tests/test_thing_utils.py @@ -0,0 +1,218 @@ +"""Test utility functions for things.""" + +import logging +import os +import re +import tempfile +import time + +import pytest + +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( + ("selected", "default", "warning_count"), + [ + ("a", "b", 1), + (None, "b", 0), + ("a", None, 1), + (None, None, 0), + ], +) +def test_coerce_with_empty_mapping(selected, default, warning_count, caplog): + """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 + ) + assert output is None + assert len(caplog.records) == warning_count + + +@pytest.mark.parametrize( + ("selected", "default", "returned", "warning_count"), + [ + ("b", "b", "b", 0), + ("b", "a", "b", 0), + ("b", None, "b", 0), + ("b", "z", "b", 0), + (None, "b", "b", 0), + (None, "a", "a", 0), + (None, None, "a", 0), + (None, "z", "a", 1), + ("z", "b", "b", 1), + ("z", "a", "a", 1), + ("z", None, "a", 1), + ("z", "z", "a", 2), + ], +) +def test_coerce_with_populated_mapping( + selected, default, returned, warning_count, caplog +): + """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"} + with caplog.at_level(logging.WARNING): + output = coerce_thing_selector( + thing_mapping=thing_mapping, selected=selected, default=default + ) + 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 messages to the thing's logger, then capture and return them.""" + 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 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() + 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"$", + )