Nodejs: Morgon logs are not logging complete response time when streaming is enabled

Question

I have a code which does Simple HTML streaming using nodejs and express. The first stream happens at 3rd sec, the second stream happens at 6th sec and the last stream happens at 9th sec. The code is enabled with Morgon log to log the response time. The response time that gets logged via Morgon shows as 3 sec (logs the first stream response time). Is there a way in Morgon or in nodejs or in express to get the complete response time when streaming is enabled? Helps is much appreciated.

var express = require("express");
var bodyParser = require('body-parser');
var utf8 = require('utf8');
var axios = require('axios');
var morgan = require('morgan')
var fs = require('fs')
var path = require('path')
var app = express();
var port = 3000;
app.use(bodyParser.urlencoded({ extended: false }));
var urlencodedParser = bodyParser.urlencoded({ extended: true })
app.use(function(req, res, next) {
        var decodedUrl = decodeURIComponent(req.originalUrl);
        req.originalUrl = decodedUrl;
    next();
});
var accessLogStream = fs.createWriteStream(path.join(__dirname, 'access.log'), { flags: 'a' })
app.use(morgan(':method :url :response-time'))
// respond with "hello world" when a GET request is made to the homepage
app.get("/test/*/id*", urlencodedParser, function (req, res) {

    let soapUIHeader = '<dummy></dummy>';
    setTimeout(function() {
        res.write('<div><p>Header........</p><div>');
        setTimeout(function body() {
            res.write('<div><p>Body........</p><div>');
            setTimeout(function footer() {
                res.write('<div><p>Footer........</p><div>');
                res.end();
            },3000)
        },3000);
    },3000)
});


app.listen(port, function() {
    console.log("server started in port " + port);
});

module.exports = app

Answer 1

The Best way to measure response time when we have the response streaming enabled is using the middleware. Here are the steps:

Introduce a middleware function setReqBeginTime at the beginning of the express request. This function captures the current time of the request and stores as a request header (req.headers['reqBeginTime'] = currentTime;). Add another function logResponeEndTime at the end of an express request. This function gets the final execution time of the request and gets the response time by subtracting the reqBeginTime.

Hope this helps

let setReqBeginTime = (req, res, next) => {
 var currentTime = Date.now();
 req.headers['reqBeginTime'] = currentTime;
 next();
}

let logResponeEndTime = (req, res, next) => {
 var currentTime = Date.now();
 var reqBeginTime = req.headers['reqBeginTime'];
 var responseTime = currentTime - reqBeginTime;
 req.headers['respEndTime'] = responseTime;
 next();
}

app.get("/test/*/id*", setReqBeginTime(), urlencodedParser, function (req, res) {

    let soapUIHeader = '<dummy></dummy>';
    setTimeout(function() {
        res.write('<div><p>Header........</p><div>');
        setTimeout(function body() {
            res.write('<div><p>Body........</p><div>');
            setTimeout(function footer() {
                res.write('<div><p>Footer........</p><div>');
                res.end();
            },3000)
        },3000);
    },3000)
}, logResponeEndTime());