Kubernetes with OpenShift World Tour: Get hands-on experience and build applications fast! Find a workshop!

Learn Node.js, Unit 10: Logging Node applications with Winston and Log4js

Many events occur when a server-side application runs, and most are written to a log file. The log file might be a collection of files on disk or a series of records in a database. Regardless, the practice of writing diagnostic information to logs is known as logging.

Logged events include:

  • The state of records as the database reads them.
  • Anytime the application cannot connect to the database.
  • Information to assist in application debugging.

Logs tell us what happened, and the log is typically the first place a programmer looks to diagnose a problem. While the most critical system events are broadcast to a management tool, all events are logged.

In this unit, learn about logging and get to know two of the most popular loggers in the Node ecosystem: Winston and Log4js.

The challenge of logging

Writing diagnostic information to the console or a log file isn’t difficult. What matters is doing it consistently across the lifetime of the application.

Unfortunately, developers have different assumptions about what logging is used for, and some simply do not realize its importance. If you’ve supported an application that is more than a few years old, you’ve probably seen the results: some parts of the code are thoroughly logged, while others are not logged at all.

Whatever the cause, inconsistent logging becomes a real issue when you need to debug your application. Experienced server-side developers generally understand the value of logging, whereas front-end developers often do not.

Choosing a good logging package

Using a logging tool will improve the quality and consistency of your logging, and fortunately the Node ecosystem offers many good packages to choose from. The trick is knowing what to look for.

In my experience, a logging package must be configurable, so that you can customize it. After that, I look for these must-have capabilities:

  • It should support multiple log channels, so that you can send logs to various destinations (console, files, database, etc.).
  • It should support flexible configuration, enabling both programmatic and external configuration styles.
  • It should support multiple log priorities, because some types of message are more important than others.
  • It should enable different log formats, which the programmer can configure and customize.
  • It should recognize multiple log categories, because different functional areas need to be logged differently.

Both of the packages introduced in this unit have all of these capabilities and more.

Winston

Winston is one of the most popular logging packages available, with almost two million downloads per week. Based on the three-part score I introduced in Unit 7 ( quality, popularity, and maintenance) Winston’s score is 81 (98/82/67, respectively).

Winston - from npmjs.com

Winston is easy to use and incredibly popular, and you are very likely to run across it as a professional Node developer.

Log4js

Log4js is another popular logging package, with over a million downloads per week and a three-part score of 76 (98/68/67, respectively).

Log4js - from npmjs.com

While it’s not as popular or highly rated as Winston, Log4js has all the qualities I look for in a logger. It also has a very similar feel to log4j, making it a popular choice for Java developers who have transitioned to Node.js.

Logging examples

Before going further, let’s set up the examples we’ll use to try out our two loggers. There are two ways to access the source code and run the examples for this unit:

  1. Navigate to the Unit-10 directory in the Course repository and run the examples.
  2. Start with an empty directory and an empty package.json. Then create and run the examples as you go along.

Accessing source from the terminal

If you choose the first option, open a terminal window or command prompt and navigate to the Unit-10 directory in the Course repository. The full path on my Mac is ~/src/projects/IBM-Developer/Node.js/Course/Unit-10. Make sure to run npm install in that directory at least once (although if you follow along with the installation instructions in each section that will happen anyway).

Creating source as you go

If you prefer the second option, you will need to create a package.json that looks like this:

Listing 1. package.json for running examples in this unit

{
  "name": "unit-10",
  "version": "1.0.0",
  "main": "unit-10.js",
  "license": "Apache-2.0",
  "scripts": {
    "lint": "eslint .",
    "lint-fix": "npm run lint -- --fix",
    "pre-run": "npm run lint && mkdir -p logs",
    "example-1": "npm run pre-run && node ./example-1",
    "example-2": "npm run pre-run && node ./example-2",
    "example-3": "npm run pre-run && node ./example-3",
    "example-4": "npm run pre-run && node ./example-4",
    "example-5": "npm run pre-run && node ./example-5",
    "example-6": "npm run pre-run && node ./example-6",
    "example-7": "npm run pre-run && node ./example-7",
    "example-8": "npm run pre-run && node ./example-8",
    "example-9": "npm run pre-run && node ./example-9",
    "example-10": "npm run pre-run && node ./example-10",
    "example-11": "npm run pre-run && node ./example-11",
    "example-12": "npm run pre-run && node ./example-12",
    "example-13": "npm run pre-run && node ./example-13",
    "example-14": "npm run pre-run && node ./example-14",
    "example-15": "npm run pre-run && node ./example-15",
    "example-16": "npm run pre-run && node ./example-16",
    "example-17": "npm run pre-run && node ./example-17"
  },
  "repository": {
    "type": "git",
    "url": "https://github.com/jstevenperry/node-modules"
  },
  "devDependencies": {
    "babel-eslint": "^8.2.6",
    "eslint": "^5.2.0",
    "eslint-config-google": "^0.9.1"
  },
  "eslintConfig": {
    "extends": [
      "eslint:recommended",
      "google"
    ],
    "env": {
      "node": true
    },
    "parserOptions": {
      "ecmaVersion": 6
    },
    "rules": {
      "max-len": [
        2,
        120,
        4,
        {
          "ignoreUrls": true
        }
      ],
      "spaced-comment": 0,
      "no-trailing-spaces": 0,
      "comma-dangle": 0,
      "object-curly-spacing": 0,
      "array-bracket-spacing": 0,
      "no-console": 0
    }
  },
  "eslintIgnore": [
    "node_modules"
  ]
}

