Fix #344: add request id to logs (#398)

* Fix #344: add request id to logs

* @grahamalama review

Author: leplatrem

jbi/app.py

@@ -4,6 +4,7 @@
 import logging
 import time
 from pathlib import Path
+from secrets import token_hex
 from typing import Any, Awaitable, Callable
 
 import sentry_sdk
@@ -47,6 +48,16 @@ def traces_sampler(sampling_context: dict[str, Any]) -> float:
 app.mount("/static", StaticFiles(directory=SRC_DIR / "static"), name="static")
 
 
+@app.middleware("http")
+async def request_id(
+    request: Request, call_next: Callable[[Request], Awaitable[Response]]
+) -> Response:
+    """Read the request id from headers. This is set by NGinx."""
+    request.state.rid = request.headers.get("X-Request-Id", token_hex(16))
+    response = await call_next(request)
+    return response
+
+
 @app.middleware("http")
 async def request_summary(
     request: Request, call_next: Callable[[Request], Awaitable[Response]]

jbi/log.py

@@ -55,6 +55,7 @@ class RequestSummary(BaseModel):
     t: int
     time: str
     status_code: int
+    rid: str
 
 
 def format_request_summary_fields(
@@ -73,4 +74,5 @@ def format_request_summary_fields(
         t=int((current_time - request_time) * 1000.0),
         time=datetime.fromtimestamp(current_time).isoformat(),
         status_code=status_code,
+        rid=request.state.rid,
     ).dict()

jbi/models.py

@@ -323,6 +323,7 @@ def lookup_action(self, actions: Actions) -> Action:
 class BugzillaWebhookRequest(BaseModel):
     """Bugzilla Webhook Request Object"""
 
+    rid: str = ""  # This field has a default since it's not parsed from body.
     webhook_id: int
     webhook_name: str
     event: BugzillaWebhookEvent
@@ -366,6 +367,7 @@ class JiraContext(Context):
 class RunnerContext(Context, extra=Extra.forbid):
     """Logging context from runner"""
 
+    rid: str
     operation: Operation
     event: BugzillaWebhookEvent
     action: Optional[Action]
@@ -375,6 +377,7 @@ class RunnerContext(Context, extra=Extra.forbid):
 class ActionContext(Context, extra=Extra.forbid):
     """Logging context from actions"""
 
+    rid: str
     operation: Operation
     event: BugzillaWebhookEvent
     jira: JiraContext

jbi/router.py

@@ -64,13 +64,15 @@ def version(version_json=Depends(get_version)):
 
 @router.post("/bugzilla_webhook")
 def bugzilla_webhook(
-    request: BugzillaWebhookRequest = Body(..., embed=False),
+    request: Request,
+    webhook_request: BugzillaWebhookRequest = Body(..., embed=False),
     actions: Actions = Depends(get_actions),
     settings: Settings = Depends(get_settings),
 ):
     """API endpoint that Bugzilla Webhook Events request"""
+    webhook_request.rid = request.state.rid
     try:
-        result = execute_action(request, actions, settings)
+        result = execute_action(webhook_request, actions, settings)
         return result
     except IgnoreInvalidRequestError as exception:
         return {"error": str(exception)}

jbi/runner.py

@@ -38,6 +38,7 @@ def execute_action(
     bug, event = request.bug, request.event
     webhook_comment: Optional[BugzillaWebhookComment] = bug.comment
     runner_context = RunnerContext(
+        rid=request.rid,
         bug=bug,
         event=event,
         operation=Operation.HANDLE,
@@ -75,6 +76,7 @@ def execute_action(
         linked_issue_key: Optional[str] = bug.extract_from_see_also()
 
         action_context = ActionContext(
+            rid=request.rid,
             bug=bug,
             event=event,
             operation=Operation.IGNORE,

tests/fixtures/factories.py

@@ -1,3 +1,5 @@
+from secrets import token_hex
+
 from jbi import Operation
 from jbi.models import (
     Action,
@@ -100,6 +102,7 @@ def comment_factory(**overrides):
 def action_context_factory(**overrides):
     return ActionContext.parse_obj(
         {
+            "rid": token_hex(16),
             "operation": Operation.IGNORE,
             "bug": bug_factory(),
             "event": webhook_event_factory(),

tests/unit/test_app.py

@@ -13,11 +13,17 @@ def test_request_summary_is_logged(caplog):
     with caplog.at_level(logging.INFO):
         with TestClient(app) as anon_client:
             # https://fastapi.tiangolo.com/advanced/testing-events/
-            anon_client.get("/")
+            anon_client.get(
+                "/",
+                headers={
+                    "X-Request-Id": "foo-bar",
+                },
+            )
 
             summary = caplog.records[-1]
 
             assert summary.name == "request.summary"
+            assert summary.rid == "foo-bar"
             assert summary.method == "GET"
             assert summary.path == "/"
             assert summary.querystring == "{}"
@@ -71,3 +77,30 @@ def test_errors_are_reported_to_sentry(
                 )
 
     assert mocked.called, "Sentry captured the exception"
+
+
+def test_request_id_is_passed_down_to_logger_contexts(
+    caplog,
+    webhook_create_example: BugzillaWebhookRequest,
+    mocked_jira,
+    mocked_bugzilla,
+):
+    mocked_bugzilla.get_bug.return_value = webhook_create_example.bug
+    mocked_jira.create_issue.return_value = {
+        "key": "JBI-1922",
+    }
+    with caplog.at_level(logging.DEBUG):
+        with TestClient(app) as anon_client:
+            anon_client.post(
+                "/bugzilla_webhook",
+                data=webhook_create_example.json(),
+                headers={
+                    "X-Request-Id": "foo-bar",
+                },
+            )
+
+    runner_logs = [r for r in caplog.records if r.name == "jbi.runner"]
+    assert runner_logs[0].rid == "foo-bar"
+
+    action_logs = [r for r in caplog.records if r.name == "jbi.actions.default"]
+    assert action_logs[0].rid == "foo-bar"