JSON Format for Logging (#446)

neuro_logging/__init__.py

@@ -1,8 +1,11 @@
 import logging
 import logging.config
+import os
 import typing as t
 from importlib.metadata import version
 
+from pythonjsonlogger.orjson import OrjsonFormatter
+
 from .config import EnvironConfigFactory
 from .trace import (
     new_sampled_trace,
@@ -54,11 +57,28 @@ def filter(self, record: logging.LogRecord) -> bool:
         return record.getMessage().find(self.url_path) == -1
 
 
-DEFAULT_CONFIG = {
+BASE_CONFIG = {
     "version": 1,
     "disable_existing_loggers": False,
     "formatters": {
-        "standard": {"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"}
+        "standard": {"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"},
+        "json": {
+            "()": OrjsonFormatter,
+            "reserved_attrs": [
+                "created",
+                "exc_text",
+                "levelno",
+                "msecs",
+                "msg",
+                "relativeCreated",
+            ],
+            "rename_fields": {
+                "name": "logName",
+                "levelname": "severity",
+                "extra": "jsonPayload",
+            },
+            "timestamp": True,
+        },
     },
     "filters": {
         "hide_errors": {"()": AllowLessThanFilter, "level": "ERROR"},
@@ -78,10 +98,12 @@ def filter(self, record: logging.LogRecord) -> bool:
             "formatter": "standard",
             "stream": "ext://sys.stderr",
         },
-    },
-    "root": {
-        "level": logging.DEBUG,
-        "handlers": ["stderr", "stdout"],
+        "json": {
+            "class": "logging.StreamHandler",
+            "level": "DEBUG",
+            "formatter": "json",
+            "stream": "ext://sys.stdout",
+        },
     },
     "loggers": {
         "aiohttp.access": {
@@ -98,14 +120,34 @@ def filter(self, record: logging.LogRecord) -> bool:
 }
 
 
+TEXT_CONFIG = BASE_CONFIG | {
+    "root": {
+        "level": logging.DEBUG,
+        "handlers": ["stderr", "stdout"],
+    },
+}
+
+JSON_CONFIG = BASE_CONFIG | {
+    "root": {
+        "level": logging.DEBUG,
+        "handlers": ["json"],
+    },
+}
+
+
 def init_logging(
     *,
     health_check_url_path: str = "/api/v1/ping",
 ) -> None:
     config = EnvironConfigFactory().create_logging()
-    dict_config: dict[str, t.Any] = DEFAULT_CONFIG.copy()
+    if "PYTEST_VERSION" in os.environ:
+        config_template = TEXT_CONFIG
+    else:
+        config_template = JSON_CONFIG
+    dict_config: dict[str, t.Any] = config_template.copy()
     dict_config["root"]["level"] = config.log_level
     if config.log_health_check:
         dict_config["loggers"].pop("aiohttp.access", None)
+        dict_config["loggers"].pop("uvicorn.access", None)
     dict_config["filters"]["hide_health_checks"]["url_path"] = health_check_url_path
     logging.config.dictConfig(dict_config)

requirements-test.txt

@@ -1,4 +1,5 @@
 -e .
+dirty-equals==0.8.0
 mypy==1.14.0
 mypy-extensions==1.0.0
 pre-commit==4.0.1

setup.cfg

@@ -16,6 +16,8 @@ include_package_data = True
 packages = find:
 install_requires =
     aiohttp>=3.8,<4.0
+    orjson>=3.10.12
+    python-json-logger>=3.2.1
     sentry-sdk>=2.19.2,<2.20
 
 [flake8]

tests/test_logging.py

@@ -1,9 +1,12 @@
+import json
 import logging
 import os
 import re
 from typing import Any
+from unittest import mock
 
 import pytest
+from dirty_equals import IsList, IsNow, IsPartialDict, IsPositiveInt, IsStr
 
 from neuro_logging import AllowLessThanFilter, init_logging
 
@@ -92,3 +95,131 @@ def test_existing_loggers_continue_work(capsys: Any) -> None:
     captured = capsys.readouterr()
     assert "InfoMessage" in captured.out
     assert "ErrorMessage" in captured.err
+
+
+def test_json_logging_with_extra(capsys: Any, monkeypatch: Any) -> None:
+    monkeypatch.delenv("PYTEST_VERSION")
+    init_logging()
+    logging.debug("msg", extra={"key": "first"})
+    captured = capsys.readouterr()
+    assert not captured.err
+    msg = json.loads(captured.out)
+    assert msg == IsPartialDict(
+        {
+            "args": [],
+            "exc_info": None,
+            "filename": "test_logging.py",
+            "funcName": "test_json_logging_with_extra",
+            "key": "first",
+            "lineno": IsPositiveInt(),
+            "logName": "root",
+            "message": "msg",
+            "module": "test_logging",
+            "pathname": mock.ANY,
+            "process": IsPositiveInt(),
+            "processName": "MainProcess",
+            "severity": "DEBUG",
+            "stack_info": None,
+            "thread": IsPositiveInt(),
+            "threadName": "MainThread",
+            "timestamp": mock.ANY,
+        }
+    )
+
+
+def test_json_logging_with_args(capsys: Any, monkeypatch: Any) -> None:
+    monkeypatch.delenv("PYTEST_VERSION")
+    init_logging()
+    logging.debug("%s msg", "arg")
+    captured = capsys.readouterr()
+    assert not captured.err
+    msg = json.loads(captured.out)
+    assert msg == IsPartialDict(
+        {
+            "args": ["arg"],
+            "exc_info": None,
+            "filename": "test_logging.py",
+            "funcName": "test_json_logging_with_args",
+            "lineno": IsPositiveInt(),
+            "logName": "root",
+            "message": "arg msg",
+            "module": "test_logging",
+            "pathname": mock.ANY,
+            "process": IsPositiveInt(),
+            "processName": "MainProcess",
+            "severity": "DEBUG",
+            "stack_info": None,
+            "thread": IsPositiveInt(),
+            "threadName": "MainThread",
+            "timestamp": IsNow(tz="UTC", iso_string=True),
+        }
+    )
+
+
+def test_json_logging_with_exc_info(capsys: Any, monkeypatch: Any) -> None:
+    monkeypatch.delenv("PYTEST_VERSION")
+    init_logging()
+    try:
+        1 / 0
+    except ZeroDivisionError:
+        logging.debug("%s msg", "arg", exc_info=True)
+    captured = capsys.readouterr()
+    assert not captured.err
+    msg = json.loads(captured.out)
+    assert msg == IsPartialDict(
+        {
+            "args": ["arg"],
+            "exc_info": IsList(
+                "ZeroDivisionError",
+                "ZeroDivisionError: division by zero",
+                length=3,
+            ),
+            "filename": "test_logging.py",
+            "funcName": "test_json_logging_with_exc_info",
+            "lineno": IsPositiveInt(),
+            "logName": "root",
+            "message": "arg msg",
+            "module": "test_logging",
+            "pathname": mock.ANY,
+            "process": IsPositiveInt(),
+            "processName": "MainProcess",
+            "severity": "DEBUG",
+            "stack_info": None,
+            "thread": IsPositiveInt(),
+            "threadName": "MainThread",
+            "timestamp": IsNow(tz="UTC", iso_string=True),
+        }
+    )
+
+
+def test_json_logging_with_stack_info(capsys: Any, monkeypatch: Any) -> None:
+    monkeypatch.delenv("PYTEST_VERSION")
+    init_logging()
+    logging.debug("%s msg", "arg", stack_info=True)
+    captured = capsys.readouterr()
+    assert not captured.err
+    msg = json.loads(captured.out)
+    import pprint
+
+    pprint.pprint(msg)
+    assert msg == IsPartialDict(
+        {
+            "args": ["arg"],
+            "exc_info": None,
+            "filename": "test_logging.py",
+            "funcName": "test_json_logging_with_stack_info",
+            "lineno": IsPositiveInt(),
+            "logName": "root",
+            "message": "arg msg",
+            "module": "test_logging",
+            "pathname": mock.ANY,
+            "process": IsPositiveInt(),
+            "processName": "MainProcess",
+            "severity": "DEBUG",
+            "stack_info": IsStr(),
+            "thread": IsPositiveInt(),
+            "threadName": "MainThread",
+            "timestamp": IsNow(tz="UTC", iso_string=True),
+        }
+    )
+    assert msg["stack_info"].startswith("Stack (most recent call last):\n")