Improve log filtering and logging error handling. Adding more logging tests.

src/openflexure_microscope_server/logging.py

@@ -16,6 +16,7 @@ from logging.handlers import RotatingFileHandler
 import os
 
 from fastapi.responses import PlainTextResponse
+from fastapi import HTTPException
 
 OFM_LOG_FILE = None
 
@@ -39,6 +40,7 @@ def configure_logging(log_folder):
     # log file can't be accessed.
     ofm_format_str = "[%(asctime)s] [%(levelname)s] %(message)s"
     OFM_HANDLER.setFormatter(logging.Formatter(ofm_format_str))
+    OFM_HANDLER.addFilter(UvicornAccessFilter())
     root_logger.addHandler(OFM_HANDLER)
 
     try:
@@ -52,6 +54,7 @@ def configure_logging(log_folder):
         )
         format_str = "[%(asctime)s] [%(levelname)s] <%(name)s> %(message)s"
         handler.setFormatter(logging.Formatter(format_str))
+        handler.addFilter(UvicornAccessFilter())
         root_logger.addHandler(handler)
 
     except PermissionError as e:
@@ -84,12 +87,17 @@ def retrieve_log_from_file() -> PlainTextResponse:
     is written to while sending through FileResponse.
     """
     if OFM_LOG_FILE is None:
-        raise RuntimeError(
-            "Cannot retrieve log file as logging directory hasn't been configured"
+        raise HTTPException(
+            500, "Cannot retrieve log file as logging directory hasn't been configured."
         )
-    with open(OFM_LOG_FILE, "r", encoding="utf-8") as logfile:
-        full_log = logfile.read()
-    return PlainTextResponse(full_log)
+    try:
+        with open(OFM_LOG_FILE, "r", encoding="utf-8") as logfile:
+            full_log = logfile.read()
+        return PlainTextResponse(full_log)
+    except IOError as e:
+        raise HTTPException(
+            500, "An error occurred while trying to access the log file."
+        ) from e
 
 
 class OFMHandler(logging.Handler):
@@ -120,11 +128,6 @@ class OFMHandler(logging.Handler):
 
     def emit(self, record):
         """Emit will save the logged record to the log."""
-        # Basic filter for now that simply stops uvicorn.access logs
-        # These are the logs each time an API endpoint is accessed
-        # This is only the log for the UI.
-        if record.name.startswith("uvicorn.access"):
-            return
         try:
             if record.levelno >= self.level:
                 self.append_record(record)
@@ -141,4 +144,12 @@ class OFMHandler(logging.Handler):
         return "\n".join(self._log)
 
 
+class UvicornAccessFilter(logging.Filter):
+    """A logging filter to filter out "uvicorn.access" messages."""
+
+    def filter(self, record):
+        """Return False if record is from "uvicorn.access"."""
+        return not record.name.startswith("uvicorn.access")
+
+
 OFM_HANDLER = OFMHandler()

tests/test_logging.py

@@ -4,6 +4,10 @@ import os
 import tempfile
 import logging
 
+from fastapi.responses import PlainTextResponse
+from fastapi import HTTPException
+import pytest
+
 from openflexure_microscope_server import logging as ofm_logging
 
 
@@ -16,6 +20,8 @@ def test_no_warnings_if_correct_permissions(caplog):
     * That the log file is created.
     * That the log file contains the expected message about setting up the logger.
     """
+    # Reset handler at start of test
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
     with caplog.at_level(logging.WARNING):
         with tempfile.TemporaryDirectory() as tmpdir:
             ofm_logging.configure_logging(tmpdir)
@@ -33,6 +39,8 @@ def test_permission_error_raises_warning(mocker, caplog):
         "openflexure_microscope_server.logging.RotatingFileHandler",
         side_effect=PermissionError("Permission denied"),
     )
+    # Reset handler at start of test
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
     with caplog.at_level(logging.WARNING):
         with tempfile.TemporaryDirectory() as tmpdir:
             ofm_logging.configure_logging(tmpdir)
@@ -44,6 +52,8 @@ def test_permission_error_raises_warning(mocker, caplog):
 
 def test_making_log_dir(caplog):
     """Check that configure_logging will make a dir if needed."""
