From 64ccb50f0f500fda5af30e25f3968dad3009218f Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Thu, 29 Feb 2024 12:31:04 +0100 Subject: [PATCH 1/3] Generalize usage of request correlation id to all integrations --- docs/changelog.rst | 8 +++++++ docs/django.rst | 19 ++++++++++++++- docs/fastapi.rst | 19 +++++++++++---- docs/flask.rst | 19 ++++++++++++++- docs/logging.rst | 15 +++++++++++- docs/sanic.rst | 18 +++++++++++++- setup.py | 2 +- src/dockerflow/django/middleware.py | 19 +++++++++++---- src/dockerflow/fastapi/__init__.py | 14 ----------- src/dockerflow/fastapi/middleware.py | 35 +++++++++++++++++++++++++--- src/dockerflow/flask/app.py | 24 +++++++++++++------ src/dockerflow/logging.py | 28 ++++++++++++++++++++++ src/dockerflow/sanic/app.py | 19 ++++++++++----- tests/django/test_django.py | 4 ++-- tests/fastapi/test_fastapi.py | 14 +++++++---- tests/flask/test_flask.py | 5 ++-- tests/requirements/fastapi.txt | 1 - tests/sanic/test_sanic.py | 6 ++--- 18 files changed, 213 insertions(+), 56 deletions(-) diff --git a/docs/changelog.rst b/docs/changelog.rst index 4ab2345..1590e7b 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -1,6 +1,14 @@ Changelog --------- +2024.2.1 +~~~~~~~~~~~~~~~~~~~~~ + +- Add request correlation ID support (#101). + In order to add a ``rid`` field to all log messages, add the ``dockerflow.logging.RequestIdLogFilter`` filter to your logging handlers. + See: :ref:`Django `, :ref:`FastAPI `, :ref:`Flask `, :ref:`Sanic ` for details. + + 2024.2.0 ~~~~~~~~~~~~~~~~~~~~~ diff --git a/docs/django.rst b/docs/django.rst index 7af44c5..6cad98b 100644 --- a/docs/django.rst +++ b/docs/django.rst @@ -386,11 +386,17 @@ configure **at least** the ``request.summary`` logger that way:: 'logger_name': 'myproject' } }, + 'filters': { + 'request_id': { + '()': 'dockerflow.logging.RequestIdFilter', + }, + }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', - 'formatter': 'json' + 'formatter': 'json', + 'filters': ['request_id'] }, }, 'loggers': { @@ -408,6 +414,17 @@ In order to include querystrings in the request summary log, set this flag in se DOCKERFLOW_SUMMARY_LOG_QUERYSTRING = True +A unique request ID is read from the `X-Request-ID` request header, and a UUID4 value is generated if unset. + +Leveraging the `RequestIdFilter` in logging configuration as shown above will add a ``rid`` attribute to all log messages. + +The header name to obtain the request ID can be customized in settings: + +.. code-block:: python + + DOCKERFLOW_REQUEST_ID_HEADER_NAME = "X-Cloud-Trace-Context" + + .. _django-static: Static content diff --git a/docs/fastapi.rst b/docs/fastapi.rst index 523bdc3..a701c50 100644 --- a/docs/fastapi.rst +++ b/docs/fastapi.rst @@ -29,6 +29,8 @@ The package ``dockerflow.fastapi`` package implements various tools to support For more information see the :doc:`API documentation ` for the ``dockerflow.fastapi`` module. +.. _fastapi-setup: + Setup ----- @@ -39,12 +41,12 @@ To install ``python-dockerflow``'s FastAPI support please follow these steps: from fastapi import FastAPI from dockerflow.fastapi import router - from dockerflow.fastapi.middleware import MozlogRequestSummaryLogger, CorrelationIdMiddleware + from dockerflow.fastapi.middleware import MozlogRequestSummaryLogger, RequestIdMiddleware app = FastAPI() app.include_router(router) app.add_middleware(MozlogRequestSummaryLogger) - app.add_middleware(CorrelationIdMiddleware) # see snok/asgi-correlation-id + app.add_middleware(RequestIdMiddleware) # see snok/asgi-correlation-id #. Make sure the app root path is set correctly as this will be used to locate the ``version.json`` file that is generated by @@ -298,7 +300,7 @@ for at least the ``request.summary`` logger: }, 'filters': { 'request_id': { - '()': 'dockerflow.fastapi.RequestIdFilter', + '()': 'dockerflow.logging.RequestIdFilter', }, }, 'handlers': { @@ -324,7 +326,16 @@ In order to include querystrings in the request summary log, set this flag in th app.state.DOCKERFLOW_SUMMARY_LOG_QUERYSTRING = True -A unique ID is added to each log message, using the `asgi-correlation-id `_ package and with the `RequestIdFilter` added in logging configuration as shown above. +A unique request ID is read from the `X-Request-ID` request header using the `RequestIdMiddleware` middleware (see :ref:`fastapi-setup`), and a UUID4 value is generated if unset. + +Leveraging the `RequestIdFilter` in logging configuration as shown above will add a ``rid`` attribute to all log messages. + +The header name to obtain the request ID can be customized in settings: + +.. code-block:: python + + app.state.DOCKERFLOW_REQUEST_ID_HEADER_NAME = "X-Cloud-Trace-Context" + .. _fastapi-static: diff --git a/docs/flask.rst b/docs/flask.rst index e4cb86e..292bfa4 100644 --- a/docs/flask.rst +++ b/docs/flask.rst @@ -441,11 +441,17 @@ for at least the ``request.summary`` logger:: 'logger_name': 'myproject' } }, + 'filters': { + 'request_id': { + '()': 'dockerflow.logging.RequestIdFilter', + }, + }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', - 'formatter': 'json' + 'formatter': 'json', + 'filters': ['request_id'] }, }, 'loggers': { @@ -460,6 +466,17 @@ In order to include querystrings in the request summary log, set this flag in :r DOCKERFLOW_SUMMARY_LOG_QUERYSTRING = True +A unique request ID is read from the `X-Request-ID` request header, and a UUID4 value is generated if unset. + +Leveraging the `RequestIdFilter` in logging configuration as shown above will add a ``rid`` attribute to all log messages. + +The header name to obtain the request ID can be customized in settings: + +.. code-block:: python + + DOCKERFLOW_REQUEST_ID_HEADER_NAME = "X-Cloud-Trace-Context" + + .. _flask-static: Static content diff --git a/docs/logging.rst b/docs/logging.rst index f295d35..1b6c255 100644 --- a/docs/logging.rst +++ b/docs/logging.rst @@ -39,11 +39,17 @@ this:: 'logger_name': 'myproject' } }, + 'filters': { + 'request_id': { + '()': 'dockerflow.logging.RequestIdFilter', + }, + }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', - 'formatter': 'json' + 'formatter': 'json', + 'filters': ['request_id'] }, }, 'loggers': { @@ -80,6 +86,12 @@ thing as the dictionary based configuratio above: [formatters] keys = json + [filters] + keys = request_id + + [filter_request_id] + class = dockerflow.logging.RequestIdFilter + [logger_root] level = INFO handlers = console @@ -94,6 +106,7 @@ thing as the dictionary based configuratio above: level = DEBUG args = (sys.stdout,) formatter = json + filters = request_id [formatter_json] class = dockerflow.logging.JsonLogFormatter diff --git a/docs/sanic.rst b/docs/sanic.rst index 00feb68..50e48d9 100644 --- a/docs/sanic.rst +++ b/docs/sanic.rst @@ -421,11 +421,17 @@ for at least the ``request.summary`` logger:: 'logger_name': 'myproject' } }, + 'filters': { + 'request_id': { + '()': 'dockerflow.logging.RequestIdFilter', + }, + }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', - 'formatter': 'json' + 'formatter': 'json', + 'filters': ['request_id'] }, }, 'loggers': { @@ -459,6 +465,16 @@ In order to include querystrings in the request summary log, set this flag in :r DOCKERFLOW_SUMMARY_LOG_QUERYSTRING = True +A unique request ID is read from the `X-Request-ID` request header, and a UUID4 value is generated if unset. + +Leveraging the `RequestIdFilter` in logging configuration as shown above will add a ``rid`` attribute to all log messages. + +The header name to obtain the request ID can be customized in settings: + +.. code-block:: python + + DOCKERFLOW_REQUEST_ID_HEADER_NAME = "X-Cloud-Trace-Context" + .. _sanic-static: diff --git a/setup.py b/setup.py index d26aac2..1c1c3cb 100644 --- a/setup.py +++ b/setup.py @@ -50,7 +50,7 @@ def read(*parts): "django": ["django"], "flask": ["flask", "blinker"], "sanic": ["sanic"], - "fastapi": ["fastapi", "asgiref", "asgi-correlation-id"], + "fastapi": ["fastapi", "asgiref"], }, zip_safe=False, python_requires=">=3.7,<4", diff --git a/src/dockerflow/django/middleware.py b/src/dockerflow/django/middleware.py index 8b20936..7a83ce7 100644 --- a/src/dockerflow/django/middleware.py +++ b/src/dockerflow/django/middleware.py @@ -2,14 +2,25 @@ import re import time import urllib -import uuid from django.conf import settings from django.utils.deprecation import MiddlewareMixin +from dockerflow.logging import get_or_generate_request_id, request_id_context + from . import views +def extract_request_id(request): + """Extract request ID from request.""" + rid = get_or_generate_request_id( + request.headers, + header_name=getattr(settings, "DOCKERFLOW_REQUEST_ID_HEADER_NAME", None), + ) + request_id_context.set(rid) + request._id = rid # Used in tests. + + class DockerflowMiddleware(MiddlewareMixin): """ Emits a request.summary type log entry for every request. @@ -33,7 +44,8 @@ def process_request(self, request): if pattern.match(request.path_info): return view(request) - request._id = str(uuid.uuid4()) + extract_request_id(request) + request._start_timestamp = time.time() return None @@ -56,8 +68,7 @@ def _build_extra_meta(self, request): # attributes before trying to use them. if hasattr(request, "user"): out["uid"] = request.user.is_authenticated and request.user.pk or "" - if hasattr(request, "_id"): - out["rid"] = request._id + out["rid"] = request_id_context.get() if hasattr(request, "_start_timestamp"): # Duration of request, in milliseconds. out["t"] = int(1000 * (time.time() - request._start_timestamp)) diff --git a/src/dockerflow/fastapi/__init__.py b/src/dockerflow/fastapi/__init__.py index 102279f..19596b0 100644 --- a/src/dockerflow/fastapi/__init__.py +++ b/src/dockerflow/fastapi/__init__.py @@ -1,6 +1,3 @@ -from logging import Filter, LogRecord - -from asgi_correlation_id import correlation_id from fastapi import APIRouter from fastapi.routing import APIRoute @@ -15,14 +12,3 @@ ], ) """This router adds the Dockerflow views.""" - - -class RequestIdLogFilter(Filter): - """Logging filter to attach request IDs to log records""" - - def filter(self, record: "LogRecord") -> bool: - """ - Attach the request ID to the log record. - """ - record.rid = correlation_id.get(None) - return True diff --git a/src/dockerflow/fastapi/middleware.py b/src/dockerflow/fastapi/middleware.py index dbf15c6..9096de9 100644 --- a/src/dockerflow/fastapi/middleware.py +++ b/src/dockerflow/fastapi/middleware.py @@ -6,7 +6,6 @@ import urllib from typing import Any, Dict -from asgi_correlation_id import CorrelationIdMiddleware, correlation_id # noqa from asgiref.typing import ( ASGI3Application, ASGIReceiveCallable, @@ -15,7 +14,37 @@ HTTPScope, ) -from ..logging import JsonLogFormatter +from ..logging import JsonLogFormatter, get_or_generate_request_id, request_id_context + + +class RequestIdMiddleware: + def __init__( + self, + app: ASGI3Application, + ) -> None: + self.app = app + + async def __call__( + self, scope: HTTPScope, receive: ASGIReceiveCallable, send: ASGISendCallable + ) -> None: + if scope["type"] != "http": + return await self.app(scope, receive, send) + + headers = {} + for name, value in scope["headers"]: + header_key = name.decode("latin1").lower() + header_val = value.decode("latin1") + headers[header_key] = header_val + + rid = get_or_generate_request_id( + headers, + header_name=getattr( + scope["app"].state, "DOCKERFLOW_REQUEST_ID_HEADER_NAME", None + ), + ) + request_id_context.set(rid) + + await self.app(scope, receive, send) class MozlogRequestSummaryLogger: @@ -75,7 +104,7 @@ def _format(self, scope: HTTPScope, info) -> Dict[str, Any]: "code": info["response"]["status"], "lang": info["request_headers"].get("accept-language"), "t": int(request_duration_ms), - "rid": correlation_id.get(), + "rid": request_id_context.get(), } if getattr(scope["app"].state, "DOCKERFLOW_SUMMARY_LOG_QUERYSTRING", False): diff --git a/src/dockerflow/flask/app.py b/src/dockerflow/flask/app.py index 49585cc..e747c2f 100644 --- a/src/dockerflow/flask/app.py +++ b/src/dockerflow/flask/app.py @@ -4,13 +4,13 @@ import logging import os import time -import uuid import warnings import flask from werkzeug.exceptions import InternalServerError from dockerflow import checks +from dockerflow.logging import get_or_generate_request_id, request_id_context from .. import version from .checks import ( @@ -39,6 +39,20 @@ class HeartbeatFailure(InternalServerError): pass +def extract_request_id(request): + """Extract request ID from request.""" + rid = get_or_generate_request_id( + flask.request.headers, + header_name=flask.current_app.config.get( + "DOCKERFLOW_REQUEST_ID_HEADER_NAME", None + ), + ) + request_id_context.set(rid) + flask.g._request_id = rid # For retro-compatibility and tests. + if not hasattr(flask.g, "request_id"): + flask.g.request_id = rid + + class Dockerflow(object): """ The Dockerflow Flask extension. Set it up like this: @@ -188,9 +202,7 @@ def _before_request(self): """ The before_request callback. """ - flask.g._request_id = str(uuid.uuid4()) - if not hasattr(flask.g, "request_id"): - flask.g.request_id = flask.g._request_id + extract_request_id(flask.request) flask.g._start_timestamp = time.time() def _after_request(self, response): @@ -269,9 +281,7 @@ def summary_extra(self): out["uid"] = user_id # the rid value to the current request ID - request_id = flask.g.get("_request_id", None) - if request_id is not None: - out["rid"] = request_id + out["rid"] = request_id_context.get() # and the t value to the time it took to render start_timestamp = flask.g.get("_start_timestamp", None) diff --git a/src/dockerflow/logging.py b/src/dockerflow/logging.py index 081d808..a6970b7 100644 --- a/src/dockerflow/logging.py +++ b/src/dockerflow/logging.py @@ -8,6 +8,9 @@ import socket import sys import traceback +import uuid +from contextvars import ContextVar +from typing import Optional class SafeJSONEncoder(json.JSONEncoder): @@ -153,3 +156,28 @@ def safer_format_traceback(exc_typ, exc_val, exc_tb): lines.append("%r\n" % (exc_typ,)) lines.append("%r\n" % (exc_val,)) return "".join(lines) + + +request_id_context: ContextVar[Optional[str]] = ContextVar("request_id", default=None) + + +def get_or_generate_request_id(headers: dict, header_name: Optional[str] = None) -> str: + """ + Read the request ID from the headers, and generate one if missing. + """ + header_name = header_name or "x-request-id" + rid = headers.get(header_name, "") + if not rid: + rid = str(uuid.uuid4()) + return rid + + +class RequestIdLogFilter(logging.Filter): + """Logging filter to attach request IDs to log records""" + + def filter(self, record: "logging.LogRecord") -> bool: + """ + Attach the request ID to the log record. + """ + record.rid = request_id_context.get(None) + return True diff --git a/src/dockerflow/sanic/app.py b/src/dockerflow/sanic/app.py index e970b03..6276b43 100644 --- a/src/dockerflow/sanic/app.py +++ b/src/dockerflow/sanic/app.py @@ -5,18 +5,28 @@ import logging import time import urllib -import uuid import warnings from inspect import isawaitable from sanic import response from dockerflow import checks +from dockerflow.logging import get_or_generate_request_id, request_id_context from .. import version from .checks import check_redis_connected +def extract_request_id(request): + """Extract request ID from request.""" + rid = get_or_generate_request_id( + request.headers, + header_name=request.app.config.get("DOCKERFLOW_REQUEST_ID_HEADER_NAME", None), + ) + request_id_context.set(rid) + request.ctx.id = rid # For retro-compatibility and tests. + + class Dockerflow(object): """ The Dockerflow Sanic extension. Set it up like this: @@ -122,6 +132,7 @@ def init_app(self, app): ("/__lbheartbeat__", "lbheartbeat", self._lbheartbeat_view), ): app.add_route(handler, uri, name="dockerflow." + name) + app.middleware("request")(extract_request_id) app.middleware("request")(self._request_middleware) app.middleware("response")(self._response_middleware) app.exception(Exception)(self._exception_handler) @@ -130,7 +141,6 @@ def _request_middleware(self, request): """ The request middleware. """ - request.ctx.id = str(uuid.uuid4()) request.ctx.start_timestamp = time.time() def _response_middleware(self, request, response): @@ -167,10 +177,7 @@ def summary_extra(self, request): out["querystring"] = urllib.parse.unquote(request.query_string) # the rid value to the current request ID - try: - out["rid"] = request.ctx.id - except AttributeError: - pass + out["rid"] = request_id_context.get() # and the t value to the time it took to render try: diff --git a/tests/django/test_django.py b/tests/django/test_django.py index 5464e97..c289861 100644 --- a/tests/django/test_django.py +++ b/tests/django/test_django.py @@ -214,8 +214,8 @@ def test_request_summary_failed_request( ): class HostileMiddleware(MiddlewareMixin): def process_request(self, request): - # simulating resetting request changes delattr(request, "_id") + # simulating resetting request changes delattr(request, "_start_timestamp") def process_response(self, request, response): @@ -228,7 +228,7 @@ def process_response(self, request, response): dockerflow_middleware.process_response(dockerflow_request, response) assert len(caplog.records) == 1 record = caplog.records[0] - assert getattr(record, "rid", None) is None + assert getattr(record, "rid", None) is not None assert getattr(record, "t", None) is None diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index d0815c7..b8f1bd2 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -1,6 +1,7 @@ # This Source Code Form is subject to the terms of the Mozilla Public # License, v. 2.0. If a copy of the MPL was not distributed with this # file, you can obtain one at http://mozilla.org/MPL/2.0/. +import io import json import logging @@ -9,19 +10,19 @@ from fastapi.testclient import TestClient from dockerflow import checks -from dockerflow.fastapi import RequestIdLogFilter from dockerflow.fastapi import router as dockerflow_router from dockerflow.fastapi.middleware import ( - CorrelationIdMiddleware, MozlogRequestSummaryLogger, + RequestIdMiddleware, ) +from dockerflow.logging import JsonLogFormatter, RequestIdLogFilter def create_app(): app = FastAPI() app.include_router(dockerflow_router) app.add_middleware(MozlogRequestSummaryLogger) - app.add_middleware(CorrelationIdMiddleware, validator=None) + app.add_middleware(RequestIdMiddleware) return app @@ -94,8 +95,11 @@ def test_mozlog_without_correlation_id_middleware(client, caplog): def test_request_id_passed_to_all_log_messages(caplog): - handler = logging.StreamHandler() + buffer = io.StringIO() + handler = logging.StreamHandler(stream=buffer) handler.addFilter(RequestIdLogFilter()) + handler.setFormatter(JsonLogFormatter()) + _logger = logging.getLogger("some_logger") _logger.addHandler(handler) @@ -111,8 +115,10 @@ def ping(): client.get("/ping") + parsed_log = json.parse(buffer.getvalue()) log_message = next(r for r in caplog.records if r.name == "some_logger") assert log_message.rid is not None + assert "rid" in parsed_log["Fields"] def test_mozlog_failure(client, mocker, caplog): diff --git a/tests/flask/test_flask.py b/tests/flask/test_flask.py index ac8f09a..03ff414 100644 --- a/tests/flask/test_flask.py +++ b/tests/flask/test_flask.py @@ -287,7 +287,6 @@ def test_request_summary(caplog, app, client, setup_request_summary_logger): caplog.set_level(logging.INFO) with app.test_request_context("/"): client.get("/", headers=headers) - assert getattr(g, "_request_id") is not None assert getattr(g, "request_id") is not None assert isinstance(getattr(g, "_start_timestamp"), float) @@ -398,14 +397,14 @@ def test_request_summary_failed_request(caplog, dockerflow, app): @app.before_request def hostile_callback(): - # simulating resetting request changes delattr(g, "_request_id") + # simulating resetting request changes delattr(g, "_start_timestamp") app.test_client().get("/", headers=headers) assert len(caplog.records) == 1 record = caplog.records[0] - assert getattr(record, "rid", None) is None + assert getattr(record, "rid", None) is not None assert getattr(record, "t", None) is None diff --git a/tests/requirements/fastapi.txt b/tests/requirements/fastapi.txt index 99cb858..18476e7 100644 --- a/tests/requirements/fastapi.txt +++ b/tests/requirements/fastapi.txt @@ -1,4 +1,3 @@ fastapi asgiref -asgi-correlation-id httpx \ No newline at end of file diff --git a/tests/sanic/test_sanic.py b/tests/sanic/test_sanic.py index 14ea640..5585e0e 100644 --- a/tests/sanic/test_sanic.py +++ b/tests/sanic/test_sanic.py @@ -286,12 +286,12 @@ def test_request_summary_failed_request( ): @app.middleware def hostile_callback(request): - # simulating resetting request changes del request.ctx.id + # simulating resetting request changes del request.ctx.start_timestamp - test_client.get(headers=headers) - assert_log_record(caplog, rid=None, t=None) + test_client.get(headers={"X-Request-ID": "tracked", **headers}) + assert_log_record(caplog, rid="tracked", t=None) def test_heartbeat_checks_legacy(dockerflow, test_client): From eab053ea78259398399fbaa10d0347d2e7a682a7 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Thu, 29 Feb 2024 16:17:52 +0100 Subject: [PATCH 2/3] Use json.loads() --- tests/fastapi/test_fastapi.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index b8f1bd2..5c90726 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -115,7 +115,7 @@ def ping(): client.get("/ping") - parsed_log = json.parse(buffer.getvalue()) + parsed_log = json.loads(buffer.getvalue()) log_message = next(r for r in caplog.records if r.name == "some_logger") assert log_message.rid is not None assert "rid" in parsed_log["Fields"] From af5cd2dee414a1be23c67a5f826aaa11f5f9682e Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Mon, 4 Mar 2024 10:57:53 +0100 Subject: [PATCH 3/3] Leverage caplog handler as suggested by @grahamalama --- tests/fastapi/test_fastapi.py | 12 +++--------- 1 file changed, 3 insertions(+), 9 deletions(-) diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index 8b7e1e3..3a496e1 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -1,7 +1,6 @@ # This Source Code Form is subject to the terms of the Mozilla Public # License, v. 2.0. If a copy of the MPL was not distributed with this # file, you can obtain one at http://mozilla.org/MPL/2.0/. -import io import json import logging @@ -95,13 +94,8 @@ def test_mozlog_without_correlation_id_middleware(client, caplog): def test_request_id_passed_to_all_log_messages(caplog): - buffer = io.StringIO() - handler = logging.StreamHandler(stream=buffer) - handler.addFilter(RequestIdLogFilter()) - handler.setFormatter(JsonLogFormatter()) - - _logger = logging.getLogger("some_logger") - _logger.addHandler(handler) + caplog.handler.addFilter(RequestIdLogFilter()) + caplog.handler.setFormatter(JsonLogFormatter()) app = create_app() @@ -115,9 +109,9 @@ def ping(): client.get("/ping") - parsed_log = json.loads(buffer.getvalue()) log_message = next(r for r in caplog.records if r.name == "some_logger") assert log_message.rid is not None + parsed_log = json.loads(caplog.text.splitlines()[0]) assert "rid" in parsed_log["Fields"]