Merge branch 'scan-logs' into 'v3'

Scan logs

Closes #627

See merge request openflexure/openflexure-microscope-server!501

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.
 

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:

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

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

tests/unit_tests/test_thing_selector.py

@@ -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

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"$",
+        )