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 7208ce4..6277032 100644 --- a/src/dockerflow/django/middleware.py +++ b/src/dockerflow/django/middleware.py @@ -3,14 +3,25 @@ import time import typing 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. @@ -34,7 +45,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 @@ -57,8 +69,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 567b64b..74e7f5b 100644 --- a/src/dockerflow/logging.py +++ b/src/dockerflow/logging.py @@ -8,7 +8,9 @@ import socket import sys import traceback -import typing +import uuid +from contextvars import ContextVar +from typing import ClassVar, Optional class SafeJSONEncoder(json.JSONEncoder): @@ -33,7 +35,7 @@ class JsonLogFormatter(logging.Formatter): LOGGING_FORMAT_VERSION = "2.0" # Map from Python logging to Syslog severity levels - SYSLOG_LEVEL_MAP: typing.ClassVar = { + SYSLOG_LEVEL_MAP: ClassVar = { 50: 2, # CRITICAL 40: 3, # ERROR 30: 4, # WARNING @@ -44,7 +46,7 @@ class JsonLogFormatter(logging.Formatter): # Syslog level to use when/if python level isn't found in map DEFAULT_SYSLOG_LEVEL = 7 - EXCLUDED_LOGRECORD_ATTRS: typing.ClassVar = set( + EXCLUDED_LOGRECORD_ATTRS: ClassVar = set( ( "args", "asctime", @@ -154,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 593798b..ee20bf2 100644 --- a/tests/django/test_django.py +++ b/tests/django/test_django.py @@ -215,8 +215,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): @@ -229,7 +229,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 79773bf..3a496e1 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 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,10 +94,8 @@ def test_mozlog_without_correlation_id_middleware(client, caplog): def test_request_id_passed_to_all_log_messages(caplog): - handler = logging.StreamHandler() - handler.addFilter(RequestIdLogFilter()) - _logger = logging.getLogger("some_logger") - _logger.addHandler(handler) + caplog.handler.addFilter(RequestIdLogFilter()) + caplog.handler.setFormatter(JsonLogFormatter()) app = create_app() @@ -113,6 +111,8 @@ def ping(): 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"] def test_mozlog_failure(client, mocker, caplog): diff --git a/tests/flask/test_flask.py b/tests/flask/test_flask.py index 857b6b4..26fb4b7 100644 --- a/tests/flask/test_flask.py +++ b/tests/flask/test_flask.py @@ -287,7 +287,6 @@ def test_request_summary(caplog, app, client): 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) @@ -399,14 +398,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 c07cde7..c274385 100644 --- a/tests/sanic/test_sanic.py +++ b/tests/sanic/test_sanic.py @@ -285,12 +285,12 @@ def exception_raiser(request): def test_request_summary_failed_request(app, caplog, test_client): @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):