From e42aaf25478ea3150198f609b8d1712ef19658fe Mon Sep 17 00:00:00 2001 From: Joe Knapper Date: Tue, 7 Jul 2026 14:27:18 +0100 Subject: [PATCH 1/3] Add invocation ID to log message if available --- src/openflexure_microscope_server/logging.py | 24 +++++++++++++++++--- 1 file changed, 21 insertions(+), 3 deletions(-) diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index 38ad3848..40709fa8 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 @@ -50,9 +52,10 @@ def configure_logging(log_folder: str, debug: bool = False) -> None: # Add OFM_HANDLER first so it can capture the error log if the # log file can't be accessed. - ofm_format_str = "[%(asctime)s] [%(levelname)s] %(message)s" - OFM_HANDLER.setFormatter(logging.Formatter(ofm_format_str)) + ofm_format_str = "[%(asctime)s] [%(levelname)s]%(invocation_id_str)s %(message)s" + OFM_HANDLER.setFormatter(OFMConsoleFormatter(ofm_format_str)) OFM_HANDLER.addFilter(UvicornAccessFilter()) + OFM_HANDLER.addFilter(inject_invocation_id) OFM_HANDLER.level = root_logger.level root_logger.addHandler(OFM_HANDLER) @@ -65,9 +68,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: @@ -182,4 +188,16 @@ class UvicornAccessFilter(logging.Filter): return not record.name.startswith("uvicorn.access") +class OFMConsoleFormatter(logging.Formatter): + """Formatter for OFM_HANDLER (the UI-facing log).""" + + def format(self, record: logging.LogRecord) -> str: + """Render the invocation ID into the record, if present.""" + invocation_id = getattr(record, "invocation_id", None) + record.invocation_id_str = ( + f" [invocation:{invocation_id}]" if invocation_id else "" + ) + return super().format(record) + + OFM_HANDLER = OFMHandler() From 013341272eeaf971800c23b0e4863c42e15cf807 Mon Sep 17 00:00:00 2001 From: Joe Knapper Date: Tue, 7 Jul 2026 14:47:53 +0100 Subject: [PATCH 2/3] Only format file log, add tests --- src/openflexure_microscope_server/logging.py | 26 +++++------ tests/unit_tests/test_logging.py | 45 ++++++++++++++++++++ 2 files changed, 56 insertions(+), 15 deletions(-) diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index 40709fa8..199f324b 100644 --- a/src/openflexure_microscope_server/logging.py +++ b/src/openflexure_microscope_server/logging.py @@ -52,8 +52,8 @@ def configure_logging(log_folder: str, debug: bool = False) -> None: # Add OFM_HANDLER first so it can capture the error log if the # log file can't be accessed. - ofm_format_str = "[%(asctime)s] [%(levelname)s]%(invocation_id_str)s %(message)s" - OFM_HANDLER.setFormatter(OFMConsoleFormatter(ofm_format_str)) + ofm_format_str = "[%(asctime)s] [%(levelname)s] %(message)s" + OFM_HANDLER.setFormatter(logging.Formatter(ofm_format_str)) OFM_HANDLER.addFilter(UvicornAccessFilter()) OFM_HANDLER.addFilter(inject_invocation_id) OFM_HANDLER.level = root_logger.level @@ -120,7 +120,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. @@ -131,6 +134,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) @@ -188,16 +196,4 @@ class UvicornAccessFilter(logging.Filter): return not record.name.startswith("uvicorn.access") -class OFMConsoleFormatter(logging.Formatter): - """Formatter for OFM_HANDLER (the UI-facing log).""" - - def format(self, record: logging.LogRecord) -> str: - """Render the invocation ID into the record, if present.""" - invocation_id = getattr(record, "invocation_id", None) - record.invocation_id_str = ( - f" [invocation:{invocation_id}]" if invocation_id else "" - ) - return super().format(record) - - OFM_HANDLER = OFMHandler() 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 From abafc012e1d2e0ea268486703aaf63d28e3114c1 Mon Sep 17 00:00:00 2001 From: Joe Knapper Date: Tue, 7 Jul 2026 15:38:31 +0100 Subject: [PATCH 3/3] Remove invocation ID from console log --- src/openflexure_microscope_server/logging.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index 199f324b..bbece763 100644 --- a/src/openflexure_microscope_server/logging.py +++ b/src/openflexure_microscope_server/logging.py @@ -55,7 +55,6 @@ def configure_logging(log_folder: str, debug: bool = False) -> None: ofm_format_str = "[%(asctime)s] [%(levelname)s] %(message)s" OFM_HANDLER.setFormatter(logging.Formatter(ofm_format_str)) OFM_HANDLER.addFilter(UvicornAccessFilter()) - OFM_HANDLER.addFilter(inject_invocation_id) OFM_HANDLER.level = root_logger.level root_logger.addHandler(OFM_HANDLER)