+    # Reset handler at start of test
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
     with caplog.at_level(logging.WARNING):
         with tempfile.TemporaryDirectory() as tmpdir:
             log_dir = os.path.join(tmpdir, "new_dir")
@@ -55,6 +65,8 @@ def test_making_log_dir(caplog):
 
 def test_max_logs():
     """Proclaim that only the most recent 250 logs are stored in memory."""
+    # Reset handler at start of test
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
     with tempfile.TemporaryDirectory() as tmpdir:
         ofm_logging.configure_logging(tmpdir)
         # But I would log five hundred times.
@@ -62,12 +74,84 @@ def test_max_logs():
             logging.info("log %s", i)
         logs = ofm_logging.OFM_HANDLER.log_history.split("\n")
         assert len(logs) == 250
-        logs[0] = "log 250"
-        logs[-1] = "log 499"
+        assert logs[0].endswith("log 250")
+        assert logs[-1].endswith("log 499")
         # And I would log five hundred more.
         for i in range(500):
-            logging.info("log %s", i)
+            logging.info("log %s", 500 + i)
         # Just to be the test who logged a thousand times to check your hand-el-or!
+        logs = ofm_logging.OFM_HANDLER.log_history.split("\n")
         assert len(logs) == 250
-        logs[0] = "log 750"
-        logs[-1] = "log 999"
+        assert logs[0].endswith("log 750")
+        assert logs[-1].endswith("log 999")
+
+
+def test_ofm_handler_ignores_uvicorn_access():
+    """Check uvicorn.access logs are ignored by custom handler.
+
+    The uvicorn.access logger logs every time an endpoint is triggered.
+    """
+    # Reset handler at start of test
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
+    with tempfile.TemporaryDirectory() as tmpdir:
+        ofm_logging.configure_logging(tmpdir)
+        logs = ofm_logging.OFM_HANDLER.log_history.split("\n")
+        starting_len = len(logs)
+        logging.info("Root 1")
+        uvicorn_logger = logging.getLogger("uvicorn.access")
+        for i in range(500):
+            uvicorn_logger.info("Uvicorn log %s", i)
+        logging.info("Root 2")
+        logs = ofm_logging.OFM_HANDLER.log_history.split("\n")
+        assert len(logs) == starting_len + 2
+        assert logs[starting_len].endswith("Root 1")
+        assert logs[-1].endswith("Root 2")
+
+
+def test_server_responses():
+    """Check that the FastAPI responses from the server are as expected.
+
+    * retrieve_log() -> PlainTextResponse containing the last 250 logs separated by
+        a new line
+    * retrieve_log_from_file() -> All the logs from the log file.
+    """
+    # Reset handler at start of test
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
+    with tempfile.TemporaryDirectory() as tmpdir:
+        ofm_logging.configure_logging(tmpdir)
+        for i in range(500):
+            logging.info("log %s", i)
+        log_response = ofm_logging.retrieve_log()
+        assert isinstance(log_response, PlainTextResponse)
+        logs = log_response.body.decode().split("\n")
+        assert len(logs) == 250
+        file_log_response = ofm_logging.retrieve_log_from_file()
+        assert isinstance(file_log_response, PlainTextResponse)
+        file_logs = file_log_response.body.decode().split("\n")
+        assert len(file_logs) > 500
+
+
+def test_server_response_with_no_log_file():
+    """Check that an HTTP exception is raised if logging isn't configured."""
+    # Reset handler at start of test
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
+    # Also Reset log file global
+    ofm_logging.OFM_LOG_FILE = None
+    with pytest.raises(HTTPException) as excinfo:
+        ofm_logging.retrieve_log_from_file()
+    assert excinfo.value.status_code == 500
+
+
+def test_server_response_with_no_log_dir():
+    """Check that an HTTP exception is raised if the log file cannot be accessed."""
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
+    with tempfile.TemporaryDirectory() as tmpdir:
+        ofm_logging.configure_logging(tmpdir)
+        for i in range(500):
+            logging.info("log %s", i)
+        file_log_response = ofm_logging.retrieve_log_from_file()
+        assert isinstance(file_log_response, PlainTextResponse)
+    # Close and delete the log folder, this should create an error.
+    with pytest.raises(HTTPException) as excinfo:
+        ofm_logging.retrieve_log_from_file()
+    assert excinfo.value.status_code == 500