Now run npm install to install the devDependencies.

Important note: Be sure to save the examples in JavaScript files that match the example number in the same directory as package.json. Save example-1 in a file called example-1.js, example-2 in a file called example-2.js, and so forth.

Spot the linter

Looking closely at Listing 1, you probably noticed that the npm scripts are set up to lint the code before every example runs.

{
  "name": "unit-10",
  "version": "1.0.0",
.
.
  "scripts": {
    "lint": "eslint .",
    "lint-fix": "npm run lint -- --fix",
    "pre-run": "npm run lint && mkdir -p logs",
    "example-1": "npm run pre-run && node ./example-1",
    "example-2": "npm run pre-run && node ./example-2",
    "example-3": "npm run pre-run && node ./example-3",
    .
    .
  }
.
.
}

I lint my code before running anything, so that I can catch potential errors as early and often as possible. I suggest making this practice a habit.

Logging with Winston

Install Winston

To install Winston, run the npm i winston command. The output should look something like this (the version you install may be different from mine):

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm i winston
npm WARN unit-10@1.0.0 No description

+ winston@3.0.0
added 194 packages from 214 contributors and audited 380 packages in 4.252s
found 0 vulnerabilities

In the next sections, I cover how Winston implements each of the core capabilities I recommend in a third-party logging package.

Multiple log channels (transports) in Winston

In Winston’s terminology, a log channel is called a transport. Examples of built-in transports include:

Additionally, a number of transport contribs are maintained outside of the Winston project.

I’ll show you how Winston handles two of the most commonly used transports: console and file.

Console transport

As the name implies, the console transport is used to send logger output to the console (aka stdout). You create the console transport as part of your logger configuration, then call the createLogger() function. You will then call one of the Winston API methods to log messages.

Listing 2 shows two ways of logging a message.

Listing 2. Winston console transport

const winston = require('winston');

// Logger configuration
const logConfiguration = {
    'transports': [
        new winston.transports.Console()
    ]
};

// Create the logger
const logger = winston.createLogger(logConfiguration);

// Log a message
logger.log({
    message: 'Hello, Winston!',
    level: 'info'
});
// Log a message
logger.info('Hello, Winston!');

To see this example in action, save the code to example-1.js, and then run npm run example-1. When you run example-1, the console output will look like something this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-1

> unit-10@1.0.0 example-1 /Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-10
> npm run pre-run && node ./example-1


> unit-10@1.0.0 pre-run /Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-10
> npm run lint && mkdir -p logs


> unit-10@1.0.0 lint /Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-10
> eslint .

{"message":"Hello, Winston!","level":"info"}
{"message":"Hello, Winston!","level":"info"}

Two ways to log in the console

Notice the last two lines of the above output. These identical lines show the results of the two different ways of logging a message from example-1.

The first way to log a message using the Winston API is the log() function, where you pass an object containing two properties:

  • message: The message text you want to log
  • level: The message level, which is one of:
    • silly
    • debug
    • verbose
    • info
    • warn
    • error

Don’t worry about levels for now; you work with them later in this unit.

The second way to log a message is to call the API function with the same name as the message level (info(), warn(), and so on), then pass only the message you want logged.

Listing 2 shows both ways to pass a message. Going forward, I’ll use the second way because it’s simpler.

File transport

File transport is used to send output to a file whose name you specify in the configuration. Just create the file transport as part of the logger configuration, then call a createLogger() function passing the configuration object. To log the message, call one of the Winston API methods, like so:

Listing 3. Winston file transport

const winston = require('winston');

// Logger configuration
const logConfiguration = {
    'transports': [
        new winston.transports.File({
            filename: './logs/example-2.log'
        })
    ]
};

// Create the logger
const logger = winston.createLogger(logConfiguration);

// Log a message
logger.info('Hello, Winston!');

To see this example in action, save the above code to example-2.js, then run npm run example-2. When you run example-2, the console output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-2
.
.
.
> unit-10@1.0.0 lint /Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-10
> eslint .

There is no logging-related console output because the file transport sends the output to a file, in this case ./logs/example-2.log:

{"message":"Hello, Winston!","level":"info"}

Multiple Winston transports

It is very common for an application to have the same log output going to multiple destinations (or transports), as Listing 4 shows.

Listing 4. Multiple Winston transports in the same configuration object

const winston = require('winston');

// Logger configuration
const logConfiguration = {
    transports: [
        new winston.transports.Console({
            level: 'verbose'
        }),
        new winston.transports.File({
            level: 'error',
            filename: './logs/example-3.log'
        })
    ]
};

// Create the logger
const logger = winston.createLogger(logConfiguration);

// Log some messages
logger.silly('Trace message, Winston!');
logger.debug('Debug message, Winston!');
logger.verbose('A bit more info, Winston!');
logger.info('Hello, Winston!');
logger.warn('Heads up, Winston!');
logger.error('Danger, Winston!');

Notice that both console and file transports are added to the transports array in the configuration object.

