Multiple morgan instances stubs out original start time

[WORMSS]

Hello, I was looking to have multiple logs, the standard process.stdout, a fileStreamRotate and a mongo variant. I was looking to see if there would be any issues with a few being synchronous and a few being asynchronous. I didn't see much in the way of problems except the fact that the _startTime is set to undefined each time. Which could cause problems between multiple morgan instances.

I understand what I am about to write is an exaggeration and prob not recommended anyway, but I just wanted to point it out.

var morgan = require("morgan");
var app = require("express")();

var stream1 = require("fs").createWriteStream("log.log");
var stream2 = process.stdout;

app.use(morgan("dev", { stream: stream1 }));
app.use((req, res, next) => { setTimeout(next, 2000); }); // Wait 2 seconds
app.use(morgan("dev", { stream: stream2 }));
app.use((req, res) => { res.send(); });

app.listen(3000);

As I said, this would be an extremely strange behaviour, but it does point out that both morgans record that the response time is ~8ms rather than over 2008ms

• Colin

[dougwilson]

Ah, yes, indeed. I'm going to try and work to overhaul these private values such that each morgan instance gets it's own copy, which would make them independenct and recording only what they saw, which is the intention. The later certainly shouldn't be stomping on the former :)

[WORMSS]

Thank you for picking this up @dougwilson

[ryhinchey]

I think a seemingly simple fix for this is to change the returned middleware function as follows:

  return function logger (req, res, next) {
    // req.startAt and req._startTime initialized values removed
    req._remoteAddress = getip(req)

    // response data
    res._startAt = undefined
    res._startTime = undefined

    // record request start
   // only if they don't exist
    if (!req._startAt || !req._startTime) {
      recordStartTime.call(req)
    }

This makes the OP's example log ~2 seconds and I'd be happy to create a PR for this.

That said, moving these values off the req and res objects is probably the end goal. I have some ideas on how that could be done and will raise a PR hopefully soon.

[dougwilson]

This makes the OP's example log ~2 seconds and I'd be happy to create a PR for this.

Why, though? It would be a breaking change and the breaking change we want is actually your second point, so why make two major releases when we already know the one breaking change we want to make is the second one? :)

[ryhinchey]

Got it. I didn’t view this as a breaking change so that’s good to know

[dougwilson]

I didn’t view this as a breaking change so that’s good to know

It doesn't seem like it on the surface, but there is a behavior change here, of course. The way in which the timers behave will change to fix the "bug". But the issue is that the docs never said which way it should work, nor did tests. This means it was left open to how users just ended up using it, which would be the "buggy" behavior.

I have learned from these heavily used module that this us the recipe in which putting that change into a non major will break folks.

Version numbers are thankfully free, so it is less friction for everyone to lean on major for some things like this issue, especially if it means we can provide a better overall fix.

[ryhinchey]

Awesome! As always thank you for the explanation