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.

In this post, we will talk about the who, what, when, where, how, and why of Node.js logging. Later in this post, the “how” section will give insights into using code. But to kick it off, we’ll briefly cover who uses logs.

Who Uses Logs?

Operations engineers and developers use logs for debugging. Product managers and UX designers use logs for planning and design. Marketers want to track the performance of various features that relate to advertising campaigns.

Anyone with a vested interest in the company can benefit from insights that logs can provide. But you’ll only realize your logs’ value when they’re properly analyzed. And to do that, we need to log the right things.

To get the insights and value you need from your logs, you need to send them to log management tools for further analysis and reporting.

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.

Let’s look at each category to get a good sense before we move into the when, where, how, and why.

Exceptions

Log levels “error” and “warn” will go to stderr when called from the console.

We want to log exceptions so we know when our application has an error. Not all exceptions are caused by bugs in our code. For example, there might be trouble with a network connection. Our code can handle this kind of exception because we are expecting it. Although, some exceptions aren’t predictable and stem from corrupt data.

We could plan for every exception, but it would add considerable time to our development efforts. We’d have an ultra-robust piece of software, but it would be released years too late! So, the occasional edge-case exception will happen. Services we depend on change without notice and cause our programs to freak out. These things happen.

But we don’t have to be derailed if they do. We need to be prepared and have a way to respond. Agility is about responding to change. Some change causes pain in the form of exceptions. So long as we log them and have a proper alerting mechanism, we can handle it (pun intended).

Try Stackify’s free code profiler, Prefix, to write better code on your workstation. Prefix works with .NET, Java, PHP, Node.js, Ruby, and Python.

Information

Log levels “info” or “log” will both go to stdout from the console functions.

Information is just that. This log level is for major events that are supposed to happen. It’s also used for logging messages to other developers, although it might be best to save some of those messages for verbose and debug.

Some developers like to put easter eggs in the info log. Reddit has this neat little gem in theirs right now:

 ,d"=≥,.,qOp,
                 ,7'  ''²$(  )
                ,7'      '?q$7'
             ..,$,.
   ,.  .,,--***²""²***--,,.  .,
 ²   ,p²''              ''²q,   ²
:  ,7'                      '7,  :
 ' $      ,db,      ,db,      $ '
  '$      ²$²      ²$²      


ASCII art like this one is common, actually. Facebook has a little warning to non-devs that says “you should not be here, someone may be trying to trick you into doing something bad!”

Debugging

For log levels “debug” and “verbose,” this is where you’ll send detailed information.

There’s a difference between the two, as with all levels. However it is complex as there may be more levels and variances depending on the package you use. Debug level can contain things like stack traces, input and output parameters, or special messages for developers. Verbose should include every event that happened, but not necessarily as much detail as debug. Debug is the highest level in this hierarchy.

In Node.js logging, it’s more important to have consistency. As long as you define your own conventions shared within your organization, stick to those and things will line up nicely!

When Should I Log?

You may think the answer to “when should I log?” is obvious. “Right away,” you might say. And in a knee-jerk reaction, I’d commit to that answer too. But to “question everything”, we can see that it isn’t so plain and simple.

Node.js logging starts at the source. Surely we want to send the log message right away. Sometimes, this means waiting until something completes. For example, a timer to measure the speed of a function has to wait until the function completes. We don’t even have to log that one either. If it’s within the bounds of a web request, we can also wait until that request completes to log it. This way, our logging is less noisy.

Hypothetically, your pipeline might look like this:

var req = defineRequest()
receiveRequest(req)

