A-Z Logging for your node application

This article is for all the developers who are either starting out with their nodeJs journey or have built great applications with it but want to understand the best practices and ways of logging. I will be covering a widely popular npm package for logging i.e. Winston and how you can customize it to suit your demands of logging.

But before diving into the practices let’s start with the fundamental question that may pop in many of your minds - why do we need logs?

Introduction to logging & why do we need it?

Speaking strictly in a theoretical manner :

Logging enables us to persist data of our application which can be used for analysis at a later time

The most common use case for logging is to trace how a bug actually occurred in your system. Now some of you may argue that logging adds extra overhead in your development timeline and in case a bug arises later, you can debug the issue pretty easily in your application.

But wait! While this is fair reasoning. I have only one word for you — scale.

What happens when your application scales up to serve a large number of users concurrently and is doing multiple operations simultaneously. Will you be able to figure out the problem without a log to help you?

If your palms are sweating just by playing this horrific scenario in your head, you now have the ansewer to the WHY. Now let’s move to another question that generally follows.

What & when to log

The answer to this question can be summarized in a single line:

Log as much as you can!

What I mean by that line is the richer your logging is in an application the easier it becomes for you to visualise and take suitable actions on the log data.

Levels of logging

There are many levels at which you can log, which are :

• debug
• verbose
• info
• warn
• error

A combination of these levels can be used to enable proper logs for every environment of your application. For eg., you will need debug/warn logs in your development & testing environments but would prefer to not have them in your staging & production environments.

What’s the issue with console.log ?

For those of you thinking why we can’t use the default console.log for logging, I would like to clarify that there is nothing wrong with using the inbuilt function provided by node but you will find that Winston provides a lot of other features which help you in designing a scalable system. A few of them are as follows:

• Streams: Winston internally uses streams provided by node which helps it process a large amount of data without incurring a large overhead on your application. You can read about streams in detail here.
• Transports: Apart from logging just to the console or standard output, you may also want to write data to files or store them in the cloud or stream them to other third-party services for analysis. Winston provides you a fairly simple way of managing all of these in a centralized manner.
• Formatting: The default console function only deals with strings and hence doesn’t provide a lot of flexibility in formatting your log messages. In comparison, Winston provides advanced features to color your logs, JSON formatting and even transforming your logs before sending them to any of your desired end log locations.

Now that we have our basics clear, let’s dive into setting up Winston for logging inside our application.

Setting up Winston

Installing Winston is pretty straight-forward. Just run the following command.

npm i winston --save

And then you can set it up using the below code in your application and save it to any file(I have saved it in logger.js).

const { createLogger, transports } = require('winston');

const generalLogger = createLogger({
  transports : [
    new transports.Console()
  ]
});

generalLogger.stream = {
  write : (info) => {
    generalLogger.info(info);
  }
};

let log = (message) => {
  generalLogger.log({
    level : 'verbose',
    message : message
  });
};

let debug = (message) => {
  generalLogger.log({
    level : 'debug',
    message : message
  });
};

let info = (message) => {
  generalLogger.log({
    level : 'info',
    message : message
  });
};

let warn = (message) => {
  generalLogger.log({
    level : 'warn',
    message : message
  });
};

let error = (message) => {
  generalLogger.log({
    level : 'error',
    message : message
  });
};

module.exports = {
  log,
  debug,
  info,
  warn,
  error
};

And then use the file in your main file (I have used index.js).

const express = require('express');
const logger = require('./logger');


const APP_DEFAULT_PORT = 12341;

const app = express();
app.set('port', process.env.PORT || APP_DEFAULT_PORT);

const server = app.listen(app.get(’port’), function() {
  logger.info(`Express server listening on port ${server.address().port}`);
});

Running this app would give you an output of the following form.

This output seems very basic, so let’s try formatting it a bit.

For this, we’ll implement a custom logger and use the functionality provided by Winston

Change your logger file to accommodate the following coding lines.

const { createLogger, format, transports } = require('winston');
const { combine, timestamp, printf, colorize } = format;

const formatter = printf((info) => {
let object = {
    message : info.message
  };
return `${info.timestamp} ${info.level} ${JSON.stringify(object)}`;
});

const generalLogger = createLogger({
   format : combine(
     colorize(),
     timestamp(),
     formatter
   ),
   transports : [
    new transports.Console({
      json : true,
      colorize : process.stdout.isTTY,
      timestamp: function () {
        return (new Date()).toLocaleTimeString();
      },
      prettyPrint : true
    })
  ]
});

Add the following extra logs in your main file.

logger.warn(`I am a warn log message`);
logger.error(`I am an error log message`);

You would get a colored response with a timestamp as shown below.

Look closely at the code above and you will find that we have specified a colorize key while declaring the logger.

process.stdout.isTTY

The statement above evaluates to true only if logging is happening on standard output. Now that we have taken care of standard logging, let’s think about some corner cases. If you want you can look and explore the other options of Winston here.

Add the following line in your main file and then observe what happens when you execute it.

try{
  throw new Error('I am a custom error');
}catch(err){
  logger.error(err);
}

The error message evaluates to {}, but why?

If you read the javascript documentation you’ll come to know that the error object does not have any enumerable properties. So in order to counter that we’ll use the extra option of JSON.stringify function to our advantage and change the code as follows:

const replaceErrors = (key, value) => {
  if (value instanceof Error) {
    let error = {};

    Object.getOwnPropertyNames(value).forEach((newKey) => {
      error[newKey] = value[newKey];
    });

    return error;
  }

  return value;
};

And use it as shown below.

JSON.stringify(object, replaceErrors);

And now run the app again, you would get the correct output.

Finally, to complete your express server we would need to log request and response. And we can log each and every request and response of the system using the code below. Create a new file (I called it requestLogger.js) and add the following to it.

const logger = require('./logger');
const logRequestMeta = (req, response) => {
  const { url, body = {}, headers = {}, params = {}, query = {} } 
         = req;
  let logObject = {
    url,
    body,
    headers,
    params,
    query,
    response
  };
  logger.info(logObject);
};
const logResponse = (req, res, next) => {
  let originalSend = res.send;
  let chunks = [];
  res.send = function(chunk) {
    let response, body;
    if (chunk) {
      chunks.push(Buffer.from(JSON.stringify(chunk)));
    }
    try {
      body = Buffer.concat(chunks).toString('utf8');
    } catch (err) {
      logger.error(err);
    }
    try {
      response = JSON.parse(body);
    } catch (err) {
      response = String(body);
    }
    logRequestMeta(req, response);
    originalSend.apply(res, arguments);
  };
  next();
};
module.exports = logResponse;

In the function logRequestMeta we have extracted the basic parameters from the request and de-structured the same and sent to our previously implemented logger function.

In logResponse function we create a wrapper around the res.send function exposed by nodeJs and call our custom logger before the response is sent to the system. I have implemented it in such a way that it can be used as a middleware, you can achieve the same with the following code.

app.use(logResponse);

NOTE: you should use this middleware before declaring any routes in your app so that each and every request and response is logged correctly.

Create a dummy route in your application and test the code and you should have an output like the following.

Conclusion

By completing the above steps you have successfully configured the following types of logs for your application :

• General logs
• Errors
• Request-response

You can always add extra features to suit the needs of your application and make it handle all types of use cases you might encounter in the real-world scenario.

You can refer to the git repository for the same or drop a comment if you want to ask anything.

At the end I would just say good luck building your application and

Happy coding :)