(fastapi) Log request ID when set in headers

[leplatrem]

I realized that tools like asgi-correlation-id for FastAPI add this header.

https://github.com/snok/asgi-correlation-id/blob/7665c31af175de194a8b1f051b71d25ea18c5187/asgi_correlation_id/middleware.py#L83-L86

However I don't really like it to be hard-coded, and would welcome any suggestion.

Option 0

This PR, hard-coded. But in the end, the header name X-Request-ID is almost like a defacto standard, and very unlikely to be customized.

Option 1

Include asgi-correlation-id by default as part of fastapi extras dependencies, and mention middleware in docs or introduce a dockerflow.setup(app) function that does all the cabling

Option 2

Introspect app.user_middleware list, and look for AsgiCorrelationMiddleware to read its header_name attribute
https://github.com/encode/starlette/blob/a4cd0b5506ac2fd3fa0ce1e967f019b94df87b97/starlette/applications.py#L142C14-L142C29

Option 3

Read header name from a constant in app.state dict...
(and let consumer app be responsible of setting it / aligning it with AsgiCorrelationMiddleware header_name param, etc.)

app.state.DOCKER_REQUEST_ID_HEADER_NAME = "X-Request-ID"
app.add_middleware(AsgiCorrelationMiddleware(header_name=app.state.DOCKER_REQUEST_ID_HEADER_NAME)

Option 4

?

[grahamalama]

Should we use setdefault, then build fields after that?

info["request_headers"].setdefault("x-request-id", uuid4())

fields = {
  ...,
  "rid": info["request_headers"]["x-request-id"]
}

[grahamalama]

X-Request-ID is almost like a defacto standard.

Almost, but it seems like Correlation-Id is common enough that it warrants a customization option here.

I like the idea of Option 1, whether we actually use asgi-correlation-id or maybe even roll our own version and ship it directly with python-dockerflow. It's really not that much code. I also wonder if it would end up being useful in the other integrations.

Options 2 feels brittle.

Option 3 looks pretty good too.

[leplatrem]

I also wonder if it would end up being useful in the other integrations.

There's already something in the other integrations:

python-dockerflow/src/dockerflow/sanic/app.py

Line 133 in c939637

request.ctx.id = str(uuid.uuid4())

python-dockerflow/src/dockerflow/flask/app.py

Line 191 in c939637

flask.g._request_id = str(uuid.uuid4())

python-dockerflow/src/dockerflow/django/middleware.py

Line 36 in c939637

request._id = str(uuid.uuid4())

but does not read it from a header that would be set by the reverse proxy (which is the ideal since it would be tracked along the whole stack)

I like the idea of Option 1

I also have a preference for Option 1, because in practice we will use this package in our services. And in the end, Option 3 consists in maintaining (and documenting) an abstraction that does not seem to bring much value

[codecov-commenter]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 98.02%. Comparing base (2ba0254) to head (a0efa7a).
Report is 3 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main     #100      +/-   ##
==========================================
+ Coverage   97.97%   98.02%   +0.05%     
==========================================
  Files          22       22              
  Lines         692      710      +18     
  Branches       92       96       +4     
==========================================
+ Hits          678      696      +18     
  Misses          8        8              
  Partials        6        6              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[grahamalama]

LGTM.

I don't know how valuable these tests would be (maybe only to validate our documentation) but I'm thinking:

• Is it okay for users to add MozlogRequestSummaryLogger without CorrelationIdMiddleware? If that happens, should we still try to get the X-Request-Id header for the rid field, or omit it? Whatever we decide, having a test that covers this possibility would be good.

• Can we set up a test that demonstrates the rid being passed down into the call stack? Something like:

(diff)

diff --git a/tests/fastapi/test_fastapi.py b/tests/fastapi/test_fastapi.py
index 7770441..e553b2d 100644
--- a/tests/fastapi/test_fastapi.py
+++ b/tests/fastapi/test_fastapi.py
@@ -15,12 +15,21 @@ from dockerflow.fastapi.middleware import (
     MozlogRequestSummaryLogger,
 )
 
+def pong():
+    logger = logging.getLogger("some_logger")
+    logger.info("returning pong")
+    return "pong"
 
 def create_app():
     app = FastAPI()
     app.include_router(dockerflow_router)
     app.add_middleware(MozlogRequestSummaryLogger)
     app.add_middleware(CorrelationIdMiddleware, validator=None)
+    
+    @app.get("/ping")
+    def ping():
+        return pong()
+    
     return app
 
 
@@ -160,3 +169,8 @@ def test_heartbeat_custom_name(client):
 
     response = client.get("/__heartbeat__")
     assert response.json()["checks"]["my_check_name"]
+
+def test_rid_passed_down(client, caplog):
+    client.get("/ping", headers={"X-Request-ID": "tracked-value"})
+    assert caplog.records[0].rid == "tracked-value"
+    assert caplog.records[1].rid == "tracked-value"

we might also have to wire up some logging config like we do with JBI (filter, adding the filter to the log config), but it would be good to have a full example documented