Skip to content

Set the request ID before the trace layer reads it - #819

Open
shaurya703 wants to merge 1 commit into
SO4-Markets:mainfrom
shaurya703:fix/request-id-reaches-trace-span
Open

Set the request ID before the trace layer reads it#819
shaurya703 wants to merge 1 commit into
SO4-Markets:mainfrom
shaurya703:fix/request-id-reaches-trace-span

Conversation

@shaurya703

Copy link
Copy Markdown

Fixes #790. Also makes the README claim in #813 true, so that one can be closed or re-checked after this lands.

The fix

SetRequestIdLayer now comes after trace_layer in the chain, which is what makes it run first. Chained Router::layer() calls make the last one added the outermost, so the request reached them bottom-up and make_span_with was reading an extension that had not been written yet.

I left a comment above the chain spelling the direction out, because reading it the natural way is exactly how this happened.

Why the existing test could not catch it

test_request_id_and_completion_logs asserts the response header, and the header never broke: PropagateRequestIdLayer only needs the id by the time the response is built. So the feature was dead in the logs while its test stayed green — which is the part worth fixing properly, not just the ordering.

The new test captures the span's own request_id field through a subscriber and asserts it is non-empty and equal to the header.

Verified against the old order:

every span carried an empty request_id — the trace layer ran before SetRequestIdLayer
ORIGINAL order -> 3 passed; 1 failed
FIXED order    -> 4 passed; 0 failed

The other three passing under the broken order is the whole point.

Two implementation notes

  • It reads the field, not formatted output, so it does not depend on the log format staying JSON.
  • The value arrives via record_debug, not record_str: the span uses request_id = %request_id, a Display value. My first version implemented only record_str and captured nothing — the test failed with "no request span was recorded at all", which is a false negative dressed as a failure. Both are implemented now so it cannot quietly stop seeing the field.

There is also a floor assertion that at least one span was recorded, so an empty capture cannot pass for a check.

Checks

cargo test — 16 suites green. cargo fmt --check and cargo clippy --all-targets -- -D warnings clean.

Fixes SO4-Markets#790.

Chained Router::layer() calls make the LAST one added the outermost, so the
request reached them bottom-up: track_metrics, trace_layer,
SetRequestIdLayer, Propagate. make_span_with therefore read an extension
SetRequestIdLayer had not written yet, and every span was created with
request_id = "".

SetRequestIdLayer now comes after trace_layer in the chain, which is what
makes it run first. A comment above the chain spells the direction out,
since reading it the natural way is exactly how this happened.

The response header kept working throughout, because Propagate only needs
the id by the time the response is built — which is why
test_request_id_and_completion_logs passed while the feature was dead. The
new test captures the span's own request_id field through a subscriber
rather than the header, and asserts it is non-empty and equal to the header.

Reading the field rather than parsing formatted output, so it does not
depend on the log format staying JSON. Recorded via record_debug because
the span uses `%request_id`, a Display value, which never reaches
record_str; both are implemented so it does not quietly stop seeing the
field.

Verified against the old order: the new test fails with "every span carried
an empty request_id" and the other three still pass, which is the point —
they could not see this.

16 suites green, fmt and clippy -D warnings clean.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

trace_layer runs before SetRequestIdLayer due to axum's layer ordering, so every trace span's request_id is always empty

1 participant