diff --git a/docs/django.rst b/docs/django.rst index 7af44c5..1877c87 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,10 @@ 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 using the `RequestIdMiddleware` middleware (see :ref:`django-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. + .. _django-static: Static content diff --git a/docs/fastapi.rst b/docs/fastapi.rst index 523bdc3..ad5ffee 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,10 @@ 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. + .. _fastapi-static: diff --git a/docs/flask.rst b/docs/flask.rst index e4cb86e..5aa8c34 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,10 @@ 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 using the `RequestIdMiddleware` middleware (see :ref:`flask-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. + .. _flask-static: Static content diff --git a/docs/sanic.rst b/docs/sanic.rst index 00feb68..e51e76f 100644 --- a/docs/sanic.rst +++ b/docs/sanic.rst @@ -459,6 +459,10 @@ 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 using the `RequestIdMiddleware` middleware (see :ref:`django-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. + .. _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..3566675 100644 --- a/src/dockerflow/django/middleware.py +++ b/src/dockerflow/django/middleware.py @@ -2,11 +2,12 @@ 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 @@ -33,7 +34,10 @@ def process_request(self, request): if pattern.match(request.path_info): return view(request) - request._id = str(uuid.uuid4()) + rid = get_or_generate_request_id(request.headers) + request_id_context.set(rid) + request._id = rid # Used in tests. + request._start_timestamp = time.time() return None @@ -57,7 +61,7 @@ def _build_extra_meta(self, request): 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..ac0dc5a 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,30 @@ 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 + + request_id_context.set(get_or_generate_request_id(headers)) + await self.app(scope, receive, send) class MozlogRequestSummaryLogger: @@ -75,7 +97,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..2eb8e82 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 ( @@ -188,9 +188,12 @@ def _before_request(self): """ The before_request callback. """ - flask.g._request_id = str(uuid.uuid4()) + rid = get_or_generate_request_id(flask.request.headers) + 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 = flask.g._request_id + flask.g.request_id = rid + flask.g._start_timestamp = time.time() def _after_request(self, response): @@ -269,9 +272,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..8f24182 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,25 @@ 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) -> str: + header_name = "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..6f62391 100644 --- a/src/dockerflow/sanic/app.py +++ b/src/dockerflow/sanic/app.py @@ -5,13 +5,13 @@ 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 @@ -130,7 +130,9 @@ def _request_middleware(self, request): """ The request middleware. """ - request.ctx.id = str(uuid.uuid4()) + rid = get_or_generate_request_id(request.headers) + request_id_context.set(rid) + request.ctx.id = rid # For retro-compatibility and tests. request.ctx.start_timestamp = time.time() def _response_middleware(self, request, response): @@ -167,10 +169,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..0221937 100644 --- a/tests/django/test_django.py +++ b/tests/django/test_django.py @@ -215,7 +215,6 @@ def test_request_summary_failed_request( class HostileMiddleware(MiddlewareMixin): def process_request(self, request): # simulating resetting request changes - delattr(request, "_id") delattr(request, "_start_timestamp") def process_response(self, request, response): @@ -228,7 +227,6 @@ 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, "t", None) is None diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index d0815c7..319579e 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -9,19 +9,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 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 diff --git a/tests/flask/test_flask.py b/tests/flask/test_flask.py index ac8f09a..0d21b07 100644 --- a/tests/flask/test_flask.py +++ b/tests/flask/test_flask.py @@ -276,7 +276,7 @@ def assert_log_record(record, errno=0, level=logging.INFO): assert record.lang == "tlh" assert record.method == "GET" assert record.path == "/" - assert record.rid == g._request_id + assert record.rid == g.request_id assert isinstance(record.t, int) @@ -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) @@ -308,19 +307,6 @@ def test_request_summary_querystring(caplog, app, client, setup_request_summary_ assert record.querystring == "x=شكر" -def test_preserves_existing_request_id(dockerflow, app): - with app.test_client() as test_client: - - def set_dummy_request_id(): - g.request_id = "predefined-request-id" - - app.before_request(set_dummy_request_id) - - test_client.get("/", headers=headers) - assert getattr(g, "_request_id") is not None - assert getattr(g, "request_id") != getattr(g, "_request_id") - - def assert_user(app, caplog, user, callback): with app.test_request_context("/", headers=headers): assert has_request_context() @@ -399,13 +385,11 @@ def test_request_summary_failed_request(caplog, dockerflow, app): @app.before_request def hostile_callback(): # simulating resetting request changes - delattr(g, "_request_id") 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, "t", None) is None diff --git a/tests/requirements/default.txt b/tests/requirements/default.txt index d972249..92b0361 100644 --- a/tests/requirements/default.txt +++ b/tests/requirements/default.txt @@ -9,3 +9,4 @@ mock redis fakeredis jsonschema +asgi-correlation-id 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..1786663 100644 --- a/tests/sanic/test_sanic.py +++ b/tests/sanic/test_sanic.py @@ -287,11 +287,10 @@ def test_request_summary_failed_request( @app.middleware def hostile_callback(request): # simulating resetting request changes - del request.ctx.id del request.ctx.start_timestamp - test_client.get(headers=headers) - assert_log_record(caplog, rid=None, t=None) + request, _ = test_client.get(headers=headers) + assert_log_record(caplog, rid=request.ctx.id, t=None) def test_heartbeat_checks_legacy(dockerflow, test_client):