Store logs as dict on server, and send as json, rather than regex from str

Closes #321

src/openflexure_microscope_server/logging.py

@@ -17,7 +17,8 @@ from logging.handlers import RotatingFileHandler
 from typing import Optional
 
 from fastapi import HTTPException
-from fastapi.responses import PlainTextResponse
+from fastapi.encoders import jsonable_encoder
+from fastapi.responses import JSONResponse, PlainTextResponse
 
 from labthings_fastapi.logs import inject_invocation_id
 
@@ -53,7 +54,7 @@ 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_HANDLER.setFormatter(OFMLogFileFormatter(ofm_format_str))
     OFM_HANDLER.addFilter(UvicornAccessFilter())
     OFM_HANDLER.level = root_logger.level
     root_logger.addHandler(OFM_HANDLER)
@@ -95,7 +96,7 @@ def retrieve_log() -> PlainTextResponse:
     All logs, including ``uvicorn.access`` are logged to the OFM_LOG_FILE (see above)
     this is the best place to get logs about crashes.
     """
-    return PlainTextResponse(OFM_HANDLER.log_history)
+    return JSONResponse(content=jsonable_encoder(OFM_HANDLER.log_history))
 
 
 def retrieve_log_from_file() -> PlainTextResponse:
@@ -157,21 +158,36 @@ class OFMHandler(logging.Handler):
         super().__init__(level=level)
         self._log: list[str] = []
         self._max_logs = max_logs
+        # start at -1 so first record is 0
+        self._running_counter = -1
+
+    def _as_record_dict(self, record: logging.LogRecord) -> dict:
+        """Format the record into the dictionary structure expected by the server."""
+        msg = record.message
+        self._running_counter += 1
+        return {
+            "timestamp": record.asctime,
+            "level": record.levelname,
+            "summary": msg.split("\n")[0],
+            "message": msg,
+            "sequence": self._running_counter,
+            "expanded": False,
+        }
 
     def append_record(self, record: logging.LogRecord) -> None:
-        """Format message and append it to a list of records.
+        """Append the record as a dictionary to a log of records.
-
-        The built in formatter is used to format the record.
 
         Any records in excess of the maximum number of logs are removed.
         """
-        self._log.append(self.format(record))
+        self._log.append(self._as_record_dict(record))
         while len(self._log) > self._max_logs:
             self._log.pop(0)
 
     def emit(self, record: logging.LogRecord) -> None:
         """Emit will save the logged record to the log."""
         try:
+            # Always format before trying to read or the attributes are not set.
+            self.format(record)
             if record.levelno >= self.level:
                 self.append_record(record)
         except RecursionError as e:
@@ -182,9 +198,9 @@ class OFMHandler(logging.Handler):
             self.handleError(record)
 
     @property
-    def log_history(self) -> str:
+    def log_history(self) -> list[dict]:
         """Return the log history up to the maximum number of logs."""
-        return "\n".join(self._log)
+        return list(reversed(self._log))
 
 
 class UvicornAccessFilter(logging.Filter):

tests/unit_tests/test_logging.py

@@ -1,5 +1,6 @@
 """Test the server's logging configuration and handling."""
 
+import json
 import logging
 import os
 import tempfile
@@ -8,7 +9,7 @@ from logging.handlers import RotatingFileHandler
 
 import pytest
 from fastapi import HTTPException
-from fastapi.responses import PlainTextResponse
+from fastapi.responses import JSONResponse, PlainTextResponse
 
 from openflexure_microscope_server import logging as ofm_logging
 
@@ -90,18 +91,18 @@ def test_max_logs():
         # But I would log five hundred times.
         for i in range(500):
             logging.info("log %s", i)
-        logs = ofm_logging.OFM_HANDLER.log_history.split("\n")
+        logs = ofm_logging.OFM_HANDLER.log_history
         assert len(logs) == 250