To see this example in action, save the above code to example-3.js and run npm run example-3. When you run example-3 the console output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-3
.
.
.
{"message":"A bit more info, Winston!","level":"verbose"}
{"message":"Hello, Winston!","level":"info"}
{"message":"Heads up, Winston!","level":"warn"}
{"message":"Danger, Winston!","level":"error"}

The console transport’s level was set to verbose, so not all of the log statements showed up in the console output. Additionally, the file transport’s level was set to error, so only one of the log statements showed up in the log file. The contents of ./logs/example-3.log look like this:

Ix:/tmp/IBM-Developer/Node.js/Course/Unit-10 sperry$ cat logs/example-3.log
{"message":"Danger, Winston!","level":"error"}

You’ll learn more more about levels shortly.

Flexible configuration in Winston

In the examples so far, the Winston configuration object was located in the same module as the logger that used it, but this isn’t mandatory. One of the capabilities to look for in a logger is its ability to be configured externally to the code that uses it. Winston has this capability.

Consider the following configuration as an example.

Listing 5. External configuration in ./config/app-settings.js

const winston = require('winston');

const appSettings = {
    winston: {
        sillyLogConfig: {
            level: 'silly',
            transports: [
                new winston.transports.File({
                    filename: './logs/silly.log'
                }),
                new winston.transports.Console()
            ]
        },
    },
    log4js: {
        traceLogConfig: {
            appenders: {
                fileAppender: { type: 'file', filename: './logs/trace.log'},
                consoleAppender: { type: 'console' }
            },
            categories: {
                default: { appenders: ['fileAppender', 'consoleAppender'], level: 'trace'}
            }
        }
    }
};

module.exports = appSettings;

If you’re creating source code as you go, you need to create a directory that’s subordinate to the location of your package.json, called config. Then you’ll create another file called app-settings.js. Paste both of these into the contents of Listing 5.

To use this external configuration, use require() as you would any other Node module, and pass the sillyLogConfig to Winston’s createLogger() function, as shown below.

Listing 6. External configuration located in ./config/app-settings.js

const winston = require('winston');

// App settings
const { sillyLogConfig } = require('./config/app-settings').winston;

// Create the logger
const logger = winston.createLogger(sillyLogConfig);

// Log some messages
logger.silly('Trace message, Winston!');
logger.debug('Debug message, Winston!');
logger.verbose('A bit more info, Winston!');
logger.info('Hello, Winston!');
logger.warn('Heads up, Winston!');
logger.error('Danger, Winston!');

To see this code in action, save the above code in example-4.js and run npm run example-4.

When you run example-4, the console output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-4
.
.
.
{"message":"Trace message, Winston!","level":"silly"}
{"message":"Debug message, Winston!","level":"debug"}
{"message":"A bit more info, Winston!","level":"verbose"}
{"message":"Hello, Winston!","level":"info"}
{"message":"Heads up, Winston!","level":"warn"}
{"message":"Danger, Winston!","level":"error"}

The file output goes to ./logs/silly.log and looks just like the console output:

Ix:/tmp/IBM-Developer/Node.js/Course/Unit-10 sperry$ cat logs/silly.log
{"message":"Trace message, Winston!","level":"silly"}
{"message":"Debug message, Winston!","level":"debug"}
{"message":"A bit more info, Winston!","level":"verbose"}
{"message":"Hello, Winston!","level":"info"}
{"message":"Heads up, Winston!","level":"warn"}
{"message":"Danger, Winston!","level":"error"}

Note: At the time of this writing, the Winston configuration object must be a JavaScript object. You cannot currently configure Winston using pure JSON, for example. However, an issue has been posted, and Winston is actively maintained, so stay tuned!

Multiple log priorities in Winston

Another capability to look for in a production-quality logging package is the ability to support multiple log priorities, also known as levels. You’ve already seen this in example-3 and example-4. Now we’ll look more closely at Winston’s support for logging levels.

With respect to how log levels are defined, Winston follows the design of RFC5424, as Listing 7 shows.

Listing 7. Winston’s standard log levels

const levels = {
  error: 0,
  warn: 1,
  info: 2,
  verbose: 3,
  debug: 4,
  silly: 5
};

According to this standard, levels are defined in reverse-numerical order. That is, the more important the message, the lower the priority number. As an example, an error message is more important than a debug message, so the error message has a lower number.

In my opinion, this order is completely backward. While I respect Winston for at least following a standard, I suspect RFC5424’s definition of log levels is based on a pre-existing implementation (Linux kernel log priorities), rather than being guided by an intuitive sense of what the word priority means.

This information will be important when we create custom log levels, which we’ll do very shortly.

Overriding priority levels

In Listing 8, we create a Winston logger, then override its level so we can see all of its messages.

Listing 8. Viewing messages at all available levels

const winston = require('winston');

// Logger configuration
const logConfiguration = {
    transports: [
        new winston.transports.Console({
            level: 'error'
        })
    ]
};

// Create the logger
const logger = winston.createLogger(logConfiguration);
// Let's see ALL the log levels
logger.transports[0].level = 'silly';

// Log some messages
logger.silly('Trace message, Winston!');
logger.debug('Debug message, Winston!');
logger.verbose('A bit more info, Winston!');
logger.info('Hello, Winston!');
logger.warn('Heads up, Winston!');
logger.error('Danger, Winston!');

