How we built a Node.js Middleware to Log HTTP API Requests and Responses

How we built a Node.js Middleware to Log HTTP API Requests and Responses

There are many different runtimes and eco-systems used to build APIs and here at Moesif we try to make integration with them as simple as possible. We build many libraries that help with this integration, one of them is the Moesif Express Middleware Library, or short Moesif-Express.

Despite its name, Moesif-Express can be used with Node.js applications that use the built-in http module.

Node.js handles requests asynchronously which can sometimes lead to problems, especially when we want to debug our systems or log what they are doing.

In this article, we will go through the steps that went into building the Moesif-Express library, the places where the relevant logging data is and how to hook into Node.js’ http module to handle the data-gathering at the right time in the pipeline.

Node.js’ HTTP Module

Node.js comes with an HTTP-server implementation out-of-the-box, while it isn’t used directly in most applications, it’s a good start to understand the basics of requests and responses.

Basic Logging of a GET Request

The idea behind logging is that we write some kind of data in some persistent data store so we can review it later. To keep things simple, we will first write to stdout with console.log().

Sometimes logging to stdout isn’t an option and we have to send the logging data to some other place. Like when running in a serverless environment, where the functions have no persistent storage.

Let’s try a simple server that does nothing but sending empty responses for every request to illustrate how to get request data that can be logged.

const http = require("http");

const server = http.createServer((request, response) => {
  console.log(request);
  response.end();
});

server.listen(8888);

If we send a request to http://localhost:8888 we see a giant object being logged to stdout, it is full of implementation details and finding the important parts isn’t easy.

Let’s look at the Node.js documentation for IncomingMessage, the class of which our requests is an object of.

What information can we find here?

  • headers and rawHeaders (for invalid/duplicate headers)
  • httpVersion
  • method
  • url
  • socket.remoteAddress (for the client IP)

This should be enough for GET requests since they usually don’t have a body. Let’s update our implementation.

const server = http.createServer((request, response) => {
  const { rawHeaders, httpVersion, method, socket, url } = request;
  const { remoteAddress, remoteFamily } = socket;

  console.log(
    JSON.stringify({
      timestamp: Date.now(),
      rawHeaders,
      httpVersion,
      method,
      remoteAddress,
      remoteFamily,
      url
    })
  );

  response.end();
});

The output should look something like this:

{
  "timestamp": 1562331336922,
  "rawHeaders": [
    "cache-control",
    "no-cache",
    "Postman-Token",
    "dcd81e98-4f98-42a3-9e13-10c8401892b3",
    "User-Agent",
    "PostmanRuntime/7.6.0",
    "Accept",
    "*/*",
    "Host",
    "localhost:8888",
    "accept-encoding",
    "gzip, deflate",
    "Connection",
    "keep alive"
  ],
  "httpVersion": "1.1",
  "method": "GET",
  "remoteAddress": "::1",
  "remoteFamily": "IPv6",
  "url": "/"
}

We only use specific parts of the request for our logging. It uses JSON as format so it’s a structured logging approach and has a timestamp so know we not only know what was requested by whom but also when the request started.

Logging Processing Time

If we wanted to add data about how long the request took to process, we need a way to check when it’s finished.

The request is done when we finished sending our response, so we have to check when a response.end() was called. In our example, this is rather simple, but sometimes these end-calls are done by other modules.

For this, we can look at the docs of the ServerResponse class. It mentions a finish event that is fired when all the sever finished sending it’s response. This doesn’t mean the client received everything, but it’s an indicator that our work is done.

Let’s update our code!

const server = http.createServer((request, response) => {
  const requestStart = Date.now();

  response.on("finish", () => {
    const { rawHeaders, httpVersion, method, socket, url } = request;
    const { remoteAddress, remoteFamily } = socket;

    console.log(
      JSON.stringify({
        timestamp: Date.now(),
        processingTime: Date.now() - requestStart,
        rawHeaders,
        httpVersion,
        method,
        remoteAddress,
        remoteFamily,
        url
      })
    );
  });

  process(request, response);
});

const process = (request, response) => {
  setTimeout(() => {
    response.end();
  }, 100);
};

