fix: keep per-logger start times for multiple morgan instances - #387
Closed
dyk1454683243-sudo wants to merge 1 commit into
Closed
dyk1454683243-sudo wants to merge 1 commit into
dyk1454683243-sudo wants to merge 1 commit into
Conversation
Multiple morgan() middlewares share req/res and used to reset the same _startAt/_startTime fields, so a later logger made earlier ones report the wrong :response-time / :total-time. Each logger now snapshots its own start times and restores them when formatting, which matches the issue expressjs#141 reproduction. Co-authored-by: David <dyk1454683243-sudo@users.noreply.github.com>
Author
|
Withdrawing this PR while I clean up a high-volume open-PR backlog. Sorry for the noise — happy to come back later with a focused change if useful. |
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
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.
Fixes #141.
Problem
Each
morgan()middleware writes request/response start times onto the sharedreq/resobjects (_startAt/_startTime) and clears those fields when it runs. With two loggers and work between them, the later instance stomps the earlier one, so both:response-time/:total-timetokens measure from the later logger.Reproduction (from the issue, delay shortened):
Before this change both loggers reported ~0.2ms. The first logger should include the delay (~80ms).
Approach
Follow maintainer guidance on #141: each morgan instance records what it saw, and a later logger must not overwrite an earlier one.
req._startAt/res._startAtdeletes_startAt(existing hidden-property tests), leave it deleted so those tokens stay emptyThis is not the "never reset, share one start time" variant. That would make the later logger also report the full delay (a behavior change dougwilson called out as major-worthy). Here:
Two loggers mounted back-to-back with no delay still report essentially the same short times.
Test plan
:response-timeand:total-timewith two loggers + delaynpm test— 98 + 6 passingnpm run lint— clean