Note that in this case there is only a console transport.

To see this example in action, save the above code in example-5.js and run npm run example-5. When you run example-5, the console output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-5
.
.
.
{"message":"Trace message, Winston!","level":"silly"}
{"message":"Debug message, Winston!","level":"debug"}
{"message":"A bit more info, Winston!","level":"verbose"}
{"message":"Hello, Winston!","level":"info"}
{"message":"Heads up, Winston!","level":"warn"}
{"message":"Danger, Winston!","level":"error"}

Custom log levels

As I noted, we can replace Winston’s standard log levels with our own, as shown below.

Listing 9. Defining custom log levels in Winston

01 const winston = require('winston');
02
03 // Custom log levels
04 const noteLevels = {
05     values: {
06         doe: 10,
07         ray: 20,
08         me: 30,
09         far: 40,
10         sew: 50,
11         la: 60,
12         tea: 70
13     }
14 };
15
16 // Logger configuration
17 const logConfiguration = {
18     level: 'far',
19     levels: noteLevels.values,
20     transports: [
21         new winston.transports.Console()
22     ]
23 };
24
25 // Create the logger
26 const logger = winston.createLogger(logConfiguration);
27
28 /**
29  *
30  */
31 function doLogging() {
32     // Log some messages
33     logger.tea('Tea, Winston!');
34     logger.la('La, Winston!');
35     logger.sew('Sew, Winston!');
36     logger.far('Far, Winston!');
37     logger.me('Me, Winston!');
38     logger.ray('Ray, Winston!');
39     logger.doe('Doe, Winston!');
40 }
41
42 // Do some logging as the logger was setup
43 logger.doe(`Logging messages, current log level: ${logger.level}`);
44 doLogging();
45
46 // Now modify the level
47 logger.level = 'tea';
48 logger.doe(`Logging messages, current log level: ${logger.level}`);
49 doLogging();
50
51 try {
52     logger.info('The previously used log methods no longer work!');
53 } catch (err) {
54     logger.doe(`${err.message}`);
55 }

To see this example in action, save the above code to example-6.js (removing the line numbers first), and run npm run example-6. The output will look like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-6
.
.
.
{"message":"Logging messages, current log level: far","level":"doe"}
{"message":"Far, Winston!","level":"far"}
{"message":"Me, Winston!","level":"me"}
{"message":"Ray, Winston!","level":"ray"}
{"message":"Doe, Winston!","level":"doe"}
{"message":"Logging messages, current log level: tea","level":"doe"}
{"message":"Tea, Winston!","level":"tea"}
{"message":"La, Winston!","level":"la"}
{"message":"Sew, Winston!","level":"sew"}
{"message":"Far, Winston!","level":"far"}
{"message":"Me, Winston!","level":"me"}
{"message":"Ray, Winston!","level":"ray"}
{"message":"Doe, Winston!","level":"doe"}
{"message":"logger.info is not a function","level":"doe"}

Notes about the Winston code

Let’s go over the above code line by line.

First, you see the custom levels defined in lines 4-14.

Next, lines 17-23 create the Winston configuration object. Notice line 19 in particular, where the newly defined levels are set. This replaces the default levels shown in Listing 7.

Also notice that the doLogging() function (line 31) is called twice:

  • Once on line 44, to log using the log level that was set when the configuration object was created.
  • Again on line 49, after the log level has been set to tea (line 47), where all the levels show up.

Finally, when you define your own log levels and use them to create a Winston configuration object, the default levels no longer apply. In fact, Winston will complain if you try to use them; see lines 51-55, and also notice the final log message:

{"message":"logger.info is not a function","level":"doe"}

Formatting in Winston

A production-quality logger should allow you to format the messages that get logged.

Examples so far have logged messages in JSON format, but Winston provides many other formats for log messages. We’ll look at two of them: printf and splat.

Before we get into these formats, it’s important to understand Winston’s formatting framework. The main thing to remember is that a Winston message centers around an info object that has at least two properties: level and message.

Every logger instance you create (via createLogger()) has a format property that you can set to the type of formatter you want to use. Winston comes with several built-in formatters that can be combined to handle pretty much whatever log message format you need.

Formatting with printf

Listing 10. Print-style formatting

01 const winston = require('winston');
02
03 // The Logger Category (functional area)
04 const CATEGORY = 'example-7';
05
06 // Logger configuration
07 const logConfiguration = {
08     transports: [
09         new winston.transports.Console()
10     ],
11     format: winston.format.combine(
12         winston.format.label({
13             label: CATEGORY
14         }),
15         winston.format.timestamp(),
16         winston.format.printf((info) => {
17             return `${info.timestamp} - ${info.label}:[${info.level}]: ${info.message}`;
18         })
19     )
20 };
21
22 // Create the logger
23 const logger = winston.createLogger(logConfiguration);
24
25 logger.info('Howdy, Winston!');

The formatter in this example is created in lines 11-19, and is a combination of Winston’s built-in label() (lines 12-14), timestamp() (line 15), and printf() (lines 16-18) formatters.

Also note that line 17 controls the message that is logged:

    return `${info.timestamp} - ${info.label}:[${info.level}]: ${info.message}`;

