Node.js Logging Tutorial

Node.js logging is an important part of supporting the complete application life cycle. From creation to debugging to planning new features, logs support us all the way. By analyzing the data in the logs, we can glean insights, resolve bugs much quicker, and detect problems early and as they happen.

There are many ways to perform Node.js logging. We can use what’s built in, or rely on one of the many popular packages to improve logging. The ideal way to accomplish logging is to pipe the stdout and stderr to your preferred log destination. This is because the main logger—debug—writes directly to process.stdout and process.stderr. If we would take those writable streams and fork them to another stream, we’d be in business! There’s a feature request out to the folks at Node.js to allow us to observe these writable streams. With that in place, things will change for the better. Here’s what we have now:

Console.log

The original method of logging is console.log. It has variants like console.error, console.info, and console.warn. Those are just convenience methods over the base function which is:

console.log(level, message)

You can write to console.log, but you have little control over where things log from outside the code. So, we have the next best thing.

Debug module

With so many packages using debug, it’s tempting to think we should hook directly into its power. Sure, we can enable it and get output to the console. The trouble is, this is most we can do with it. We can redirect stdout and stderr to a file.

The benefit of using debug is that many packages use it. You can turn it on to get additional info on what’s going on in web middleware like Express and Koa when your back-end gets a web request. The good frameworks will give you a way to hook up logging middleware, but you might not get all the details sent to it.

Middleware

So what is middleware? Middleware is just something you can put into the request pipeline. Requests and responses pass through the middleware. You can set up middleware in just about any framework you’ll use. Express, for example, is one of the most popular API frameworks. You can set up logging middleware in several ways:

application

const app = express()
const loggingMiddleware = require('my-logging-middleware')
app.use(loggingMiddleware)

router

const router = express.Router()
const routeLoggingMiddleware = require('my-route-logging-middleware')
router.use(routeLoggingMiddleware)

errors

const app = express();
const errorLoggingMiddleware = require('my-error-logging-middleware')
app.use(errorLoggingMiddleware)

There’s a definite pattern in the way we set middleware in Express. You can set middleware on individual route templates too. Each type of middleware function takes specific arguments. It may be tempting (and you may see this in the docs) to write the middleware, or to use a logging package directly in your app code like this:

// DON'T DO THIS!!!
app.use(function(req, res, next) 
{
    console.log(req.url)
    next()
}

But you don’t want to do this. This will trap you into having to change everything when you want to enhance your code. Instead, wrap your logging in your own utility code, as you would with any I/O. This way, you can change behavior centrally.

Logging With Winston

Winston is a flexible logging library for Node.js. From its inception, Winston was designed to be simple yet configurable, so it includes support for custom log formats, sending log messages to multiple types of destinations, and colorizing logs. Critically, Winston also comes with a feature we’ve been missing in our discussions until now – logging levels.

No one wants to pick through log messages in the middle of a heated troubleshooting session to figure out whether, at that moment, a particular message is vitally important or inconsequential noise.

The best logging frameworks offer logging levels so you can highlight the messages you care about. Use them correctly when writing code and they will save you a lot of time when you need to view only a select category of messages.

The logging levels available in Winston are those from npm. Ordered from most important to least important, the corresponding functions are: error, warn, info, verbose, debug, and silly.

The component used to send log messages to their destination is known as a transport, and a Winston logger can use multiple transports at the same time. This comes in handy if you want to use Winston’s core transports to send debug or info logs to the console, and use one of the community transports to send critical messages to a remote log management tool.

Here is an example of creating a simple logger object with winston that writes a debug and error string:

const winston = require(‘winston’);

const logger = winston.createLogger({
  level: 'info',
  format: winston.format.simple(),
  transports: [
    //
    // - Write to all logs with level `info` and below to `combined.log` 
    // - Write all logs error (and below) to `error.log`
    //
    new winston.transports.File({ filename: 'error.log', level: 'error' }),
    new winston.transports.File({ filename: 'combined.log' })
  ]
});

logger.info(‘Info string’);
logger.error(‘Error string’);

Writing a message with the highest priority level (error) writes to both combined.log and error.log:

$ cat combined.log 
info: Info string
error: Error string

Node.js logging packages

Next, we’re looking at Node.js logging packages. Winston is one of the most popular logging utilities. The cool thing is, it can take more than one output transport. Unfortunately, because Node.js works as it does, you still can’t pipe the output of “debug” into a different transport. Otherwise, it would be great to do that, and send all the debug logs to whatever you want! Here’s how you set Winston up in Express:

const app = express()
const winston = require('winston')
const consoleTransport = new winston.transports.Console()
const myWinstonOptions = 
{
    transports: [consoleTransport]
}
const logger = new winston.createLogger(myWinstonOptions)

function logRequest(req, res, next) 
{
    logger.info(req.url)next()
}
app.use(logRequest)

function logError(err, req, res, next) 
{
    logger.error(err)
    next()
}
app.use(logError)

Incorporating Winston is easy because it is highly configurable. You can set up multiple transports with filtering, set custom formatters, and use more than one logger instance. In the code above, I’m only logging the requested URL.

You can set a formatter on your request logger that prepares the request and response for logging. Here are sample snippets:

'use strict'
const winston = require('winston')
const remoteLog = new winston.transports.Http(
{
    host: "localhost",
    port: 3001,
    path: "/errors"
})

const consoleLog = new winston.transports.Console()

module.exports = 
{
    requestLogger: createRequestLogger([consoleLog]),
    errorLogger: createErrorLogger([remoteLog, consoleLog])
}

function createRequestLogger(transports) 
{
    const requestLogger = winston.createLogger({
        format: getRequestLogFormatter(),
        transports: transports
    })
    
    return function logRequest(req, res, next) 
    {
        requestLogger.info({req, res})next()
    }
}

function createErrorLogger(transports) 
{
    const errLogger = winston.createLogger(
    {
        level: 'error',
        transports: transports
    })
    
    return function logError(err, req, res, next) 
    {
        errLogger.error({err, req, res})next()
    }
}

function getRequestLogFormatter() 
{
    const {combine, timestamp, printf} = winston.format;
    
    return combine(
        timestamp(),
        printf(info => 
        {
            const {req, res} = info.message;
            return ${info.timestamp} ${info.level}: ${req.hostname}${req.port || ''}${req.originalUrl};
        })
    );
}

This setup will create logging middleware using Winston. The middleware plugs into the Express request pipeline. Keep in mind the patterns you’re seeing here. The middleware is reusable. You can apply this pattern to any framework you’re using. And if you want to hook in the debug module, you just change this file to include it.

If you’re using Retrace, there’s a package that plugs right into this model via a Stackify transport. And for Express, there’s a middleware handler built into the Stackify logger. It makes Node.js logging even easier! Combined with the global handler, it logs global and route exceptions.

var stackify = require('stackify-logger')

// logs global exceptions to Retrace
stackify.start({apiKey: '***', env: 'dev'})

// logs Express route exceptions to Retrace
app.use(stackify.expressExceptionHandler)

// or add the Stackify transport
require('winston-stackify').Stackify
winstonLogger.add(winston.transports.Stackify, {storage: stackify})

// or create a Stackify transport and include that in your loggers transports
require('winston-stackify').Stackify
const stackifyTransport = new winston.transports.Stackify(
{
    storage: stackify
})

This is great for Node.js logging within application code, but it doesn’t stop there. Something can go wrong outside your web host, and you need to pay attention to that as well.

Server logs

It’s worth mentioning, while we’re on the subject, that server logs are an important piece of the big picture—application monitoring. You need to keep an eye on this no matter what hosting environment you’re using. The ideal solution is to send all the information to a single place. Application logs, database logs, and server logs should be taken as a whole since these things in aggregate impact your users. You can capture server logs using the Retrace agent.

What should I log?

Deciding what to log is fairly important. Node.js logging has to be done purposefully. There are a few key categories of logging to consider, and each has its own purpose. Although there’s no general standard, here are common levels of Node.js logging:

error
warn
info
verbose
debug

Each of these can be loosely correlated with a specific purpose. In the built-in Node.js console log, all logging levels equate to either log or error. The different levels of logging give us a way to treat log events differently.

Why should I log?

It may be clear to you why you should log, but just to close the loop, here are the main reasons.

Performance—You and your users care about performance. To measure it, track it somehow. Logging is one way to do this, but APM tools that do this automatically are even better.
Debugging—Stuff happens. We’re only human and will make mistakes. Our development processes have become rather robust, but they’re made by humans. So, we inevitably need to debug. The first step in debugging is log analysis where we need to see where the error occurred and under what conditions.
Error tracking—When errors do happen, it helps to know when they started, how often they occurred, for whom they occurred, if they’ve been resolved, and if they’ve resurfaced. Those are just a few reasons to keep track of errors.
Analyzing logs—Logs are rich sources of information. You can analyze logs to discover usage patterns to guide troubleshooting.