var timer = new DiagnosticTimer(context)
timer.measure(// do work)
timer.measure(// do more work)
var res = buildResponse()
...
sendResponse(req, res)
logRequest(req, res, timer)

Even if you called some kind of log function, it won’t hit the logs immediately. Imagine thousands of log requests coming into a single point all at once. That single point might be a log file, but it could be Retrace’s ingest endpoint or both. You’d quickly end up with a bottleneck. So you need some kind of queue mechanism to throttle those log requests. A good logging framework should take care of things like throttling.

Does everything need to get recorded in the log immediately when log.error is called in the code? That depends. When the output is the console or stdout/stderr, it should. When it’s a file or network location, it should probably get queued up somewhere.

This brings up the important question of where to send your logging data.

Where Should I Log?

I’ve mentioned loose coupling already. This is most appropriately exemplified by an event source pattern. A microservices architecture often uses an event source pattern. It comprises multiple services that place events on a bus or queue. We can respond to those events by independent processes “listening” to the queue.

Log events are just another type of event, and they can be queued. Multiple listeners can listen to the queue and write to whatever log they want. With this kind of flexibility comes a level of added complexity. It’s often the case where we register a single logger to the log call. There’s a range of possibilities, but whatever we use for logging needs to handle the number of log messages. Here are some of the most common log locations.

stdout/stderr or console

In Node.js, the basic console.log and console.info will log to stdout. Console.warn and console.error will log to stderr. By default, these will print the output to your console. On the front-end, this will be the developer tools console (assuming it’s open). When you’re running your Node.js back-end locally, this is usually enough. But in some scenarios, you might want to consider logging to a file.

Log File

You can redirect stdout and stderr to a file and not have to touch your code if you’ve already used the console everywhere. You do this by doing the usual redirect when you launch your application:

node app.js > app.log 2>&1

This would redirect stdout to a file named app.log and redirect stderr to stdout.

When would you want to log to a file? In production, you’ll usually want to log to a persistent store. A file is the most basic way to persist logs. But it isn’t the best long-term solution.

Sometimes when you’re running locally, you’ll want to log to your file system. This can be helpful when you have multiple processes running at once. They may even be in separate containers. Either way, you’ll want to pull all the logs together when you have a process, such as a workflow, that spans multiple processes. It’ll make the analysis easier. You don’t want to be bouncing around between different log outputs to correlate the events.

What’s even better than log files?

Log Management Tools

For logging, the best thing is to flow structured events into a log management tool. Structured logging makes it easier to correlate the data, find patterns, and make the data more useful. Persisting the logs in a centralized logging database—specifically, one intended for the purpose—makes querying the data more efficient.

Node.js Logging

There are so 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.

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 express = require("express");
const { createLogger, transports } = require("winston");

const app = express();
const logger = createLogger({
transports: [new transports.Console
});

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.

And let’s not forget the network. Most of us don’t control the network, but it might be worth considering how you might log network issues. Sometimes errors are rooted in the network. If we don’t have insight into network issues, we can chase our tails looking for a cause after an incident. We inevitably end up shrugging and blaming ghosts. Wouldn’t it be better to have a definitive answer right away?

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.

Node.js Logging with Stackify

Node.js logging plays an integral role in the whole pipeline of any node.js application. Node.js logging impacts nearly everyone with a stake in the application. From users to executives to designers and developers, logs are critical to the feedback loop that drives success. We should log anything from minutiae to exceptions.

There are different levels of logging that serve different purposes. And we don’t always need to log right away. Sometimes, it benefits us to place a log message onto a queue or wait until something completes before we log.

You can log to the terminal, the file system, a database, and send the log messages over HTTP. You can and should log to multiple locations when appropriate. Use a logging package such as Winston to give you flexibility. It’s best to abstract your logger for even greater flexibility. Install an agent to monitor your server.

We do this to improve our applications for usability and profit!

Be sure to check out our product, Retrace APM, which can help you view all of your Node.js logs, track exceptions, and even understand the performance of your code.

Try our FREE 14-day trial today!

Improve Your Code with Retrace APM

Stackify's APM tools are used by thousands of .NET, Java, PHP, Node.js, Python, & Ruby developers all over the world.
Explore Retrace's product features to learn more.

• App Performance Management
• Code Profiling
• Error Tracking
• Centralized Logging
• App & Server Metrics

Learn More

Author

Phil

More articles by Phil