Merge branch 'send-json-logs' into 'v3'

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

Closes #321

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

.gitignore

@@ -56,7 +56,6 @@ pytest_report.xml
 .coverage.picamera
 .coverage.main
 picamera_test_hashes.json
-webapp/src/tests/fixtures/*
 
 # Translations
 *.mo

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,8 +54,9 @@ 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.addFilter(inject_invocation_id)
     OFM_HANDLER.level = root_logger.level
     root_logger.addHandler(OFM_HANDLER)
 
@@ -84,7 +86,7 @@ def configure_logging(log_folder: str, debug: bool = False) -> None:
     )
 
 
-def retrieve_log() -> PlainTextResponse:
+def retrieve_log() -> JSONResponse:
     """Return logs since the server started, up to a maximum of 250 messages.
 
     This log is the one shown in the UI and on the logging page.
@@ -95,7 +97,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:
@@ -155,23 +157,39 @@ class OFMHandler(logging.Handler):
             how many can be returned over HTTP.
         """
         super().__init__(level=level)
-        self._log: list[str] = []
+        self._log: list[dict] = []
         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,
+            "invocation_id": getattr(record, "invocation_id", None),
+            "logger": record.name,
+            "sequence": self._running_counter,
+        }
 
     def append_record(self, record: logging.LogRecord) -> None:
-        """Format message and append it to a list of records.
-
-        The built in formatter is used to format the record.
+        """Append the record as a dictionary to a log of records.
 
         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 +200,24 @@ class OFMHandler(logging.Handler):
             self.handleError(record)
 
     @property
-    def log_history(self) -> str:
-        """Return the log history up to the maximum number of logs."""
-        return "\n".join(self._log)
+    def log_history(self) -> list[dict]:
+        """Return the log history up to the maximum number of logs.
+
+        Order is reversed so most recent logs are at the top.
+        """
+        return list(reversed(self._log))
+
+    @property
+    def get_formatted_log_history(self) -> str:
+        """Return the log history as a formatted string.
+
+        This is to be used for the fallback server, the formatting does not contain invocation
+        IDs as no actions should have started.
+        """
+        output = ""
+        for entry in self._log:
+            output += f"[{entry['timestamp']} [{entry['level']}] <{entry['logger']}> {entry['message']}\n"
+        return output
 
 
 class UvicornAccessFilter(logging.Filter):

src/openflexure_microscope_server/server/__init__.py

@@ -150,7 +150,7 @@ def serve_from_cli(argv: Optional[list[str]] = None) -> None:
             print(f"Error: {e}")  # noqa: T201
             print("Starting fallback server.")  # noqa: T201
             try:
-                log_history = OFM_HANDLER.log_history
+                log_history = OFM_HANDLER.get_formatted_log_history
             except BaseException:
                 # If log history fails for any reason carry on.
                 log_history = None

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].endswith("log 499")
+        assert logs[-1]["message"] == "log 250"
+        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].endswith("log 999")
+        assert logs[-1]["message"] == "log 750"
+        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[-1].endswith("Root 2")
+        assert logs[starting_len]["message"] == "Root 1"
+        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)
-        logs = log_response.body.decode().split("\n")
+        # Retrieve log should get a json that can be decoded into a list
+        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 lines = response.data.split("\n");
-      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
+      let logs = await axios.get(this.logURI);
+      this.logs = Object.values(logs.data);
     },
     formatDateTime: function (isoDateTimeString) {
       isoDateTimeString = isoDateTimeString.replace(",", ".");

webapp/src/tests/unit/LoggingContent.spec.js

@@ -3,8 +3,7 @@ import { describe, it, expect, vi, beforeEach } from "vitest";
 import { createTestingPinia } from "@pinia/testing";
 import { setActivePinia } from "pinia";
 import axios from "axios";
-import fs from "fs";
-import path from "path";
+import realLogs from "../fixtures/realLog.json";
 import LoggingContent from "../../components/tabContentComponents/loggingContent.vue";
 
 // Mock Axios
@@ -33,12 +32,10 @@ describe("Test LoggingContent.vue", () => {
   let wrapper;
 
   // Define path to a real log file and read it
-  const logFilePath = path.resolve(__dirname, "../fixtures/realLog.txt");
-  const mockLogData = fs.readFileSync(logFilePath, "utf-8");
+  const mockLogData = realLogs;
 
   // Things to do before each test
   beforeEach(async () => {
-    vi.useFakeTimers();
     // Reset mocks before each test
     vi.resetAllMocks();
 
@@ -69,8 +66,6 @@ describe("Test LoggingContent.vue", () => {
     });
     // flush so we avoid leaving uncompleted processes running on background
     await flushPromises();
-    vi.advanceTimersByTime(1000);
-    vi.useRealTimers();
   });
 
   // Tear down wrapper, unmount testing component
@@ -107,14 +102,11 @@ describe("Test LoggingContent.vue", () => {
 
     // Verify the logs have correct file length
     // Helps validate formatting, etc
-    expect(wrapper.vm.logs.length).toBe(5491);
+    expect(wrapper.vm.logs.length).toBe(113);
 
     // Check the most recent log
     expect(wrapper.vm.logs[0].level).toBe("INFO");
-
-    // Check if the multi-line file has real first connection information
-    expect(wrapper.vm.logs[0].message).toContain("uvicorn");
-    expect(wrapper.vm.logs[0].summary).toContain("http://0.0.0.0:5000");
+    expect(wrapper.vm.logs[0].logger).toContain("smart_scan");
   });
 
   // Test 3: Filter logging file information
@@ -124,19 +116,19 @@ describe("Test LoggingContent.vue", () => {
     // Set filter to WARNING wait and compare expected length
     wrapper.vm.filterLevel = "WARNING";
     await wrapper.vm.$nextTick();
-    expect(wrapper.vm.filteredItems.length).toBe(1449);
+    expect(wrapper.vm.filteredItems.length).toBe(5);
     expect(wrapper.vm.filteredItems[0].level).toBe("WARNING");
 
     // Set filter to INFO wait and compare expected length
     wrapper.vm.filterLevel = "INFO";
     await wrapper.vm.$nextTick();
-    expect(wrapper.vm.filteredItems.length).toBe(5491);
+    expect(wrapper.vm.filteredItems.length).toBe(113);
     expect(wrapper.vm.filteredItems[0].level).toBe("INFO");
 
     // Set filter to ERROR wait and compare expected length
     wrapper.vm.filterLevel = "ERROR";
     await wrapper.vm.$nextTick();
-    expect(wrapper.vm.filteredItems.length).toBe(7);
+    expect(wrapper.vm.filteredItems.length).toBe(1);
     expect(wrapper.vm.filteredItems[0].level).toBe("ERROR");
   });