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

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