为何Morgan中间件日志晚于自定义中间件输出？Express技术问询

我在使用Express框架与Morgan日志中间件时遇到了输出顺序问题：按中间件声明顺序，Morgan日志应该先输出，但实际自定义中间件的“hello”先打印，Morgan需要等待整个请求完成才输出。这是否与Morgan的内部机制有关？我已尝试调整中间件顺序、在app.use中使用异步函数。

可复现问题的Node.js代码：

const express = require('express')
const morgan = require('morgan')

const app = express()

app.use(express.json()) //middleware

const customFormat = (tokens, req, res) => {
    let rarr = [
        tokens.method(req, res),
        tokens.url(req, res),
        tokens.status(req, res),
        tokens.res(req, res, 'content-length'), '-',
        tokens['response-time'](req, res), 'ms'
    ]
    return rarr.join(' ')
  } 

app.use(morgan(customFormat))

app.use( (req, res, next) => {

    console.log("hello");
    next();
});

let data = [
    { 
      "id": 1,
      "name": "alpha"
    },
    { 
      "id": 2,
      "name": "beta", 
    },
    { 
      "id": 3,
      "name": "gamma"
    }
]

app.get("/api/persons", (request, response) => {
    response.send(data)
})

这确实是Morgan的内部机制导致的。Morgan默认会等待整个请求-响应周期完成后才输出日志，因为它需要获取响应状态码、响应时长、响应内容长度这些只有请求处理完毕、响应发送给客户端后才能拿到的信息。

你的自定义中间件是同步执行的，调用next()之前就直接打印了“hello”；而Morgan在执行时，会先注册监听响应的finish或close事件，等响应完全结束后才会执行日志格式化和输出操作——所以不管你把Morgan放在哪个中间件前面，它的日志输出都会晚于那些同步执行的中间件里的console.log。

如果想要让Morgan在请求到达时就输出部分日志（比如仅打印请求方法和URL），可以启用Morgan的immediate选项：

// 启用immediate选项，请求到达时立即输出日志
app.use(morgan(customFormat, { immediate: true }))

注意：启用immediate后，status、response-time这类依赖响应的token会返回空值，你需要调整自定义格式，只保留请求阶段能获取到的字段。

内容的提问来源于stack exchange，提问作者sjdevelop