express - Morgan 未在日志中显示响应时间

Question

我正在尝试使用 morgan 来记录对我的 api 服务器的请求。我的路线是这样配置的；

  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 大部分都按预期工作，但在一些路由上给出了一些无意义的输出；

POST/api/collab/dataobjects/1/update - - 毫秒 - -

在检查了一些时间后，很明显 morgan 在实际返回之前记录了这些响应。为了解决这个问题，我将 app.use logger('dev') 行移到了 api 路由之后，错误捕获路由之前。放在那里，Morgan 会显示长请求的状态代码和大小，这与以前不同，但现在在所有请求上它都不会显示所花费的时间；

获取/api/collab/dataobjects/1 200 - 毫秒 - 4119

为什么 Morgan 无法显示响应时间，我该如何解决？

Answer 1

我刚刚注意到这个问题已有 2 年多的历史了，但我已经完成了跑腿工作，所以无论如何我都会发布我的回复。

我自己也遇到过类似的问题，所以我花了一点时间四处寻找，试图解决这个问题。我不确定我能否完全回答您的问题(还？)，但我可以解释您所看到的一些内容:

开始计时:

Morgan 在调用中间件处理程序方法(带有 (req, res, next) 签名的方法)时启动 计时器，因此在这种情况下:

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

报告的时间应该包括处理/api/foo/:bar的时间，但是这种情况:

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

它应该不包括处理 /api/foo/:bar 的时间，因为计时器在 handler 方法运行后启动。

停止计时器:

在格式化要写入的日志行之前，Morgan 不会停止计时器。

除非另有配置(例如使用immediate 选项)，Morgan 不会在响应完全处理之前使用on-finished 将行写入日志当快速请求处理完成时获得回调的模块。

报告 - 而不是响应时间

我认为有几个场景会导致Morgan写-而不是响应时间:

1. 基于 the source code看起来 Morgan 会在找不到它“启动计时器”时设置的临时变量时将 - 写入日志，因此写入 - 来指示值或多或少是“空”。

2. 如果请求“从未”完成处理，Morgan 还会将 - 写入日志 - 即，如果请求超时而未完成有效响应。 (在这种情况下，我猜 - 或多或少表示“无穷大”)。

3. Morgan 可能 也写 - 当值实际上是 0 时，这可能解释了为什么你开始一直看到 -将 app.use(logger) 代码移动到实际路线下方后。或者，由于在你的第二个场景中 Morgan 调用 onFinished 时响应可能已经被处理，on-finished 回调立即触发，可能在临时开始时间变量被写入之前，导致# 1.

那么为什么摩根有时会在您的原始设置中写入 -？

我认为最有可能的情况是您的“长时间运行”请求根据您的基础设施的一部分或另一部分超时。例如，位于 expressjs 应用程序(像 nginx 或最终用户的网络浏览器这样的网络服务器)前面的服务最终会放弃等待响应关闭连接。

我需要深入研究未完成的代码库(或者让某人向我解释一下 :))以了解 Morgan 在这种情况下将从未完成的代码中得到什么，以及它将如何处理这些信息，但我认为响应超时与您分享的信息一致。