We passed the processing of our request to a separate function to simulate an other module that takes care of it. The processing takes place asynchronously, because of the setTimeout, so synchronous logging wouldn’t get the desired result, but the finish event takes care of this by firing after response.end() was called.

Logging the Body

The request body is still not logged, which means POST, PUT and PATCH requests aren’t 100% covered.

To get the body into the logs too, we need a way to extract it from our request object.

The IncomingMessage class implements the ReadableStream interface. It uses the events of that interface to signal when body data from the client arrives.

  • The data event is fired when the server received new chunks of data from the client
  • The end event is called when all data has been sent
  • The error event is called when something goes wrong

Let’s update our code:

const server = http.createServer((request, response) => {
  const requestStart = Date.now();

  let errorMessage = null;
  let body = [];
  request.on("data", chunk => {
    body.push(chunk);
  });
  request.on("end", () => {
    body = Buffer.concat(body);
    body = body.toString();
  });
  request.on("error", error => {
    errorMessage = error.message;
  });

  response.on("finish", () => {
    const { rawHeaders, httpVersion, method, socket, url } = request;
    const { remoteAddress, remoteFamily } = socket;

    console.log(
      JSON.stringify({
        timestamp: Date.now(),
        processingTime: Date.now() - requestStart,
        rawHeaders,
        body,
        errorMessage,
        httpVersion,
        method,
        remoteAddress,
        remoteFamily,
        url
      })
    );
  });

  process(request, response);
});

This way we log an additional error message when something goes wrong and add the body content to the logging.

Caution: The body can be very big and/or binary, so validation checks are needed, otherwise the amount of data or the encoding can mess up our logs.

Logging Response Data

Now that we got the requests down, the next step is the logging of our responses.

We already listen to the finish event of our response, so we have a pretty safe way to get all the data. We just have to extract what the response object holds.

Let’s look at the docs for the ServerResponse class to find out what it offers us.

  • statusCode
  • statusMessage
  • getHeaders()

Let’s add it to our code.

const server = http.createServer((request, response) => {
  const requestStart = Date.now();

  let errorMessage = null;
  let body = [];
  request.on("data", chunk => {
    body.push(chunk);
  });
  request.on("end", () => {
    body = Buffer.concat(body).toString();
  });
  request.on("error", error => {
    errorMessage = error.message;
  });

  response.on("finish", () => {
    const { rawHeaders, httpVersion, method, socket, url } = request;
    const { remoteAddress, remoteFamily } = socket;

    const { statusCode, statusMessage } = response;
    const headers = response.getHeaders();

    console.log(
      JSON.stringify({
        timestamp: Date.now(),
        processingTime: Date.now() - requestStart,
        rawHeaders,
        body,
        errorMessage,
        httpVersion,
        method,
        remoteAddress,
        remoteFamily,
        url,
        response: {
          statusCode,
          statusMessage,
          headers
        }
      })
    );
  });

  process(request, response);
});

Handling Response Errors and Client Aborts

At the moment we only log when the response finish event is fired, this isn’t the case if something goes wrong in response or if the client aborts the request.

For these two cases, we need to create additional handlers.

const server = http.createServer((request, response) => {
  const requestStart = Date.now();

  let body = [];
  let requestErrorMessage = null;

  const getChunk = chunk => body.push(chunk);
  const assembleBody = () => {
    body = Buffer.concat(body).toString();
  };
  const getError = error => {
    requestErrorMessage = error.message;
  };
  request.on("data", getChunk);
  request.on("end", assembleBody);
  request.on("error", getError);

  const logClose = () => {
    removeHandlers();
    log(request, response, "Client aborted.");
  };
  const logError = error => {
    removeHandlers();
    log(request, response, error.message);
  };
  const logFinish = () => {
    removeHandlers();
    log(request, response, requestErrorMessage);
  };
  response.on("close", logClose);
  response.on("error", logError);
  response.on("finish", logFinish);

  const removeHandlers = () => {
    request.off("data", getChunk);
    request.off("end", assembleBody);
    request.off("error", getError);
    response.off("close", logClose);
    response.off("error", logError);
    response.off("finish", logFinish);
  };

  process(request, response);
});

