From 5d41b2b0a61c78c8ccee2fb4f23e93ed53775ea3 Mon Sep 17 00:00:00 2001 From: Kim Gustyr Date: Wed, 29 May 2024 11:29:55 +0100 Subject: [PATCH 1/3] fix: Setting LOG_FORMAT: json does not write stack traces to logs --- api/tests/unit/util/test_logging.py | 80 ++++++++++++++++++++++------- api/util/logging.py | 5 +- 2 files changed, 65 insertions(+), 20 deletions(-) diff --git a/api/tests/unit/util/test_logging.py b/api/tests/unit/util/test_logging.py index 2e85a7eb2f10..87fc20d69672 100644 --- a/api/tests/unit/util/test_logging.py +++ b/api/tests/unit/util/test_logging.py @@ -1,28 +1,70 @@ import json import logging +import os + +import pytest from util.logging import JsonFormatter -def test_json_formatter__outputs_expected(): +@pytest.fixture +def inspecting_handler() -> logging.Handler: + class InspectingHandler(logging.Handler): + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + self.messages = [] + + def handle(self, record): + self.messages.append(self.format(record)) + + return InspectingHandler() + + +@pytest.mark.freeze_time("2023-12-08T06:05:47.320000+00:00") +def test_json_formatter__outputs_expected(inspecting_handler: logging.Handler) -> None: + # Given json_formatter = JsonFormatter() - log_record = logging.LogRecord( - name="test_logger", - level=logging.INFO, - pathname="test.py", - lineno=42, - msg="This is a test message with args: %s and %s", - args=("arg1", "arg2"), - exc_info=None, + inspecting_handler.setFormatter(json_formatter) + logger = logging.getLogger("test_json_formatter__outputs_expected") + logger.addHandler(inspecting_handler) + logger.setLevel(logging.INFO) + + expected_pid = os.getpid() + expected_tb_string = ( + "Traceback (most recent call last):\n" + ' File "/Users/kgustyr/dev/flagsmith/flagsmith/api/tests/unit/util/test_logging.py",' + " line 43, in _log_traceback\n" + " raise Exception()\nException" ) - formatted_message = json_formatter.format(log_record) - json_message = json.loads(formatted_message) - - assert "levelname" in json_message - assert "message" in json_message - assert "timestamp" in json_message - assert "logger_name" in json_message - assert "process_id" in json_message - assert "thread_name" in json_message - assert json_message["message"] == "This is a test message with args: arg1 and arg2" + + def _log_traceback() -> None: + try: + raise Exception() + except Exception as exc: + logger.error("this is an error", exc_info=exc) + + # When + logger.info("hello") + _log_traceback() + + # Then + assert [json.loads(message) for message in inspecting_handler.messages] == [ + { + "levelname": "INFO", + "message": "hello", + "timestamp": "2023-12-08 06:05:47,319", + "logger_name": "test_json_formatter__outputs_expected", + "process_id": expected_pid, + "thread_name": "MainThread", + }, + { + "levelname": "ERROR", + "message": "this is an error", + "timestamp": "2023-12-08 06:05:47,319", + "logger_name": "test_json_formatter__outputs_expected", + "process_id": expected_pid, + "thread_name": "MainThread", + "exc_info": expected_tb_string, + }, + ] diff --git a/api/util/logging.py b/api/util/logging.py index 32a81d08b2e1..27aa7117abf9 100644 --- a/api/util/logging.py +++ b/api/util/logging.py @@ -14,7 +14,7 @@ class JsonFormatter(logging.Formatter): def get_json_record(self, record: logging.LogRecord) -> dict[str, Any]: formatted_message = record.getMessage() - return { + json_record = { "levelname": record.levelname, "message": formatted_message, "timestamp": self.formatTime(record, self.datefmt), @@ -22,6 +22,9 @@ def get_json_record(self, record: logging.LogRecord) -> dict[str, Any]: "process_id": record.process, "thread_name": record.threadName, } + if record.exc_info: + json_record["exc_info"] = self.formatException(record.exc_info) + return json_record def format(self, record: logging.LogRecord) -> str: try: From 0b63cba627599adf7c92d4d3f29716678a0ef34f Mon Sep 17 00:00:00 2001 From: Kim Gustyr Date: Wed, 29 May 2024 11:34:13 +0100 Subject: [PATCH 2/3] add logger args --- api/tests/unit/util/test_logging.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/api/tests/unit/util/test_logging.py b/api/tests/unit/util/test_logging.py index 87fc20d69672..0f750ff47cc6 100644 --- a/api/tests/unit/util/test_logging.py +++ b/api/tests/unit/util/test_logging.py @@ -45,14 +45,14 @@ def _log_traceback() -> None: logger.error("this is an error", exc_info=exc) # When - logger.info("hello") + logger.info("hello %s, %d", "arg1", 22.22) _log_traceback() # Then assert [json.loads(message) for message in inspecting_handler.messages] == [ { "levelname": "INFO", - "message": "hello", + "message": "hello arg1, 22", "timestamp": "2023-12-08 06:05:47,319", "logger_name": "test_json_formatter__outputs_expected", "process_id": expected_pid, From 5b47ebb54ff2d272cfb00fb342f0a4897412a292 Mon Sep 17 00:00:00 2001 From: Kim Gustyr Date: Wed, 29 May 2024 14:55:38 +0100 Subject: [PATCH 3/3] Fix path --- api/tests/unit/util/test_logging.py | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/api/tests/unit/util/test_logging.py b/api/tests/unit/util/test_logging.py index 0f750ff47cc6..d8c31a19f9f3 100644 --- a/api/tests/unit/util/test_logging.py +++ b/api/tests/unit/util/test_logging.py @@ -21,7 +21,10 @@ def handle(self, record): @pytest.mark.freeze_time("2023-12-08T06:05:47.320000+00:00") -def test_json_formatter__outputs_expected(inspecting_handler: logging.Handler) -> None: +def test_json_formatter__outputs_expected( + inspecting_handler: logging.Handler, + request: pytest.FixtureRequest, +) -> None: # Given json_formatter = JsonFormatter() @@ -31,10 +34,11 @@ def test_json_formatter__outputs_expected(inspecting_handler: logging.Handler) - logger.setLevel(logging.INFO) expected_pid = os.getpid() + expected_module_path = os.path.abspath(request.path) expected_tb_string = ( "Traceback (most recent call last):\n" - ' File "/Users/kgustyr/dev/flagsmith/flagsmith/api/tests/unit/util/test_logging.py",' - " line 43, in _log_traceback\n" + f' File "{expected_module_path}",' + " line 47, in _log_traceback\n" " raise Exception()\nException" )