If you match up the fields, you can see exactly how the message was computed:

  • info.timestamp is from line 15.
  • info.label is from lines 12-14.
  • info.level is the log level from the info object.
  • info.message is the message text you want to log (line 25).

To see this example in action, save the code to example-7.js. Strip out the line numbers first, then run npm run example-7. The console output looks like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-7
.
.
.
2018-07-26T01:22:09.087Z - example-7:[info]: Howdy, Winston!

Formatting with splat and simple

If you want to control the formatting right when a log function is invoked, you can combine the splat and simple formatters.

  • splat() formats level.message based on Node’s util.format() function.
  • simple() returns level.info along with level.message.

Listing 11. Formatting with splat and simple

const winston = require('winston');

// The Logger Category (functional area)
const CATEGORY = 'example-8';

// Logger configuration
const logConfiguration = {
    transports: [
        new winston.transports.Console()
    ],
    format: winston.format.combine(
        winston.format.splat(),
        winston.format.simple()
    )
};

// Create the logger
const logger = winston.createLogger(logConfiguration);

logger.warn('%d - %s: Howdy, Winston!', Date.now(), CATEGORY);

To see this example in action, save the above code to example-8.js and run npm run example-8. The console output look like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-8
.
.
.
warn: 1532569853985 - example-8: Howdy, Winston!

Winston provides several more built-in formatters that you can learn about by reading the WinstonJS docs and the Winston logform docs.

Note: In this example, the message is logged at a level of warn, which is the value of level.info. The name collision between the info object and the info level is confusing until you give the info object docs a thorough read. If you’re going to use Winston, I suggest you invest the time to do that.

Log categories in Winston

The final feature we’ll look at for Winston is the ability to segment logger instances based on the functional areas of your application. Winston provides this capability through the notion of a container.

Consider the following examples, noting that I’ve removed the comments to save space.

First, there is a function to create a Winston configuration, as Listing 12 shows.

Listing 12. Create a Winston configuration

01 const winston = require('winston');
02
03 const DEFAULT_CATEGORY = 'DEFAULT';
04
05 function createLoggerConfig(category) {
06     return {
07         level: 'info',
08         transports: [
09             new winston.transports.Console()
10         ],
11         format: winston.format.combine(
12             winston.format.label({
13                 label: category
14             }),
15             winston.format.timestamp(),
16             winston.format.printf((info) => {
17                 return `${info.timestamp} - ${info.label}:[${info.level}]: ${info.message}`;
18             })
19         )
20     };
21 }
22 winston.loggers.add(DEFAULT_CATEGORY, createLoggerConfig(DEFAULT_CATEGORY));
23
24 module.exports.defaultLogger = winston.loggers.get(DEFAULT_CATEGORY);
25
26 module.exports.createLoggerConfig = createLoggerConfig;

If you are manually creating the source, strip out the line numbers, then save this listing to ./config/winston-config.js. You should also be sure to add a JSDoc comment to the createLoggerConfig() function, otherwise the linter will complain about it. (If you want to avoid complaint, you could disable the linting rule in package.json, but I leave that option as an exercise for the reader.)

The module in Listing 12 defines a default category (line 3), then adds a logger to Winston’s internal Container store (line 22), and exports that as defaultLogger (line 24). The createLoggerConfig() function (lines 5-21) is also exported, so it can be called as follows:

Listing 13. Log categories

01 const winstonConfig = require('./config/winston-config');
02
03 const winston = require('winston');
04
05 let defaultLogger = winstonConfig.defaultLogger;
06 defaultLogger.info('Beginning program execution...');
07
08 const MODULE = 'example-9';
09
10 winston.loggers.add(MODULE, winstonConfig.createLoggerConfig(MODULE));
11 const moduleLogger = winston.loggers.get(MODULE);
12
13 moduleLogger.info('Howdy, Winston!');
14 moduleLogger.warn('WARNING, Winston!');
15 moduleLogger.error('ERROR, Winston!');
16
17 const FOO = 'foo';
18 const BAR = 'bar';
19
20 winston.loggers.add(FOO, winstonConfig.createLoggerConfig(FOO));
21 winston.loggers.add(BAR, winstonConfig.createLoggerConfig(BAR));
22
23 const fooLogger = winston.loggers.get(FOO);
24 fooLogger.info('Howdy, Winston!');
25
26 const barLogger = winston.loggers.get(BAR);
27 barLogger.info('Howdy, Winston!');
28
29 defaultLogger.info('Program terminated.');

Notes about the code

A lot is going on in this simple example, so let’s walk through it.

First, the default logger (line 5-6), which was exported from ./config/winston-config.js is used to output a message.

Then, the configuration for a new logger category is defined (line 8), added to Winston’s container store (line 10), and then a logger object is retrieved (line 11). That logger is specific to this module (example-9), and is used to log a few messages.

Then two new category configurations are created, added (lines 20-21), and their logger instances are retrieved in the same manner (lines 23, 26).

