Merge branch 'logging-groups' into 'v3'

Add invocation ID to log message if available

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

src/openflexure_microscope_server/logging.py

@@ -19,6 +19,8 @@ from typing import Optional
 from fastapi import HTTPException
 from fastapi.responses import PlainTextResponse
 
+from labthings_fastapi.logs import inject_invocation_id
+
 LOGGER = logging.getLogger(__name__)
 OFM_LOG_FILE: Optional[str] = None
 
@@ -65,9 +67,12 @@ def configure_logging(log_folder: str, debug: bool = False) -> None:
             maxBytes=1000000,
             backupCount=10,
         )
-        format_str = "[%(asctime)s] [%(levelname)s] <%(name)s> %(message)s"
+        format_str = (
+            "[%(asctime)s] [%(levelname)s] <%(name)s>%(invocation_id_str)s %(message)s"
+        )
         handler.setFormatter(OFMLogFileFormatter(format_str))
         handler.addFilter(UvicornAccessFilter())
+        handler.addFilter(inject_invocation_id)
         root_logger.addHandler(handler)
 
     except PermissionError as e:
@@ -114,7 +119,10 @@ def retrieve_log_from_file() -> PlainTextResponse:
 
 
 class OFMLogFileFormatter(logging.Formatter):
-    """The formatter used for the OpenFlexure Microscope Server log file."""
+    """The formatter used for the OpenFlexure Microscope Server log file.
+
+    This is the log that is then read by the GUI.
+    """
 
     def format(self, record: logging.LogRecord) -> str:
         """Adjust the logging formatting for uvicorn logs.
@@ -125,6 +133,11 @@ class OFMLogFileFormatter(logging.Formatter):
         such as server start up. This can lead to people erroneously thinking that
         there is an error with their miroscope.
         """
+        invocation_id = getattr(record, "invocation_id", None)
+        record.invocation_id_str = (
+            f" [invocation:{invocation_id}]" if invocation_id else ""
+        )
+
         if record.name == "uvicorn.error" and record.levelno < logging.ERROR:
             record.name = "uvicorn"
         return super().format(record)

tests/unit_tests/test_logging.py

@@ -234,3 +234,48 @@ def test_configure_logging_debug_mode(debug_flag, expected_level):
         # Cleanup: Remove the OFM_HANDLER from the root logger so it doesn't
         # interfere with other tests in the suite.
         root_logger.removeHandler(ofm_logging.OFM_HANDLER)
+
+
+def test_log_file_formatter_includes_invocation_id():
+    """Check that invocation IDs are included in logs when available."""
+    formatter = ofm_logging.OFMLogFileFormatter(
+        "[%(levelname)s]%(invocation_id_str)s %(message)s"
+    )
+
+    record = logging.LogRecord(
+        name="test",
+        level=logging.INFO,
+        pathname="",
+        lineno=0,
+        msg="Test message",
+        args=(),
+        exc_info=None,
+    )
+    record.invocation_id = "abc123"
+
+    formatted = formatter.format(record)
+
+    assert "[invocation:abc123]" in formatted
+    assert "Test message" in formatted
+
+
+def test_log_file_formatter_without_invocation_id():
+    """Check that logs without invocation IDs still format correctly."""
+    formatter = ofm_logging.OFMLogFileFormatter(
+        "[%(levelname)s]%(invocation_id_str)s %(message)s"
+    )
+
+    record = logging.LogRecord(
+        name="test",
+        level=logging.INFO,
+        pathname="",
+        lineno=0,
+        msg="Test message",
+        args=(),
+        exc_info=None,
+    )
+
+    formatted = formatter.format(record)
+
+    assert "[invocation:" not in formatted
+    assert "Test message" in formatted