Creating a logging middleware in Expressjs

Logging is an important part of supporting the complete application life cycle. By analyzing the data in the logs, we could resolve bugs much quicker, and detect problems early as they happen.

One of the most basic kind of logging every backend application should have is a trace logging of all incoming HTTP requests.

In expressjs it’s easy to use middleware to stow into the beginning of the processing and execute our logging code there.

What is a Middleware in Expressjs

Middleware is a subset of chained functions called by the expressjs routing layer before the user-defined handler is invoked.

We will be building a logging middleware that logs clients and server requests in our application. So let’s start by creating a simple expressjs server. We will create a new directory on our home directory for our application using the terminal.

cd desktop && mkdir logger && cd logger
npm init -y

This command npm init -y will create a package.json file on our root directory. To install expressjs open the terminal and type:

npm i express nodemon --save

Nodemon will restart the server when once the file changes. To create our expressjs server, create a new server.js file on the root directory and type the code below:

const express = require("express");
const PORT = 5000;
const app = express();

app.listen(PORT, () => {
  console.log(`App is listening to port ${PORT}`);
});

On your terminal, type nodemon to run the server. After running the server you should see App is listening to port 5000 displayed on the console.

Before Writing logs for our application, we need to create some routes. So let’s modify the codes in our server.js file with the code below:

const express = require("express");
const PORT = 5000;
const app = express();
app.get("/", (req, res) => {
  res.send("This is the home Page");
});
app.get("/about", (req, res) => {
  res.send("This is the About page");
});
app.post("/add", (req, res) => {
  res.send("Post request");
});
app.listen(PORT, () => {
  console.log(`App is listening to port ${PORT}`);
});

Writing Your First Middleware Function

Middleware functions are functions that have access to the request object(req), the response object (res), and the next function in the application’s request-response cycle. The next function is a function in the Express router which, when invoked, executes the middleware succeeding the current middleware. In your server.js file add the code below before your routes:

let demoLogger = (req, res, next) => {
  console.log("Hello from logger");
  next();
};

app.use(demoLogger);

Here is a simple example of a middleware function called “demoLogger”. This function just prints “Hello from logger” when a request to the app passes through it. The middleware function is assigned to a variable named demoLogger.The app.use() method is used to load the middleware. Every time the app receives a request, it prints the message “Hello from logger” to the terminal.

In this article, we will focus on creating a middleware function that will log all requests and responses we make and get in our application and then store it in a text file.

What We Will Be Logging

Our middleware will be logging the following when a request is made in our application:

• Timestamp.
• Request method.
• Request URL.
• Response Status Code.
• Time taken to complete the request.

Let’s continue by modifying our demoLogger function to this:

let demoLogger = (req, res, next) => {
  let current_datetime = new Date();
  let formatted_date =
    current_datetime.getFullYear() +
    "-" +
    (current_datetime.getMonth() + 1) +
    "-" +
    current_datetime.getDate() +
    " " +
    current_datetime.getHours() +
    ":" +
    current_datetime.getMinutes() +
    ":" +
    current_datetime.getSeconds();
  let method = req.method;
  let url = req.url;
  let status = res.statusCode;
  let log = `[${formatted_date}] ${method}:${url} ${status}`;
  console.log(log);
  next();
};

Here we get the current time and date and format it a little bit. We also get the request method and URL from the req object. When the request is made, we then get the status code from the response object and then we log it on the console. when we make any request in our application, the details of the request and response will be logged in the console like this:

So, to measure the time we will be using high-resolution Node.js timer. The process.hrtime() method returns the current high-resolution real-time in a [seconds, nanoseconds] tuple Array, where nanoseconds is the remaining part of the real-time that can’t be represented in second precision.

Lets write a simple helper function that will calculate the time taken to complete a request.:

const getActualRequestDurationInMilliseconds = start => {
  const NS_PER_SEC = 1e9; // convert to nanoseconds
  const NS_TO_MS = 1e6; // convert to milliseconds
  const diff = process.hrtime(start);
  return (diff[0] * NS_PER_SEC + diff[1]) / NS_TO_MS;
};

And then modify our logger middleware function to this:

let demoLogger = (req, res, next) => {
  let current_datetime = new Date();
  let formatted_date =
    current_datetime.getFullYear() +
    "-" +
    (current_datetime.getMonth() + 1) +
    "-" +
    current_datetime.getDate() +
    " " +
    current_datetime.getHours() +
    ":" +
    current_datetime.getMinutes() +
    ":" +
    current_datetime.getSeconds();
  let method = req.method;
  let url = req.url;
  let status = res.statusCode;
  const start = process.hrtime();
  const durationInMilliseconds = getActualRequestDurationInMilliseconds(start);
  let log = `[${formatted_date}] ${method}:${url} ${status} ${durationInMilliseconds.toLocaleString()} ms`;
  console.log(log);
  next();
};

Now that the time has been calculated, we need a file to store all our logs for reference purposes. For this we need to bring in the file system(fs) module by requiring it at the top of our application like this:

const fs = require('fs');

and add this code to our middleware function:

fs.appendFile("request_logs.txt", log + "\n", err => {
    if (err) {
      console.log(err);
    }
  });

The fs.appendFile method asynchronously appends data to a file, creating the file if it does not yet exist. So all our logs will be stored in this file. our server.js file should look like this at the end:

const express = require("express");
const fs = require("fs");
const PORT = 5000;
const app = express();


const getActualRequestDurationInMilliseconds = start => {
  const NS_PER_SEC = 1e9; //  convert to nanoseconds
  const NS_TO_MS = 1e6; // convert to milliseconds
  const diff = process.hrtime(start);
  return (diff[0] * NS_PER_SEC + diff[1]) / NS_TO_MS;
};


let demoLogger = (req, res, next) => { //middleware function
  let current_datetime = new Date();
  let formatted_date =
    current_datetime.getFullYear() +
    "-" +
    (current_datetime.getMonth() + 1) +
    "-" +
    current_datetime.getDate() +
    " " +
    current_datetime.getHours() +
    ":" +
    current_datetime.getMinutes() +
    ":" +
    current_datetime.getSeconds();
  let method = req.method;
  let url = req.url;
  let status = res.statusCode;
  const start = process.hrtime();
  const durationInMilliseconds = getActualRequestDurationInMilliseconds(start);
  let log = `[${formatted_date}] ${method}:${url} ${status} ${durationInMilliseconds.toLocaleString()} ms`;
  console.log(log);
  fs.appendFile("request_logs.txt", log + "\n", err => {
    if (err) {
      console.log(err);
    }
  });
  next();
};


app.use(demoLogger);


app.get("/", (req, res) => {
  res.send("This is the home Page");
});
app.get("/about", (req, res) => {
  res.send("This is the About page");
});
app.post("/add", (req, res) => {
  res.send("Post request");
});
app.listen(PORT, () => {
  console.log(`App is listening to port ${PORT}`);
});

Styling The Terminal Output

We will be styling the log output on the terminal.We will set the time stamp to a blue color and set the duration of the request to a red color. Chalkjs is an awesome module that allows you to control the color of the text that gets printed to the console. To install it, run npm i chalk and then require it in the server.js file like this: const chalk = require('chalk');

We will then modify the code that logs the request to our terminal to this:

let log = `[${chalk.blue(formatted_date)}]
 ${method}:${url} ${status} 
 ${chalk.red(durationInMilliseconds.toLocaleString() + "ms")}`;

now your response on the console should look like this:

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.

You can access CodeSource From here.