How does morgan middleware always print the result to console after any other middleware

Question

I am using express library and a logging library called morgan

I am attaching a working code below, to be able to reproduce this in nodejs:

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)
})

Why does in this case "hello" get printed before the output of Morgan middleware, ideally it should be in the order of middleware declaration?

Morgan middleware seems to be waiting for whole request to be completed, and is logged at the very end, does it have something to do with internals of morgan?

I have tried running different order of middleware, using async function inside app.use()

Answer 1

Morgan by default is configured to run after the response ends. (So that it can log the time it took). By Looking at the code in GitHub, you can control this behavior with an option property immediate?.

app.use(morgan(customFormat, {
    immediate: true
}))

Here's the code from the morgan source:

if (immediate) {
  // immediate log
  logRequest()
} else {
  // record response start
  onHeaders(res, recordStartTime)

  // log when response finished
  onFinished(res, logRequest)
}