Skip to content

Add rid to logs with asgi-correlation-id #782

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 6 commits into from
Dec 8, 2023
Merged

Conversation

grahamalama
Copy link
Contributor

@grahamalama grahamalama commented Dec 5, 2023

This PR adds asgi-correlation-id, which provides a filter to add a request id (what they call a "correlation id") to logs by using a ContextVar.

Here's an example when calling __heartbeat__, where I didn't take too much care in settings configuration properly (I also patched the heartbeat route handler -- more on that in another PR)

{"Timestamp": 1701795525209590016, "Type": "jbi.services.bugzilla", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 6, "Pid": 34650, "Fields": {"rid": "b3b2499f04fe642a618c24506045796c", "msg": "No webhooks enabled"}}
{"Timestamp": 1701795525797857024, "Type": "jbi.services.jira", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 3, "Pid": 34650, "Fields": {"rid": "b3b2499f04fe642a618c24506045796c", "msg": "Jira projects {'DevTest'} are not visible with configured credentials"}}
{"Timestamp": 1701795525911177984, "Type": "atlassian.rest_client", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 3, "Pid": 34650, "Fields": {"body": "{\"errorMessages\":[\"Could not find project with provided key.\"],\"errors\":{}}", "rid": "-", "msg": "HTTP: GET /rest/api/2/mypermissions?permissions=ADD_COMMENTS%2CCREATE_ISSUES%2CEDIT_ISSUES%2CDELETE_ISSUES&projectKey=DevTest -> 404 Not Found"}}
{"Timestamp": 1701795525911500032, "Type": "backoff", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 3, "Pid": 34650, "Fields": {"rid": "-", "msg": "Giving up wrapper(...) after 1 tries (requests.exceptions.HTTPError: Could not find project with provided key.)"}}
{"Timestamp": 1701795525911770880, "Type": "jbi.services.jira", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 4, "Pid": 34650, "Fields": {"rid": "b3b2499f04fe642a618c24506045796c", "msg": "Failed to fetch permissions for project DevTest"}}
{"Timestamp": 1701795526029776896, "Type": "atlassian.rest_client", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 3, "Pid": 34650, "Fields": {"body": "{\"errorMessages\":[\"No project could be found with key 'DevTest'.\"],\"errors\":{}}", "rid": "b3b2499f04fe642a618c24506045796c", "msg": "HTTP: GET /rest/api/2/project/DevTest/components -> 404 Not Found"}}
{"Timestamp": 1701795526030150912, "Type": "backoff", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 3, "Pid": 34650, "Fields": {"rid": "b3b2499f04fe642a618c24506045796c", "msg": "Giving up wrapper(...) after 1 tries (requests.exceptions.HTTPError: No project could be found with key 'DevTest'.)"}}
{"Timestamp": 1701795526143874048, "Type": "atlassian.rest_client", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 3, "Pid": 34650, "Fields": {"body": "{\"errorMessages\":[\"No project could be found with key 'DevTest'.\"],\"errors\":{}}", "rid": "b3b2499f04fe642a618c24506045796c", "msg": "HTTP: GET /rest/api/2/project/DevTest -> 404 Not Found"}}
{"Timestamp": 1701795526144160000, "Type": "backoff", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 3, "Pid": 34650, "Fields": {"rid": "b3b2499f04fe642a618c24506045796c", "msg": "Giving up wrapper(...) after 1 tries (requests.exceptions.HTTPError: No project could be found with key 'DevTest'.)"}}
{"Timestamp": 1701795526144962048, "Type": "request.summary", "Logger": "jbi", "Hostname": "gbeckley-kxmd6r", "EnvVersion": "2.0", "Severity": 6, "Pid": 34650, "Fields": {"agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:122.0) Gecko/20100101 Firefox/122.0", "path": "/__heartbeat__", "method": "GET", "lang": "en-US,en;q=0.5", "querystring": "{}", "errno": 0, "t": 1376, "time": "2023-12-05T11:58:46.144848", "status_code": 503, "rid": "b3b2499f04fe642a618c24506045796c"}}

One note: the rid does not seem to be preserved in instances where we use a ThreadPoolExecutor. I believe this is a limitation of Context Vars. We can investigate how to copy this context to other threads in a future PR, but this seems "good enough" for now, and we have other ways to diagnose what's going on in the heartbeat

I don't know _why_ this was happening, but trying to use a breakpoint in
test_request_summary_is_logged caused the test to hang. I found that using
the fixture directly (i.e. not as a context manager) made the test work as
expected
@grahamalama grahamalama requested a review from a team as a code owner December 5, 2023 17:01
@grahamalama grahamalama added the enhancement New feature or request label Dec 5, 2023
@grahamalama grahamalama requested review from a team and removed request for a team December 6, 2023 16:26
@grahamalama grahamalama merged commit 4401bc0 into main Dec 8, 2023
@grahamalama grahamalama deleted the rid-logging-filter branch December 8, 2023 14:39
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants