From 6b6707812937e5e7591bd28b9548bae0e8be71e1 Mon Sep 17 00:00:00 2001 From: Julian Stirling Date: Tue, 8 Apr 2025 16:35:34 +0100 Subject: [PATCH] Store logs as dict on server, and send as json, rather than regex from str Closes #321 --- src/openflexure_microscope_server/logging.py | 34 ++++++++++---- tests/unit_tests/test_logging.py | 29 +++++++----- .../tabContentComponents/loggingContent.vue | 47 +------------------ 3 files changed, 43 insertions(+), 67 deletions(-) diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index bbece763..7298985e 100644 --- a/src/openflexure_microscope_server/logging.py +++ b/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. - - 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 +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): diff --git a/tests/unit_tests/test_logging.py b/tests/unit_tests/test_logging.py index 76ae0f24..4479084f 100644 --- a/tests/unit_tests/test_logging.py +++ b/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) diff --git a/webapp/src/components/tabContentComponents/loggingContent.vue b/webapp/src/components/tabContentComponents/loggingContent.vue index deaffe4d..87d0f19a 100644 --- a/webapp/src/components/tabContentComponents/loggingContent.vue +++ b/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) + - "" + - entry.message.substring(ustart, uend) + - "" + - 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(",", ".");