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
stdoutisn’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?
headersandrawHeaders(for invalid/duplicate headers)httpVersionmethodurlsocket.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
dataevent is fired when the server received new chunks of data from the client - The
endevent is called when all data has been sent - The
errorevent 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.
statusCodestatusMessagegetHeaders()
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
Related Articles
API Analytics and Monitoring
Introducing AI Explain
We are thrilled to introduce our newest feature to Moesif - AI Explain - a powerful conversational tool that lets you interact with your API analytics data l...
API Analytics and Monitoring
Monitoring Cost and Consumption of AI APIs and Apps
Discover how Moesif can help manage and optimize your AI-driven APIs with powerful observability tools that track costs and usage efficiently.
API Development
Unlock Deep API Insights with Moesif’s HTTP Body Analytics
Learn how to use Moesif to analyze HTTP bodies.
API Analytics and Monitoring
How Moesif API Observability Compares to Treblle
Learn how Moesif’s API observability platform compares to Treblle.