To see this example in action save the above code to example-9.js (don’t forget to strip out the line numbers first) and run npm run example-9. The console output looks like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-9
.
.
.
2018-07-26T02:10:19.402Z - DEFAULT:[info]: Beginning program execution...
2018-07-26T02:10:19.404Z - example-9:[info]: Howdy, Winston!
2018-07-26T02:10:19.404Z - example-9:[warn]: WARNING, Winston!
2018-07-26T02:10:19.404Z - example-9:[error]: ERROR, Winston!
2018-07-26T02:10:19.405Z - foo:[info]: Howdy, Winston!
2018-07-26T02:10:19.405Z - bar:[info]: Howdy, Winston!
2018-07-26T02:10:19.405Z - DEFAULT:[info]: Program terminated.

Notice that the category appears as the label, because that’s how it was configured (see Listing 12, line 13).

That’s it for Winston, at least for this unit. Next you’ll install and try out Log4js.

Logging with Log4js

Install Log4js

To install Log4js, run the npm i log4js command. The output should look something like this (the version you install may be different from mine):

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm i log4js
npm WARN unit-10@1.0.0 No description

+ log4js@3.0.2
added 4 packages from 2 contributors and audited 400 packages in 1.916s
found 0 vulnerabilities

In the next section, we look at how Log4js implements each of the five core capabilities you should look for in a logging package.

Multiple log channels (appenders) in Log4js

In Log4js terminology, a log channel is called an appender. Examples of built-in appenders include:

For more appenders, see the list.

Once again, we’ll look at two of the most commonly used appenders: console and file.

Console appender

As the name implies, the console appender is used to send logger output to the console. Log4js has a built-in configuration that includes a console appender, so you don’t need to explicitly add it. Request a logger instance from Log4js by calling getLogger(). Make sure to set the log level, then log a message by calling one of the following Log4js API methods:

Listing 14. Log4js console appender

const log4js = require('log4js');

// Create the logger
const logger = log4js.getLogger();
logger.level = 'info';

// Log a message
logger.info('Hello, log4js!');

Note: By default, the log level is OFF. You must set the logger level, or nothing will be logged.

To see this example in action, save the above code to example-10.js and run npm run example-10. When you run example-10, the output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-10
.
.
.
[2018-07-25T22:06:00.154] [INFO] default - Hello, log4js!

File appender

The file appender is used to send output to a file whose name you specify in the configuration.

Listing 15. Log4js file transport

const log4js = require('log4js');

// Logger configuration
log4js.configure({
    appenders: { fileAppender: { type: 'file', filename: './logs/example-11.log' } },
    categories: { default: { appenders: ['fileAppender'], level: 'info' } }
});

// Create the logger
const logger = log4js.getLogger();
logger.level = 'info';

// Log a message
logger.info('Hello, log4js!');

Notice the additional call to log4js.configure(), which is required if you override the default console appender to add your own.

To see this example in action, save the above code to example11.js, and then run npm run example-11. The console output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-11
.
.
.
> unit-10@1.0.0 lint /Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-10
> eslint .

There’s no logging-related console output because the file appender sends the output to a file. In this case, the file is ./logs/example-11.log, and the contents look like so:

Ix:/tmp/IBM-Developer/Node.js/Course/Unit-10 sperry$ cat logs/example-11.log
[2018-07-26T21:52:29.801] [INFO] default - Hello, log4js!

Multiple transports

It is very common for an application to send the same log output to multiple destinations. You can add multiple appenders to the Log4js configuration object like this:

Listing 16. Multiple Log4js appenders in the same configuration

const log4js = require('log4js');

// Logger configuration
log4js.configure({
    appenders: {
        fileAppender: { type: 'file', filename: './logs/example-12.log' },
        console: { type: 'console' }
    },
    categories: {
        default: { appenders: ['fileAppender', 'console'], level: 'error' }
    }
});

// Create the logger
const logger = log4js.getLogger();

// Log a message
logger.trace('Trace, log4js!');
logger.debug('Debug, log4js!');
logger.info('Hello, log4js!');
logger.warn('Heads up, log4js!');
logger.error('Danger, log4js!');
logger.fatal('Fatal, log4js!');

To see this example in action, save the above code to example-12.js and run npm run example-12. The console output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-12
.
.
.
[2018-07-26T21:56:24.196] [ERROR] default - Danger, log4js!
[2018-07-26T21:56:24.201] [FATAL] default - Fatal, log4js!

The console appender’s level was set to info (the default), so not all of the log statements from example-12 showed up in the console output.

The file transport’s level was set to error, so only one of the log statements showed up in the log file. The contents of ./logs/example-12.log look just like the console output:

Ix:/tmp/IBM-Developer/Node.js/Course/Unit-10 sperry$ cat logs/example-12.log
[2018-07-26T21:56:24.196] [ERROR] default - Danger, log4js!
[2018-07-26T21:56:24.201] [FATAL] default - Fatal, log4js!

Flexible configuration in Log4js

In the examples so far, the Log4js configuration object was located in the same module as the logger that used it, but this isn’t mandatory. Like Winston, Log4js can be configured externally to the code that uses it.

Recall the following configuration snippet in ./config/app-settings.js, from Listing 5:

Listing 17. Log4js external configuration in ./config/app-settings.js

const appSettings = {
.
.
    log4js: {
        traceLogConfig: {
            appenders: {
                fileAppender: { type: 'file', filename: './logs/trace.log'},
                consoleAppender: { type: 'console' }
            },
            categories: {
                default: { appenders: ['fileAppender', 'consoleAppender'], level: 'trace'}
            }
        }
    }
};

