Skip to content

fix: keep per-logger start times for multiple morgan instances - #387

Closed
dyk1454683243-sudo wants to merge 1 commit into
expressjs:masterfrom
dyk1454683243-sudo:cursor/fix-multiple-morgan-start-time-bec7
Closed

dyk1454683243-sudo wants to merge 1 commit into
expressjs:masterfrom
dyk1454683243-sudo:cursor/fix-multiple-morgan-start-time-bec7

Conversation

@dyk1454683243-sudo

Copy link
Copy Markdown

Fixes #141.

Problem

Each morgan() middleware writes request/response start times onto the shared req/res objects (_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-time tokens measure from the later logger.

Reproduction (from the issue, delay shortened):

app.use(morgan('dev', { stream: stream1 }))
app.use(function (req, res, next) { setTimeout(next, 80) })
app.use(morgan('dev', { stream: stream2 }))

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.

  • Snapshot start times in the middleware closure (per logger, per request)
  • Restore that snapshot when formatting the log line so built-in and custom tokens still read req._startAt / res._startAt
  • If the caller deletes _startAt (existing hidden-property tests), leave it deleted so those tokens stay empty
  • Keep ES5 / Node 0.8 syntax

This 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:

  • first logger: time from when it ran (includes the inter-logger delay)
  • second logger: time from when it ran (does not include that delay)

Two loggers mounted back-to-back with no delay still report essentially the same short times.

Test plan

  • Reproduced Multiple morgan instances stubs out original start time #141 with two morgan instances and a delay (both ~0.2ms before; first ~80ms / second ~0.2ms after)
  • Regression tests for :response-time and :total-time with two loggers + delay
  • Sanity test that two loggers mounted together both emit a response-time
  • Existing hidden-property / immediate / after-response-sent tests still pass
  • npm test — 98 + 6 passing
  • npm run lint — clean

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>
@dyk1454683243-sudo

Copy link
Copy Markdown
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.

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.

Multiple morgan instances stubs out original start time

2 participants