From 3529c96ec633abda3a47ad66ea2aed7ce9943572 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Thu, 21 Aug 2025 15:33:56 +0100 Subject: [PATCH 1/3] Stop reporting uvicorn.error in log file unless log it is an error --- src/openflexure_microscope_server/logging.py | 21 ++++++++++++- tests/test_logging.py | 33 ++++++++++++++++++++ 2 files changed, 53 insertions(+), 1 deletion(-) diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index ce00f5e3..6ebde7db 100644 --- a/src/openflexure_microscope_server/logging.py +++ b/src/openflexure_microscope_server/logging.py @@ -53,7 +53,7 @@ def configure_logging(log_folder): backupCount=10, ) format_str = "[%(asctime)s] [%(levelname)s] <%(name)s> %(message)s" - handler.setFormatter(logging.Formatter(format_str)) + handler.setFormatter(OFMLogFileFormatter(format_str)) handler.addFilter(UvicornAccessFilter()) root_logger.addHandler(handler) @@ -100,6 +100,25 @@ def retrieve_log_from_file() -> PlainTextResponse: ) from e +class OFMLogFileFormatter(logging.Formatter): + """The formatter used for the OpenFlexure Microscope Server log file.""" + + def format(self, record): + """Adjust the logging formatting for uvicorn logs. + + Any ``uvicorn.error`` logs that are at a lower + + uvicorn has two loggers. Each API access is ``uvicorn.access`` which we filter + due to the noise the other is ``uvicorn.error`` for more important messages. + However, ``uvicorn.error`` is used for expected messages that are not errors, + such as server start up. This can lead to people erroneously thinking that + there is an error with their miroscope. + """ + if record.name == "uvicorn.error" and record.levelno < logging.ERROR: + record.name = "uvicorn" + return super().format(record) + + class OFMHandler(logging.Handler): """A logging.Handler that stores the most recent logs for access by the server.""" diff --git a/tests/test_logging.py b/tests/test_logging.py index 0a48125a..01c38562 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -155,3 +155,36 @@ def test_server_response_with_no_log_dir(): with pytest.raises(HTTPException) as excinfo: ofm_logging.retrieve_log_from_file() assert excinfo.value.status_code == 500 + + +FAKE_UVICORN_LOGGER = logging.getLogger("uvicorn.error") + + +@pytest.mark.parametrize( + "log_command, names_in_log, names_not_in_log", + [ + [FAKE_UVICORN_LOGGER.debug, [], ["", ""]], + [FAKE_UVICORN_LOGGER.info, [""], [""]], + [FAKE_UVICORN_LOGGER.warning, [""], [""]], + [FAKE_UVICORN_LOGGER.error, [""], [""]], + [FAKE_UVICORN_LOGGER.exception, [""], [""]], + ], +) +def test_uvicorn_error_only_says_error_on_error( + log_command, names_in_log, names_not_in_log +): + """Check that an HTTP exception is raised if the log file cannot be accessed. + + Parametrised to check: debug doesn't log, info and warning log as , and + error logs as . + """ + ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler() + with tempfile.TemporaryDirectory() as tmpdir: + ofm_logging.configure_logging(tmpdir) + log_command("Mockedy mock mock!") + with open(ofm_logging.OFM_LOG_FILE, "r", encoding="utf-8") as log_file: + log_txt = log_file.read() + for name in names_in_log: + assert name in log_txt + for name in names_not_in_log: + assert name not in log_txt From 95969c5daa7205c38b6ab533dd207ea1d242127e Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Thu, 21 Aug 2025 15:49:00 +0100 Subject: [PATCH 2/3] Improve typehinting for logging --- src/openflexure_microscope_server/logging.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index 6ebde7db..4710e1d4 100644 --- a/src/openflexure_microscope_server/logging.py +++ b/src/openflexure_microscope_server/logging.py @@ -103,7 +103,7 @@ def retrieve_log_from_file() -> PlainTextResponse: class OFMLogFileFormatter(logging.Formatter): """The formatter used for the OpenFlexure Microscope Server log file.""" - def format(self, record): + def format(self, record: logging.LogRecord): """Adjust the logging formatting for uvicorn logs. Any ``uvicorn.error`` logs that are at a lower @@ -134,7 +134,7 @@ class OFMHandler(logging.Handler): self._log = [] self._max_logs = max_logs - def append_record(self, record): + def append_record(self, record: logging.LogRecord): """Format message and append it to a list of records. The built in formatter is used to format the record. @@ -145,7 +145,7 @@ class OFMHandler(logging.Handler): while len(self._log) > self._max_logs: self._log.pop(0) - def emit(self, record): + def emit(self, record: logging.LogRecord): """Emit will save the logged record to the log.""" try: if record.levelno >= self.level: @@ -166,7 +166,7 @@ class OFMHandler(logging.Handler): class UvicornAccessFilter(logging.Filter): """A logging filter to filter out "uvicorn.access" messages.""" - def filter(self, record): + def filter(self, record: logging.LogRecord): """Return False if record is from "uvicorn.access".""" return not record.name.startswith("uvicorn.access") From 353d311c1e83ae978e620896e023988056b3f9e0 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Wed, 27 Aug 2025 13:24:37 +0000 Subject: [PATCH 3/3] Apply suggestions from code review of branch no-uvicorn.error-logs-without-error Co-authored-by: Richard Bowman --- src/openflexure_microscope_server/logging.py | 4 +--- tests/test_logging.py | 2 +- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index 4710e1d4..69a03ffc 100644 --- a/src/openflexure_microscope_server/logging.py +++ b/src/openflexure_microscope_server/logging.py @@ -106,10 +106,8 @@ class OFMLogFileFormatter(logging.Formatter): def format(self, record: logging.LogRecord): """Adjust the logging formatting for uvicorn logs. - Any ``uvicorn.error`` logs that are at a lower - uvicorn has two loggers. Each API access is ``uvicorn.access`` which we filter - due to the noise the other is ``uvicorn.error`` for more important messages. + due to the noise. The other is ``uvicorn.error`` for more important messages. However, ``uvicorn.error`` is used for expected messages that are not errors, such as server start up. This can lead to people erroneously thinking that there is an error with their miroscope. diff --git a/tests/test_logging.py b/tests/test_logging.py index 01c38562..bdeec6d2 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -181,7 +181,7 @@ def test_uvicorn_error_only_says_error_on_error( ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler() with tempfile.TemporaryDirectory() as tmpdir: ofm_logging.configure_logging(tmpdir) - log_command("Mockedy mock mock!") + log_command("Mockety mock mock!") with open(ofm_logging.OFM_LOG_FILE, "r", encoding="utf-8") as log_file: log_txt = log_file.read() for name in names_in_log: