From 953521c1eaf5765330a5c706030026d0951e18dc Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Thu, 22 Feb 2024 18:51:27 +0100 Subject: [PATCH 1/4] (fastapi) Log request ID when set in headers --- src/dockerflow/fastapi/middleware.py | 9 ++++++++- tests/fastapi/test_fastapi.py | 12 ++++++++++++ 2 files changed, 20 insertions(+), 1 deletion(-) diff --git a/src/dockerflow/fastapi/middleware.py b/src/dockerflow/fastapi/middleware.py index 9be8b45..2a6a883 100644 --- a/src/dockerflow/fastapi/middleware.py +++ b/src/dockerflow/fastapi/middleware.py @@ -66,7 +66,7 @@ def _format(self, scope: HTTPScope, info) -> Dict[str, Any]: info["request_headers"][header_key] = header_val request_duration_ms = (info["end_time"] - info["start_time"]) * 1000.0 - return { + fields = { "agent": info["request_headers"].get("user-agent", ""), "path": scope["path"], "method": scope["method"], @@ -74,3 +74,10 @@ def _format(self, scope: HTTPScope, info) -> Dict[str, Any]: "lang": info["request_headers"].get("accept-language"), "t": int(request_duration_ms), } + try: + # Log the request ID if it's set by the reverse proxy + # or by a library like `asgi-correlation-id`. + fields["rid"] = info["request_headers"]["x-request-id"] + except KeyError: + pass + return fields diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index 4b14775..ed03924 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -61,6 +61,18 @@ def test_mozlog(client, caplog): assert isinstance(record.t, int) +def test_mozlog_request_id(client, caplog): + client.get( + "/__lbheartbeat__", + headers={ + "X-Request-ID": "tracked-value", + }, + ) + record = caplog.records[0] + + assert record.rid == "tracked-value" + + def test_mozlog_failure(client, mocker, caplog): mocker.patch( "dockerflow.fastapi.views.get_version", side_effect=ValueError("crash") From a0efa7ab3b1f712865d16a41b4de64b756e7e34d Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Tue, 27 Feb 2024 13:13:39 +0100 Subject: [PATCH 2/4] Implement option 1 --- docs/fastapi.rst | 3 ++- setup.py | 2 +- src/dockerflow/fastapi/middleware.py | 11 +++-------- tests/fastapi/test_fastapi.py | 6 +++++- tests/requirements/fastapi.txt | 1 + 5 files changed, 12 insertions(+), 11 deletions(-) diff --git a/docs/fastapi.rst b/docs/fastapi.rst index 9f15112..e2bfa8a 100644 --- a/docs/fastapi.rst +++ b/docs/fastapi.rst @@ -39,11 +39,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 + from dockerflow.fastapi.middleware import MozlogRequestSummaryLogger, CorrelationIdMiddleware app = FastAPI() app.include_router(router) app.add_middleware(MozlogRequestSummaryLogger) + app.add_middleware(CorrelationIdMiddleware) #. Make sure the app root path is set correctly as this will be used to locate the ``version.json`` file that is generated by diff --git a/setup.py b/setup.py index 1c1c3cb..d26aac2 100644 --- a/setup.py +++ b/setup.py @@ -50,7 +50,7 @@ def read(*parts): "django": ["django"], "flask": ["flask", "blinker"], "sanic": ["sanic"], - "fastapi": ["fastapi", "asgiref"], + "fastapi": ["fastapi", "asgiref", "asgi-correlation-id"], }, zip_safe=False, python_requires=">=3.7,<4", diff --git a/src/dockerflow/fastapi/middleware.py b/src/dockerflow/fastapi/middleware.py index 2a6a883..e24eab8 100644 --- a/src/dockerflow/fastapi/middleware.py +++ b/src/dockerflow/fastapi/middleware.py @@ -5,6 +5,7 @@ import time from typing import Any, Dict +from asgi_correlation_id import CorrelationIdMiddleware, correlation_id # noqa from asgiref.typing import ( ASGI3Application, ASGIReceiveCallable, @@ -66,18 +67,12 @@ def _format(self, scope: HTTPScope, info) -> Dict[str, Any]: info["request_headers"][header_key] = header_val request_duration_ms = (info["end_time"] - info["start_time"]) * 1000.0 - fields = { + return { "agent": info["request_headers"].get("user-agent", ""), "path": scope["path"], "method": scope["method"], "code": info["response"]["status"], "lang": info["request_headers"].get("accept-language"), "t": int(request_duration_ms), + "rid": correlation_id.get(), } - try: - # Log the request ID if it's set by the reverse proxy - # or by a library like `asgi-correlation-id`. - fields["rid"] = info["request_headers"]["x-request-id"] - except KeyError: - pass - return fields diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index ed03924..7770441 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -10,13 +10,17 @@ from dockerflow import checks from dockerflow.fastapi import router as dockerflow_router -from dockerflow.fastapi.middleware import MozlogRequestSummaryLogger +from dockerflow.fastapi.middleware import ( + CorrelationIdMiddleware, + MozlogRequestSummaryLogger, +) def create_app(): app = FastAPI() app.include_router(dockerflow_router) app.add_middleware(MozlogRequestSummaryLogger) + app.add_middleware(CorrelationIdMiddleware, validator=None) return app diff --git a/tests/requirements/fastapi.txt b/tests/requirements/fastapi.txt index 18476e7..99cb858 100644 --- a/tests/requirements/fastapi.txt +++ b/tests/requirements/fastapi.txt @@ -1,3 +1,4 @@ fastapi asgiref +asgi-correlation-id httpx \ No newline at end of file From 3919aa891eb874b58e401f8eb5dbfd49643e43f3 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Tue, 27 Feb 2024 16:33:52 +0100 Subject: [PATCH 3/4] Add mention in docs --- docs/fastapi.rst | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/docs/fastapi.rst b/docs/fastapi.rst index e2bfa8a..9b79bf0 100644 --- a/docs/fastapi.rst +++ b/docs/fastapi.rst @@ -44,7 +44,7 @@ To install ``python-dockerflow``'s FastAPI support please follow these steps: app = FastAPI() app.include_router(router) app.add_middleware(MozlogRequestSummaryLogger) - app.add_middleware(CorrelationIdMiddleware) + app.add_middleware(CorrelationIdMiddleware) # 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 @@ -308,6 +308,9 @@ for at least the ``request.summary`` logger: } }) + +A unique ID is added to each log message, using the `asgi-correlation-id `_ package. + .. _fastapi-static: Static content From 3839c1b25e21da9b2d719da49901ddd70ad8ff54 Mon Sep 17 00:00:00 2001 From: Mathieu Leplatre Date: Wed, 28 Feb 2024 16:26:58 +0100 Subject: [PATCH 4/4] Add and document a logging filter --- docs/fastapi.rst | 6 +++++ src/dockerflow/fastapi/__init__.py | 14 ++++++++++++ tests/fastapi/test_fastapi.py | 35 ++++++++++++++++++++++++++++++ 3 files changed, 55 insertions(+) diff --git a/docs/fastapi.rst b/docs/fastapi.rst index 9b79bf0..fe21a90 100644 --- a/docs/fastapi.rst +++ b/docs/fastapi.rst @@ -293,10 +293,16 @@ for at least the ``request.summary`` logger: 'logger_name': 'myproject' } }, + 'filters': { + 'request_id': { + '()': 'dockerflow.fastapi.RequestIdFilter', + }, + }, 'handlers': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', + 'filters': ['request_id'], 'formatter': 'json' }, }, diff --git a/src/dockerflow/fastapi/__init__.py b/src/dockerflow/fastapi/__init__.py index 19596b0..102279f 100644 --- a/src/dockerflow/fastapi/__init__.py +++ b/src/dockerflow/fastapi/__init__.py @@ -1,3 +1,6 @@ +from logging import Filter, LogRecord + +from asgi_correlation_id import correlation_id from fastapi import APIRouter from fastapi.routing import APIRoute @@ -12,3 +15,14 @@ ], ) """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/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py index 7770441..5d5fbb8 100644 --- a/tests/fastapi/test_fastapi.py +++ b/tests/fastapi/test_fastapi.py @@ -9,6 +9,7 @@ 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, @@ -77,6 +78,40 @@ def test_mozlog_request_id(client, caplog): assert record.rid == "tracked-value" +def test_mozlog_without_correlation_id_middleware(client, caplog): + app = FastAPI() + app.include_router(dockerflow_router) + app.add_middleware(MozlogRequestSummaryLogger) + client = TestClient(app) + + client.get("/__lbheartbeat__") + record = caplog.records[0] + + assert record.rid is None + + +def test_request_id_passed_to_all_log_messages(caplog): + handler = logging.StreamHandler() + handler.addFilter(RequestIdLogFilter()) + _logger = logging.getLogger("some_logger") + _logger.addHandler(handler) + + app = create_app() + + @app.get("/ping") + def ping(): + logger = logging.getLogger("some_logger") + logger.info("returning pong") + return "pong" + + client = TestClient(app) + + client.get("/ping") + + log_message = next(r for r in caplog.records if r.name == "some_logger") + assert log_message.rid is not None + + def test_mozlog_failure(client, mocker, caplog): mocker.patch( "dockerflow.fastapi.views.get_version", side_effect=ValueError("crash")