module.exports = appSettings;

For this external configuration, use require() as you would any other Node module, and pass the traceLogConfig to Log4j’s configure() function as you see here:

Listing 18. External configuration located in ./config/app-settings.js

const log4js = require('Log4js');

// App settings
const { traceLogConfig } = require('./config/app-settings').log4js;

// Logger configuration
log4js.configure(traceLogConfig);

// Create the logger
const logger = log4js.getLogger();

// Log a message
logger.trace('Trace, Log4js!');
logger.debug('Debug, Log4js!');
logger.info('Hello, Log4js!');
logger.warn('Heads up, Log4js!');
logger.error('Danger, Log4js!');
logger.fatal('Fatal, Log4js!');

To see this code in action, save the above code in example-13.js and run npm run example-13. The console output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-13
.
.
.
[2018-07-26T21:58:28.084] [TRACE] default - Trace, Log4js!
[2018-07-26T21:58:28.089] [DEBUG] default - Debug, Log4js!
[2018-07-26T21:58:28.089] [INFO] default - Hello, Log4js!
[2018-07-26T21:58:28.089] [WARN] default - Heads up, Log4js!
[2018-07-26T21:58:28.089] [ERROR] default - Danger, Log4js!
[2018-07-26T21:58:28.089] [FATAL] default - Fatal, Log4js!

The file output goes to ./logs/trace.log, and looks just like the console output:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ cat ./logs/trace.log
[2018-07-25T22:25:04.796] [TRACE] default - Trace, Log4js!
[2018-07-25T22:25:04.800] [DEBUG] default - Debug, Log4js!
[2018-07-25T22:25:04.801] [INFO] default - Hello, Log4js!
[2018-07-25T22:25:04.801] [WARN] default - Heads up, Log4js!
[2018-07-25T22:25:04.801] [ERROR] default - Danger, Log4js!
[2018-07-25T22:25:04.801] [FATAL] default - Fatal, Log4js!

You can also configure Log4js using a pure JSON object. Consider the following JSON:

Listing 19. Pure-JSON configuration in log4js-config.json

{
    "appenders": {
        "consoleAppender": {
            "type": "console", "layout": {
                "type": "pattern", "pattern": "%d - %c:[%p]: %m"
            }
        }
    },
    "categories": {
        "default": {
            "appenders": ["consoleAppender"],
            "level": "info"
        }
    }
}

If you’re using the create-as-you-go option, you need to create a new file in the ./config directory called log4js-config.json and paste in the contents of Listing 19.

For this external configuration, use require() as you would any other Node module, and pass the traceLogConfig to Log4j’s configure() function, as shown here:

Listing 20. Pure JSON configuration

const log4js = require('log4js');

// Logger configuration
log4js.configure('./config/log4js-config.json');

// Default logger
const logger = log4js.getLogger();

// Log a message with the default logger
logger.info('Howdy, Log4js!');

To configure the logger, just pass it the name of a file containing the JSON configuration, and you’re good to go.

To see this code in action, save it to example-14.js and run npm run example-14. When you run example-14, the output looks like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-14
.
.
.
2018-07-25T22:38:32.424 - default:[INFO]: Howdy, Log4js!

Multiple log priorities (levels) in Log4js

Next we’ll look at how Log4j’s handles multiple log priorities, also known as levels.

Listing 21. Log4js default levels

Level.addLevels({
  ALL: { value: Number.MIN_VALUE, colour: 'grey' },
  TRACE: { value: 5000, colour: 'blue' },
  DEBUG: { value: 10000, colour: 'cyan' },
  INFO: { value: 20000, colour: 'green' },
  WARN: { value: 30000, colour: 'yellow' },
  ERROR: { value: 40000, colour: 'red' },
  FATAL: { value: 50000, colour: 'magenta' },
  MARK: { value: 9007199254740992, colour: 'grey' }, // 2^53
  OFF: { value: Number.MAX_VALUE, colour: 'grey' }
});

You will find a list of all Log4js-supported levels here.

The lowest priority message (TRACE) has a value of 5,000, whereas the highest priority message (FATAL) has a value of 50,000. Seems like Log4js approaches the concept of priority in the same way I do. On the other hand, Log4js doesn’t allow you to customize log levels like Winston does, and the defaults are fairly opaque.

Moving on, let’s create a Log4js logger, then we’ll override its level so we can see all of its messages.

Listing 22. Messages at all available levels

const log4js = require('log4js');

// Create the logger
const logger = log4js.getLogger();
// Let's see ALL of the levels!
logger.level = 'trace';

// Log a message
logger.trace('Trace, log4js!');
logger.debug('Debug, log4js!');
logger.info('Hello, log4js!');
logger.warn('Heads up, log4js!');
logger.error('Danger, log4js!');
logger.fatal('Fatal, log4js!');

Not that in this example there is only a console transport.

To see this example in action, save the above code in example-15.js and run npm run example-15. The console output looks something like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-15
.
.
.
[2018-07-26T22:06:00.588] [TRACE] default - Trace, log4js!
[2018-07-26T22:06:00.591] [DEBUG] default - Debug, log4js!
[2018-07-26T22:06:00.591] [INFO] default - Hello, log4js!
[2018-07-26T22:06:00.591] [WARN] default - Heads up, log4js!
[2018-07-26T22:06:00.591] [ERROR] default - Danger, log4js!
[2018-07-26T22:06:00.591] [FATAL] default - Fatal, log4js!

