https://medium.com/javascript-in-plain-english/improve-observability-of-nodejs-http-request-response-a12f8629ccd0

 NodeJS being IO intensive, http requests form a major part of the application lifecycle. For monitoring and observability of a NodeJS application, understanding its behavior of requests made to other systems is an integral part of a micro-services architecture. Inspired by the tweet below, we decided to share how to improve the Observability in context of HTTP request-response lifecycle in a NodeJS application.

NodeJS HTTP request-response phases

In NodeJS, both HTTP Request and Response are NodeJS streams, they implement the EventEmitter interface and emit events for specific lifecycle events. We can add event listeners to these events in order to measure the important metrics for request and response. The events emitted by NodeJS for the parts of the above HTTP lifecycle phases are

• Socket
• DNS Lookup
• TCP Connect
• TLS Connect for HTTPS connections (secureConnect event on the socket)
• Response body start
• Response body end

The request starts with the creation of net.Socket object which emits the socket event once the socket is created. Now this socket can be used to listen to the DNS Lookup, TCP and TLS events. We will use process.hrtime() which marks High Resolution timestamp to mark the events and would find the duration from start of the request to each of those timestamps.

const request = https.request(options, callback)
const startTime = process.hrtime();
let dnsLookup, tcpConnection, tlsHandshake, responseBodyStart, responseBodyEnd;request.on("socket", socket => {
    // Socket created for dnslookup
    socket.on("lookup", () => {
        dnsLookup = process.hrtime();
    });    // TCP Connection established
    socket.on("connect", () => {
        tcpConnection = process.hrtime();
    });    // TLS Handshake complete
    socket.on("secureConnect", () => {
        tlsHandshake = process.hrtime();
    });
});

Once the request completes, the server would start sending responses. These response bytes can be listened on the http.Response object

https.request(requestOptions, res => {
    // The first time response bytes are transferred
    res.once("data", () => {
        responseBodyStart = process.hrtime();
    });
    res.on("data", chunk => (response += chunk));
    res.on("end", () => {
        responseBodyEnd = process.hrtime();
        callback(null, {
            body: response,
            duration: getEventDuration()
        });
    });
});

Now you can find the duration of each of these events marked with a timestamp to find the duration of important parts of the lifecycle.

DNS lookup = dnsLookup - startTime
TCP connection = tcpConnection - (dnsLookup || startTime)
TLS connection = tlsHandshake - tcpConnection
First byte = responseBodyStart - tlsHandshake
Content transfer = responseBodyEnd - responseBodyStart
Total = responseBodyEnd - startTime

This information can now be added to Monitoring and Distributed tracing to help improve the Observability of your systems.

The whole implementation for this is published as a npm package http-duration-client and the whole code is available on github/http-duration-client