const log = (request, response, errorMessage) => {
  const { rawHeaders, httpVersion, method, socket, url } = request;
  const { remoteAddress, remoteFamily } = socket;

  const { statusCode, statusMessage } = response;
  const headers = response.getHeaders();

  console.log(
    JSON.stringify({
      timestamp: Date.now(),
      processingTime: Date.now() - requestStart,
      rawHeaders,
      body,
      errorMessage,
      httpVersion,
      method,
      remoteAddress,
      remoteFamily,
      url,
      response: {
        statusCode,
        statusMessage,
        headers
      }
    })
  );
};

Now, we also log errors and aborts.

The logging handlers are also removed when the response finished and all the logging is moved to an extra function.

Logging to an external API

At the moment the script only writes its logs to the console and in many cases, this is enough because operating systems allow other programs to capture the stdout and do their thing with it, like writing into a file or sending it to a third-party API like Moesif, for example.

In some environments, this isn’t possible, but since we gathered all information into one place, we can replace the call to console.log with a third-party function.

Let’s refactor the code so it resembles a library and logs to some external service.

const log = loggingLibrary({ apiKey: "XYZ" });
const server = http.createServer((request, response) => {
  log(request, response);
  process(request, response);
});

const loggingLibray = config => {
  const loggingApiHeaders = {
    Authorization: "Bearer " + config.apiKey
  };

  const log = (request, response, errorMessage, requestStart) => {
    const { rawHeaders, httpVersion, method, socket, url } = request;
    const { remoteAddress, remoteFamily } = socket;

    const { statusCode, statusMessage } = response;
    const responseHeaders = response.getHeaders();

    http.request("https://example.org/logging-endpoint", {
      headers: loggingApiHeaders,
      body: JSON.stringify({
        timestamp: requestStart,
        processingTime: Date.now() - requestStart,
        rawHeaders,
        body,
        errorMessage,
        httpVersion,
        method,
        remoteAddress,
        remoteFamily,
        url,
        response: {
          statusCode,
          statusMessage,
          headers: responseHeaders
        }
      })
    });
  };

  return (request, response) => {
    const requestStart = Date.now();

    // ========== REQUEST HANLDING ==========
    let body = [];
    let requestErrorMessage = null;
    const getChunk = chunk => body.push(chunk);
    const assembleBody = () => {
      body = Buffer.concat(body).toString();
    };
    const getError = error => {
      requestErrorMessage = error.message;
    };
    request.on("data", getChunk);
    request.on("end", assembleBody);
    request.on("error", getError);

    // ========== RESPONSE HANLDING ==========
    const logClose = () => {
      removeHandlers();
      log(request, response, "Client aborted.", requestStart);
    };
    const logError = error => {
      removeHandlers();
      log(request, response, error.message, requestStart);
    };
    const logFinish = () => {
      removeHandlers();
      log(request, response, requestErrorMessage, requestStart);
    };
    response.on("close", logClose);
    response.on("error", logError);
    response.on("finish", logFinish);

    // ========== CLEANUP ==========
    const removeHandlers = () => {
      request.off("data", getChunk);
      request.off("end", assembleBody);
      request.off("error", getError);

      response.off("close", logClose);
      response.off("error", logError);
      response.off("finish", logFinish);
    };
  };
};

With these changes, we can now use our logging implementation as we would use Moesif-Express.

The loggingLibrary function takes an API-key as configuration and returns the actual logging-function that will send the log-data to a logging service via HTTP. The logging-function itself takes a request and response object.

Conclusion

Logging in Node.js isn’t as straight forward as one would think, especially in an HTTP environment. JavaScript handles many things asynchronously, so we need to hook into the right events, otherwise, we don’t know what’s happening.

Luckily for us, there are many logging libraries out there so we don’t have to write one by ourself.

Here are a few:

  • Bunyan - https://github.com/trentm/node-bunyan
  • Debug - https://github.com/visionmedia/debug
  • Log4js - https://github.com/log4js-node/log4js-node
  • Morgan - https://github.com/expressjs/morgan
  • Npmlog - https://github.com/npm/npmlog
  • Winston - https://github.com/winstonjs/winston
Learn More About Moesif Get User-Centric API Monitoring for Node.js 14 day free trial. No credit card required. Learn More
Get User-Centric API Monitoring for Node.js Get User-Centric API Monitoring for Node.js

Get User-Centric API Monitoring for Node.js

Learn More