logging: add requestID for access logs, application logs and traceback logs - #1064
logging: add requestID for access logs, application logs and traceback logs#1064boddumanohar wants to merge 3 commits into
requestID for access logs, application logs and traceback logs#1064Conversation
c8c2b11 to
37c5276
Compare
mxsrc
left a comment
There was a problem hiding this comment.
Generally I like this, but in the case of sbctl execution, instead of -, establishing a context var with some random hash might be helpful
…and traceback logs
…s it get_logger() wraps the stderr handler in a QueueHandler/QueueListener for non-blocking logging: the listener formats and filters each record on its own background thread. RequestIdFilter reads a contextvars.ContextVar set by the request-handling thread, but ContextVars aren't inherited by a plain threading.Thread — so with the filter on the handler, it would always read the default '-' instead of the real request ID once records started flowing through the queue. Attach the filter to the logger instead: Logger.filter() runs synchronously on the emitting thread before the record is queued, so record.request_id is captured in the right context and just carried through by the listener.
c8bebcb to
5e6fc8c
Compare
|
rebased the PR. @mxsrc can you please re-review. |
There was a problem hiding this comment.
Pull request overview
This PR introduces a per-request request_id to correlate FastAPI access logs, application logs, and traceback logs by propagating a request-scoped identifier via contextvars and injecting it into log records.
Changes:
- Add a
request_id_varContextVarandRequestIdFilterto attachrequest_idonto log records insimplyblock_core.utils. - Inject/reset
request_idin the web request middleware and include it in access log formatting. - Initialize a
request_idfor CLI runs to avoid placeholder[-]values in CLI log output.
Reviewed changes
Copilot reviewed 3 out of 3 changed files in this pull request and generated 3 comments.
| File | Description |
|---|---|
| simplyblock_web/app.py | Generates/propagates request_id per request and adds it to access log output. |
| simplyblock_core/utils/init.py | Adds ContextVar + log filter and updates the core log formatter to include request_id. |
| simplyblock_cli/clibase.py | Seeds a CLI-scoped request_id so CLI logs can include a stable correlation ID. |
Suppressed comments (1)
simplyblock_web/app.py:86
request_id_var.reset(token)should be guaranteed even if access-log emission fails (e.g., handler/formatting issues). Wrap the access log call intry/finallyand reset in thefinallyso the contextvar is always cleared.
core_utils.request_id_var.reset(token)
return response
| except Exception: | ||
| logger.exception('Unhandled exception during %s %s (%.1fms)', | ||
| request.method, path, (time.monotonic() - start) * 1000) | ||
| core_utils.request_id_var.reset(token) | ||
| raise |
| request_id = request.headers.get('x-request-id') or uuid.uuid4().hex[:8] | ||
| token = core_utils.request_id_var.set(request_id) |
| # Filter is on the logger, not the handler: it must run synchronously | ||
| # on the emitting thread to read the caller's contextvars.ContextVar, | ||
| # before the record crosses into the QueueHandler/listener thread | ||
| # below (which has no access to the emitting thread's context). | ||
| logg.addFilter(RequestIdFilter()) |
mxsrc
left a comment
There was a problem hiding this comment.
I like this, but think the co-pilot suggestions should be folded in. I don't know about the root-logger concern, but if this worked in testing that should be a false-positive. Another thing I'm wondering about is the X-Request-ID header. Is that something we'd actually use? Otherwise I'd drop this, not only for the injection concern co-pilot flagged, but just simplicity as well.
currently in the WebApp API we have see 3 types of logs:
POST /cluster/<uid>.. 20ms "Go clientERROR: failed to clone volumeTraceback: ...To allow us to connect all these 3 together, have added a new field
request_idto the logging filter.So at the start of the request, within the middleware, we inject the request_id
and then reset it after the request ends
But since the update has been to the core logger,
simplyblock_core/utils/__init__.pyfor CLI, output, we'll see the extra [-] in between.