Merge branch 'consistent-logging' into 'v3'

Stop uvicorn.run disabling existing loggers

Closes #284

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

src/openflexure_microscope_server/logging.py

@@ -2,7 +2,7 @@ import logging
 from logging.handlers import RotatingFileHandler
 import os
 
-from fastapi.responses import FileResponse, PlainTextResponse
+from fastapi.responses import PlainTextResponse
 
 OFM_LOG_FOLDER = "/var/openflexure/logs/"
 OFM_LOG_FILE = os.path.join(OFM_LOG_FOLDER, "openflexure_microscope.log")
@@ -11,6 +11,7 @@ OFM_LOG_FILE = os.path.join(OFM_LOG_FOLDER, "openflexure_microscope.log")
 def configure_logging():
     root_logger = logging.getLogger()
     root_logger.setLevel(logging.INFO)
+
     try:
         if not os.path.exists(OFM_LOG_FOLDER):
             os.makedirs(OFM_LOG_FOLDER)
@@ -20,10 +21,13 @@ def configure_logging():
             maxBytes=1000000,
             backupCount=10,
         )
-        handler.setFormatter(
-            logging.Formatter("[%(asctime)s] [%(levelname)s] %(message)s")
-        )
+        format_str = "[%(asctime)s] [%(levelname)s] <%(name)s> %(message)s"
+        handler.setFormatter(logging.Formatter(format_str))
         root_logger.addHandler(handler)
+        ofm_format_str = "[%(asctime)s] [%(levelname)s] %(message)s"
+        OFM_HANDLER.setFormatter(logging.Formatter(ofm_format_str))
+        root_logger.addHandler(OFM_HANDLER)
+
     except PermissionError as e:
         logging.warning(f"Cannot create log file at {OFM_LOG_FILE}: {e}")
     logging.info("")
@@ -33,5 +37,77 @@ def configure_logging():
 
 
 def retrieve_log() -> PlainTextResponse:
-    """The most recent 1Mb of logs from the server"""
-    return FileResponse(OFM_LOG_FILE, media_type=PlainTextResponse.media_type)
+    """
+    Returns logs since we started running the server, up to a maxiumum of
+    250 messages. This log is the one shown in the UI and on the logging page.
+
+    It does not include any of the `uvicorn.access` logs as these are emmitted
+    every time any API route is called.
+
+    All logs, including `uvicorn.access` are logged to the OFM_LOG_FILE (see above)
+    ths is the best place to get logs about crashes.
+    """
+    return PlainTextResponse(OFM_HANDLER.log_history)
+
+
+def retrieve_log_from_file() -> PlainTextResponse:
+    """
+    Returns the full log from the file for downloading.
+
+    Note this is read and then sent as otherwise it causes a RuntimeError if it
+    is written to while sending through FileResponse
+    """
+    with open(OFM_LOG_FILE, "r", encoding="utf-8") as logfile:
+        full_log = logfile.read()
+    return PlainTextResponse(full_log)
+
+
+class OFMHandler(logging.Handler):
+    """
+    A child class of logging.Handler. This class handles storing the most recent
+    logs for access by the server.
+    """
+
+    def __init__(self, level=logging.INFO, max_logs=250):
+        super().__init__(level=level)
+        self._log = []
+        self._max_logs = max_logs
+
+    def append_record(self, record):
+        """
+        Use the built in formatter to format the record, then save
+        it to an array. Pop any in excess of the mamimum number of logs
+        """
+        self._log.append(self.format(record))
+        while len(self._log) > self._max_logs:
+            self._log.pop(0)
+
+    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)
+        except RecursionError as e:
+            raise e
+        except BaseException:
+            # Never let the logger crash unless there is somehow recursion.
+            # Use built in logging error handler
+            self.handleError(record)
+
+    @property
+    def log_history(self):
+        """
+        Return the log history up to the maximum number of logs
+        """
+        return "\n".join(self._log)
+
+
+OFM_HANDLER = OFMHandler()

src/openflexure_microscope_server/server/__init__.py

@@ -6,7 +6,7 @@ from labthings_fastapi.server import cli, ThingServer
 import uvicorn
 from .serve_static_files import add_static_files
 from .legacy_api import add_v2_endpoints
-from ..logging import configure_logging, retrieve_log
+from ..logging import configure_logging, retrieve_log, retrieve_log_from_file
 
 
 def customise_server(server: ThingServer):
@@ -18,8 +18,9 @@ def customise_server(server: ThingServer):
     except RuntimeError:
         print("Failed to add static files - you will have to do without them!")
 
-    # Add an endpoint to get the log
+    # Add an endpoint to get the logs - (directly calling the FastAPI decorator)
     server.app.get("/log/")(retrieve_log)
+    server.app.get("/logfile/")(retrieve_log_from_file)
 
 
 def serve_from_cli(argv: Optional[list[str]] = None):
@@ -30,7 +31,16 @@ def serve_from_cli(argv: Optional[list[str]] = None):
         config = cli.config_from_args(args)
         server = cli.server_from_config(config)
         customise_server(server)
-        uvicorn.run(server.app, host=args.host, port=args.port)
+        uvicorn.run(
+            server.app,
+            host=args.host,
+            port=args.port,
+            log_config={
+                "version": 1,
+                "disable_existing_loggers": False,
+            },
+        )
+
     except BaseException as e:
         if args.fallback:
             print(f"Error: {e}")
@@ -40,6 +50,14 @@ def serve_from_cli(argv: Optional[list[str]] = None):
             app.labthings_config = config
             app.labthings_server = server
             app.labthings_error = e
-            uvicorn.run(app, host=args.host, port=args.port)
+            uvicorn.run(
+                app,
+                host=args.host,
+                port=args.port,
+                log_config={
+                    "version": 1,
+                    "disable_existing_loggers": False,
+                },
+            )
         else:
             raise e