-        assert logs[0].endswith("log 250")
+        assert logs[-1]["message"] == "log 250"
-        assert logs[-1].endswith("log 499")
+        assert logs[0]["message"] == "log 499"
         # And I would log five hundred more.
         for i in range(500):
             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")
+        logs = ofm_logging.OFM_HANDLER.log_history
         assert len(logs) == 250
-        assert logs[0].endswith("log 750")
+        assert logs[-1]["message"] == "log 750"
-        assert logs[-1].endswith("log 999")
+        assert logs[0]["message"] == "log 999"
 
 
 def test_ofm_handler_ignores_uvicorn_access():
@@ -113,17 +114,17 @@ def test_ofm_handler_ignores_uvicorn_access():
     ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
     with tmp_logging_dir() as tmpdir:
         ofm_logging.configure_logging(tmpdir)
-        logs = ofm_logging.OFM_HANDLER.log_history.split("\n")
+        logs = ofm_logging.OFM_HANDLER.log_history
         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")
+        logs = ofm_logging.OFM_HANDLER.log_history
         assert len(logs) == starting_len + 2
-        assert logs[starting_len].endswith("Root 1")
+        assert logs[starting_len]["message"] == "Root 1"
-        assert logs[-1].endswith("Root 2")
+        assert logs[0]["message"] == "Root 2"
 
 
 def test_server_responses():
@@ -140,8 +141,10 @@ def test_server_responses():
         for i in range(500):
             logging.info("log %s", i)
         log_response = ofm_logging.retrieve_log()
-        assert isinstance(log_response, PlainTextResponse)
+        # Retrieve log should get a json that can be decoded into a list
-        logs = log_response.body.decode().split("\n")
+        assert isinstance(log_response, JSONResponse)
+        logs = json.loads(log_response.body.decode())
+        assert isinstance(logs, list)
         assert len(logs) == 250
         file_log_response = ofm_logging.retrieve_log_from_file()
         assert isinstance(file_log_response, PlainTextResponse)

webapp/src/components/tabContentComponents/loggingContent.vue

@@ -185,51 +185,8 @@ export default {
       }
     },
     async updateLogs() {
-      let response = await axios.get(this.logURI);
+      let logs = await axios.get(this.logURI);
-      let lines = response.data.split("\n");
+      this.logs = Object.values(logs.data);
-      let logs = [];
-      let regexp = /^\[(.+?)\] \[(DEBUG|INFO|WARNING|ERROR|CRITICAL)\] (.*)$/;
-      for (let line of lines) {
-        if (line.length > 0) {
-          let m = line.match(regexp);
-          if (m) {
-            logs.push({
-              timestamp: m[1],
-              level: m[2],
-              summary: m[3],
-              message: this.escapeText(m[3]),
-              sequence: logs.length,
-              expanded: false,
-            });
-          } else if (logs) {
-            // If a line does not look like a log entry, append it to the last
-            // log entry (i.e. allow multi-line messages)
-            let entry = logs[logs.length - 1];
-            m = line.match(/^( *)(\^+)/); // detect python stack trace "underlines"
-            if (m) {
-              let linestart = entry.message.lastIndexOf("\n") + 1;
-              let ustart = linestart + m[1].length;
-              let uend = ustart + m[2].length;
-              entry.message =
-                entry.message.substring(0, ustart) +
-                "<u>" +
-                entry.message.substring(ustart, uend) +
-                "</u>" +
-                entry.message.substring(uend);
-            } else {
-              entry.message += "\n" + this.escapeText(line);
-              if (entry.message.startsWith("Traceback")) {
-                entry.summary = line; // For tracebacks, the last line is the best summary
-              }
-            }
-          } else {
-            // if there's no existing log message to append to, discard lines
-            // until we find one.
-            continue;
-          }
-        }
-      }
-      this.logs = logs.reverse(); // Display in reverse chronological order
     },
     formatDateTime: function (isoDateTimeString) {
       isoDateTimeString = isoDateTimeString.replace(",", ".");