Repository: CentOS/duffy (language: python)

Issue:
Create request ids and include them in log entries



Discussion / hints:

Fix patch:
diff --git a/duffy/app/logging.py b/duffy/app/logging.py
index fde9a579..59a0c4ff 100644
--- a/duffy/app/logging.py
+++ b/duffy/app/logging.py
@@ -1,9 +1,53 @@
+import uuid
+from collections import UserString
 from logging import Filter, LogRecord
+from typing import Any, Dict
 
 from .middleware import request_id_ctxvar
 
 
+class LazyShortRequestId(UserString):
+    def __init__(self, request_id: uuid.UUID) -> None:
+        self._request_id = request_id
+
+    def __str__(self) -> str:
+        if not hasattr(self, "_short"):
+            self._short = str(self._request_id)[-12:]
+        return self._short
+
+    @property
+    def data(self):
+        return self.__str__()
+
+
+class LazyFormattedString(UserString):
+    def __init__(self, fmt: str, **kwargs: Dict[str, Any]) -> None:
+        self._fmt = fmt
+        self._kwargs = kwargs
+
+    def __str__(self) -> str:
+        if not hasattr(self, "_formatted"):
+            self._formatted = self._fmt.format(**self._kwargs)
+        return self._formatted
+
+    @property
+    def data(self):
+        return self.__str__()
+
+
 class RequestIdFilter(Filter):
     def filter(self, record: LogRecord) -> bool:
-        record.request_id = request_id_ctxvar.get()
+        record.request_id = rid = request_id_ctxvar.get()
+
+        if rid:
+            # Use lazily evaluated objects here, so they’re only formatted when actually accessed.
+            record.short_request_id = srid = LazyShortRequestId(rid)
+
+            # Note the trailing spaces
+            record.request_id_optional = LazyFormattedString("[{rid}] ", rid=rid)
+            record.short_request_id_optional = LazyFormattedString("[{srid}] ", srid=srid)
+        else:
+            record.short_request_id = None
+            record.request_id_optional = record.short_request_id_optional = ""
+
         return True
diff --git a/pyproject.toml b/pyproject.toml
index 98edb998..0fda445a 100644
--- a/pyproject.toml
+++ b/pyproject.toml
@@ -105,6 +105,7 @@ client = ["httpx"]
 [tool.pytest.ini_options]
 addopts = "--black --cov-config .coveragerc --cov=duffy --cov-report term --cov-report xml --cov-report html --isort"
 asyncio_mode = "auto"
+log_format = "%(levelname)s: %(asctime)s %(short_request_id_optional)s(%(filename)s:%(lineno)s %(message)s)"
 
 [tool.isort]
 line_length = 100


Test patch:
diff --git a/tests/app/test_logging.py b/tests/app/test_logging.py
index ef07c942..9fb856ec 100644
--- a/tests/app/test_logging.py
+++ b/tests/app/test_logging.py
@@ -1,12 +1,43 @@
+import logging
 import uuid
 from unittest import mock
 
 import pytest
 
-from duffy.app import logging
+from duffy.app import logging as app_logging
 from duffy.app.middleware import request_id_ctxvar
 
 
+def test_lazy_short_request_id():
+    long_id = uuid.uuid4()
+
+    short_id = app_logging.LazyShortRequestId(long_id)
+
+    with mock.patch.object(app_logging, "str", wraps=str) as wrapped_str:
+        assert str(short_id) == short_id.data == str(long_id)[-12:]
+        wrapped_str.assert_called_once_with(long_id)
+
+        wrapped_str.reset_mock()
+
+        assert str(short_id) == short_id.data == str(long_id)[-12:]
+        wrapped_str.assert_not_called()
+
+
+def test_lazy_formatted_string():
+    foo = mock.Mock()
+    foo.__str__ = wrapped_str = mock.Mock(return_value="foo")
+
+    lazy_str = app_logging.LazyFormattedString("{foo}", foo=foo)
+
+    assert str(lazy_str) == lazy_str.data == "foo"
+    wrapped_str.assert_called_once_with()
+
+    wrapped_str.reset_mock()
+
+    assert str(lazy_str) == lazy_str.data == "foo"
+    wrapped_str.assert_not_called()
+
+
 class TestRequestIdFilter:
     @pytest.mark.parametrize("id_set", (True, False), ids=["id-set", "id-unset"])
     def test_filter(self, id_set):
@@ -18,10 +49,36 @@ def test_filter(self, id_set):
 
         record = mock.Mock()
 
-        retval = logging.RequestIdFilter().filter(record)
+        retval = app_logging.RequestIdFilter().filter(record)
 
         assert retval is True
         assert record.request_id is expected
 
         if id_set:
+            expected_short = str(expected)[-12:]
+            assert record.short_request_id == expected_short
+            assert record.request_id_optional == f"[{expected}] "
+            assert record.short_request_id_optional == f"[{expected_short}] "
             request_id_ctxvar.reset(token)
+        else:
+            assert record.short_request_id is None
+            assert record.request_id_optional == ""
+            assert record.short_request_id_optional == ""
+
+
+@pytest.mark.parametrize("id_set", (True, False), ids=["id-set", "id-unset"])
+def test_request_id_logged_in_tests(id_set, caplog):
+    if id_set:
+        expected = uuid.uuid4()
+        token = request_id_ctxvar.set(expected)
+    else:
+        expected = None
+
+    with caplog.at_level("DEBUG"):
+        logging.debug("BOO")
+
+    if id_set:
+        assert f" [{str(expected)[-12:]}] (" in caplog.text
+        request_id_ctxvar.reset(token)
+    else:
+        assert "[None]" not in caplog.text
diff --git a/tests/conftest.py b/tests/conftest.py
index 0324a536..b38d6569 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -12,6 +12,7 @@
 from sqlalchemy.engine.url import URL
 from sqlalchemy.ext.asyncio import create_async_engine
 
+from duffy.app.logging import RequestIdFilter
 from duffy.configuration import read_configuration
 from duffy.database import (
     Base,
@@ -293,3 +294,8 @@ class TestMechanism(Mechanism, mech_type="test"):
         pass
 
     return TestMechanism
+
+
+@pytest.fixture(autouse=True)
+def install_logging_request_id_filter(caplog):
+    caplog.handler.addFilter(RequestIdFilter())