Merge branch 'no-uvicorn.error-logs-without-error' into 'v3'

Stop reporting uvicorn.error in log file unless log it is an error

Closes #511

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

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,23 @@ 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: logging.LogRecord):
+        """Adjust the logging formatting for uvicorn logs.
+
+        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."""
 
@@ -115,7 +132,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.
@@ -126,7 +143,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:
@@ -147,7 +164,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")
 

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, [], ["<uvicorn>", "<uvicorn.error>"]],
+        [FAKE_UVICORN_LOGGER.info, ["<uvicorn>"], ["<uvicorn.error>"]],
+        [FAKE_UVICORN_LOGGER.warning, ["<uvicorn>"], ["<uvicorn.error>"]],
+        [FAKE_UVICORN_LOGGER.error, ["<uvicorn.error>"], ["<uvicorn>"]],
+        [FAKE_UVICORN_LOGGER.exception, ["<uvicorn.error>"], ["<uvicorn>"]],
+    ],
+)
+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 <uvicorn>, and
+    error logs as <uvicorn.error>.
+    """
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
+    with tempfile.TemporaryDirectory() as tmpdir:
+        ofm_logging.configure_logging(tmpdir)
+        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:
+            assert name in log_txt
+        for name in names_not_in_log:
+            assert name not in log_txt