Morgan not displaying the response time in log

Question

I'm trying to use morgan to log requests for my api server. With my routes configured like this;

  app.use logger('dev')

  app.use '/api/collab/dataobjects/:do',  if config.disable_auth then authMid.noAuthCheck else authMid.authCheck
  app.use '/api/collab/dataobjects/:do', queryRouter(config.testing)
  app.use '/api/collab/dataobjects/:do', queryRouter()

  app.use (req, res, next) ->
    console.warn "Test"
    err = new Error('Not Found')
    err.status = 404
    next err

  app.use (err, req, res, next) ->
    res.status(err.status || 500)
    console.warn err
    res.send {
      message: err.message
      error: err
    }

Morgan mostly works as expected, but on a few routes gives some nonsense output;

POST /api/collab/dataobjects/1/update - - ms - -

After checking some timings, it was clear that morgan was logging these responses before they had actually been returned. To fix this, I moved the app.use logger('dev') line after the api routes, but before the error catching routes. Placed there, Morgan would display the status code and size of long requests, unlike before, but now on all requests it doesn't show the time it took;

GET /api/collab/dataobjects/1 200 - ms - 4119

Why is Morgan failing to show the response time, and how can I fix it?

Answer 1

I just noticed this question is 2+ years old now, but I've already done the legwork so I'll post my response anyway.

I've seen similar problems myself so I spent a little time digging around to try to figure this out. I'm not sure I can fully answer your question (yet?) but I can explain a few of the things you are seeing:

STARTING THE TIMER:

Morgan starts its timer when the middleware-handler-method (the one with the (req, res, next) signature) is invoked, so in this case:

app.use logger('dev')
app.use '/api/foo/:bar', handler

the reported time should include the time to process /api/foo/:bar, but this case:

app.use '/api/foo/:bar', handler
app.use logger('dev')

it should not include the time to process /api/foo/:bar since the timer starts after the handler method runs.

STOPPING THE TIMER:

Morgan will not stop the timer until it is formatting the log line to be written.

Unless configured otherwise (e.g. with the immediate option), Morgan doesn't write the line to the log until the response has been completely processed, using the on-finished module to get called-back when the express request processing is complete.

REPORTING - INSTEAD OF THE RESPONSE TIME

I think there are a few scenarios that will cause Morgan to write - instead of the response time:

1. Based on the source code it looks like Morgan will write - to the log when it can't find the temporary variable it set when it "started the timer", therefore writing - to indicate the value is more or less "null".

2. Morgan also writes - to the log if the request "never" finished processing -- i.e., if the request timed out without completing a valid response. (In this case I guess - more or less indicates "infinity").

3. Morgan might also write - when the value is literally 0, which might explain why you started seeing - all the time once you moved the app.use(logger) code below your actual routes. Alternatively, since the response is probably already processed by the time Morgan invokes onFinished in your second scenario, the on-finished callback fires immediately, possibly before the temporary start-time variable has been written, leading to #1.

SO WHY DOES MORGAN SOMETIMES WRITE - IN YOUR ORIGINAL SET-UP?

I think the most likely scenario is that your "long-running" requests are timing out according to one part of your infrastructure or another. For example the service that sits in front of your expressjs application (a web server like nginx or an end-user's web browser) will eventually give up on waiting for a response close the connection.

I would need to dig around in the on-finished codebase (or have someone explain this to me :)) to understand what Morgan will get back from on-finished in this scenario, and what it will do with that information, but I think the response time-out is consistent with the information you've shared.