Formatting in Log4js

A production-quality logger should give you a variety of options for formatting messages that get logged. Log4js does this by offering a variety of layout types, including the one shown in Listing 23.

Listing 23. Log4js pattern formatter

const log4js = require('log4js');

// The Logger Category (functional area)
const CATEGORY = 'example-16';

// Logger configuration
log4js.configure({
    appenders: {
        consoleAppender: {
            type: 'console',
            layout: {
                type: 'pattern',
                pattern: '%d - %c:[%p]: %m'
            }
        }
    },
    categories: { default: { appenders: ['consoleAppender'], level: 'info' } }
});

// Create the logger
const logger = log4js.getLogger(CATEGORY);

logger.info('Howdy, Log4js!');

If you want to override Log4js’s default formatting, you simply add an element called layout, then specify a layout type.

In Listing 23, the layout type is pattern. Because the type is pattern you must specify the pattern property, which is the pattern string and is specific to Log4js (see the layout documentation for more details).

In this case the values are:

  • %d for the timestamp (that is, the date), formatted in ISO8601 format.
  • %c for the log category (example-16 in this case).
  • %p for the log level (or priority if you prefer).
  • %m for the message to be logged.

To see this example in action, save the above code to example-16.js and run npm run example-16. The console output looks like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-16
.
.
.
2018-07-26T22:04:27.801 - example-16:[INFO]: Howdy, Log4js!

Log4js has other layouts you can specify, including these two:

  • basic includes the ISO8601 date, log level and message (equivalent to a pattern of [%d] [%p] [%c] - [%m]).
  • messagePassThrough includes just the message.

You can also create your own layouts. Check out the layout documentation if you want to learn more.

Log categories in Log4js

A production-quality logging package should allow you to segment logger instances based on the functional areas of your application. In this section you’ll see how Log4js handles that capability.

First, to retrieve a new instance of a pre-configured logger for a different category, simply pass the name of the category to the getLogger() call, as show below (note that I’ve removed the comments and added line numbers):

Listing 24. Log categories

01  const log4js = require('log4js');
02
03  const MODULE = 'example-17';
04
05  const defaultLogger = log4js.getLogger();
06  defaultLogger.level = 'info';
07  defaultLogger.info('Beginning program execution...');
08
09  log4js.configure('./config/log4js-config.json');
10
11  const moduleLogger = log4js.getLogger(MODULE);
12
13  moduleLogger.info('Howdy, Log4js!');
14  moduleLogger.warn('WARNING, Log4js!');
15  moduleLogger.error('ERROR, Log4js!');
16
17  const FOO = 'foo';
18  const BAR = 'bar';
19
20  const fooLogger = log4js.getLogger(FOO);
21  fooLogger.info('Howdy, Log4js!');
22
23  const barLogger = log4js.getLogger(BAR);
24  barLogger.info('Howdy, Log4js!');
25
26  defaultLogger.info('Program terminated.');

Notes about the Log4js code

There’s a lot going on in this simple example, so let’s walk through it.

First, the default logger is retrieved and a message is logged indicating program execution start (lines 5-7).

Then, the logger is configured using the JSON configuration from ./config/log4js-config.json (line 9).

Next, a module-specific instance of the logger is retrieved (line 11) and a few messages are logged using the module-specific logger (lines 13-15).

In lines 20-24, two new category configurations are created, added, and their logger instances retrieved in the same manner.

Finally, the default logger is used to output a message indicating program termination (line 26).

To see this example in action, save the above code to example-17.js (don’t forget to strip out the line numbers first), then run npm run example-17. The console output looks like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-10 sperry$ npm run example-17
.
.
.
[2018-07-26T22:08:21.771] [INFO] default - Beginning program execution...
2018-07-26T22:08:21.775 - example-17:[INFO]: Howdy, Log4js!
2018-07-26T22:08:21.776 - example-17:[WARN]: WARNING, Log4js!
2018-07-26T22:08:21.776 - example-17:[ERROR]: ERROR, Log4js!
2018-07-26T22:08:21.776 - foo:[INFO]: Howdy, Log4js!
2018-07-26T22:08:21.777 - bar:[INFO]: Howdy, Log4js!
2018-07-26T22:08:21.777 - default:[INFO]: Program terminated.

Other loggers

Winston and Log4js are not the only loggers available, and you should be aware of additional options. While I can’t cover them here, these two are also very popular and worth considering–especially now that you know what to look for in a logger:

Conclusion to Unit 10

In this unit you learned what to look for in a production-quality logging package. A good logging package should be configurable, with support for at least the following:

  • Multiple log channels (console, files, database, etc.)
  • External as well as programmatic configuration styles
  • Multiple log priorities (also known as levels)
  • A variety of log formats
  • Multiple log categories

Examples in this unit also walked you through installing Winston and Log4j, and you saw how each of these loggers implements the features I’ve recommended for a production quality logger.

Now that you know what to look for in a logger, you can use what you’ve learned to evaluate other logging packages, including the two I mentioned but did not cover here: npmlog and bunyan.

Video

J Steven Perry