fix(logging): stable leading-key order on every JSON line#54
Merged
Conversation
structlog inserts user-supplied kwargs into event_dict before TimeStamper /
EventRenamer / the metadata processor run, which means
`logger.info("event", k=v)` produces JSON where `k` lands at position 0,
ahead of `timestamp`. Lines from the uvicorn bridge — which carry no user
kwargs — put `timestamp` first. The mixed shape is what produced the
out-of-order `riptide_collector_starting` line where `version` led:
{"version": "0.1.0", "teams": 1, ..., "timestamp": "...", "msg": "..."}
All 22 structured-log call sites in the codebase use the same kwargs
convention so every one of them has the same problem. Adding a final
reorder processor at the formatter level catches every line — uvicorn
bridge, access middleware, every router — without per-call-site edits.
Also drop the redundant `version=__version__` kwarg in lifespan: the
metadata processor already supplies it, the kwarg was a duplicate that
landed at position 0 in the dict.
Tests:
- test_stable_leading_key_order_with_user_kwargs — unit-level: the chain
reorders even when the caller passes kwargs that would otherwise lead.
- test_every_emitted_line_starts_with_timestamp — end-to-end: parse the
actual JSON output of a real webhook request and assert every line
starts with `timestamp`.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
structlog inserts user kwargs into `event_dict` before the timestamp / metadata processors run, so `logger.info("event", k=v)` ends up with `k` at position 0 — ahead of `timestamp`. Lines without kwargs (uvicorn bridge) lead with `timestamp` instead. Visible regression: the `riptide_collector_starting` line started with `"version"` while every other line started with `"timestamp"`.
All 22 structured-log call sites use the same kwargs style → all of them have the same shape problem. Adding one reorder processor at the formatter level fixes every line — uvicorn bridge, access middleware, every router — without touching call sites.
Also drops the redundant `version=version` kwarg in the lifespan call (the metadata processor already supplies it).
Test plan