Proper way to measure request duration in a Node.js + Express application

app.js

const app = require('express')()

const getDurationInMilliseconds  = (start) => {
    const NS_PER_SEC = 1e9
    const NS_TO_MS = 1e6
    const diff = process.hrtime(start)

    return (diff[0] * NS_PER_SEC + diff[1]) / NS_TO_MS
}

app.use((req, res, next) => {
    console.log(`${req.method} ${req.originalUrl} [STARTED]`)
    const start = process.hrtime()

    res.on('finish', () => {            
        const durationInMilliseconds = getDurationInMilliseconds (start)
        console.log(`${req.method} ${req.originalUrl} [FINISHED] ${durationInMilliseconds.toLocaleString()} ms`)
    })

    res.on('close', () => {
        const durationInMilliseconds = getDurationInMilliseconds (start)
        console.log(`${req.method} ${req.originalUrl} [CLOSED] ${durationInMilliseconds.toLocaleString()} ms`)
    })

    next()
})

// send response immediately
app.get('/fast/', (req, res) => {
    res.sendStatus(200)
})

// mock heavy load, send response after 10 seconds
app.get('/slow/', (req, res) => {
    setTimeout(() => res.sendStatus(200), 10 * 1000)
})

app.listen(3000, () => {
    console.log('Server started')
})

It's very helpful, Thanks.

According to my tests the close event is always emitted, even after finish, so this code logs doubled. Would it better to just listen for the close event?

@sochix thanks for the snippet!

On a quick note, this approach doesn't work well with hyper-express as the close event is not being emitted when closing the connection on the client-side. With Express.js this is working just fine.

https://gist.github.com/bulletinmybeard/f5620ba22a32d4e2bc020f72cb0f2d1e

According to my tests the close event is always emitted, even after finish, so this code logs doubled. Would it better to just listen for the close event?

How I use it is the finish event for calculating the request duration and the close event to log it. This way I can keep the middleware simple with only the finish event in there and somewhere else (at the end) I use the close event to log everything I need.

res.on('finish', () => {
    req.requestTimeMs = getDurationInMilliseconds(start);
  });

and then somewhere else/later:

res.on('close', () => {
    logger.log({request_time_millis: req.requestTimeMs...});
}