diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index 38ad3848..bbece763 100644 --- a/src/openflexure_microscope_server/logging.py +++ b/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) diff --git a/tests/unit_tests/test_logging.py b/tests/unit_tests/test_logging.py index 0f961c23..76ae0f24 100644 --- a/tests/unit_tests/test_logging.py +++ b/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