Designing Error Messages and a Logging Strategy in Node.js

Error handling is one section of our job that we tend to neglect, especially when working on something new, interesting, or something we just need to get working. We'll handle errors later, we say — and that's often a big lie.

But that's not even the worst part. The problem comes when we decide to 'quickly' add some code to handle our errors and completely forget about the importance and relevance of a properly constructed error message.

Who cares about the other side as long as my app doesn't burn while crashing, right? Wrong. And don't even get me started on the lack of proper logging for those errors — who's interested in the person troubleshooting those midnight crashes?

These are prevalent situations that we need to learn to avoid. We can't code assuming our applications won't have issues (they will), and we can't think that no one will try to troubleshoot those issues. There is a lot of information that we can provide if we do it properly.

So let's see what a proper logging strategy looks like and how we can structure our error messages to be helpful.

The Importance of a Good Error Message

"There's been an error, try again later."

How many times have we read or written that error message (bad developer!). Who are we helping? And honestly, do you really think "try again later" solves anything? Is the problem going to fix itself magically? For the sake of our sanity, let's assume that it won't, shall we?

Error messages aren't there to get you out of crashing your app. They should help whatever or whoever is on the other side of the request to understand why they're not getting what they asked.

Notice how I said "whatever or whoever." That's because we live in a world where people can use our systems through a piece of software, or an automated software can read errors directly.

Both need very different types of error messages.

We need to have an explanation of:

• what went wrong
• why it went wrong
• what we can do to fix it, if possible

On the other hand, automated systems won't benefit from such an approach since we all know getting machines to understand our language can be very hard. Instead, other systems might just need a single alphanumerical code representing the error code. They'll have an internal mapping to understand how to respond to problems.

From the perspective of returning a particular error message in Node.js, I like to take the JSON approach and return everything I need to return inside a single JSON object. For example, in the following code snippet, we return an error for a fictional sign-up form. In this scenario, the user attempts to register on our site with an already existing username:

{
    "error": {
        "error_code": "44CDA",
        "error_msg": "There was a problem with your username, it looks like it's already been taken, please try with a different one"
    }
}

The above error response does a few things:

1. It lets the other end know there is information about the error by encapsulating everything inside a single error key.
2. It returns a single error code for any potential system to automatically react to, without the need to parse and understand our error message.
3. It also returns a detailed explanation of the error for a human user to understand.

You could even expand on #3 and provide some suggested usernames that are currently available. But the example above is more than enough.

Another great practice for returning error messages is to consider the HTTP response code. This is, of course, only useful if you're working under HTTP (but let's assume you are).

As part of the standard (and this is why it's so useful — because it's a standard), we have the following groupings:

• 1XX (Informational responses) — These are informational statuses meant to let you know the server has received your request and is still working on it.
• 2XX (Successful responses) — OK return codes, meaning that whatever you tried to do, it worked.
• 3XX (Redirects) — Redirect messages usually mean that the resource you're trying to reach is no longer there.
• 4XX (Client errors) — These indicate that the problem is on the request, meaning it's incorrectly formatted, trying to access something that's not allowed, or some variation of that. In other words: it's your fault.
• 5XX (Server errors) — These indicate that something went terribly wrong on the server-side. Your code crashed, and it couldn't recover, thus the 500 error.

Read all about the different status codes.

With this in mind, we know that we could potentially group our custom error codes into two categories:

• Errors generated by the user
• Errors generated by our code

Why would we do this? Why isn't the custom error code enough? It actually is in some situations. However, if you're dealing with client code that you know follows HTTP standards, such as a web browser, then you're providing them with information that they can automatically use to improve the way they handle the error.

So, for instance, back to our 'invalid username' error example: we would return it with an HTTP Status Code of 400 — 'bad request.' The request initiated by the user is incorrect, as they wanted to sign-up with an already taken username.

How to Log Errors in Node.js

Consider the necessity of understanding why errors happen. Why does your application constantly return the same error message stating that a username is already taken?

Meanwhile, this is causing users to complain that they can't sign-up to your app, so you'd better figure out what's happening fast.

This is where logging comes into play — because returning a good error message to the user is only half the battle.

What happens when the user is getting the wrong error message? You, my friend, have a problem. But you now need to understand it and figure out how to solve it. Doing this without proper logging will be a pain, especially if you're troubleshooting a production application.

How Does a Good Logger Look?

What is a "good logger" after all?

Well, it's not console.log("This is my log message"), that's for sure.

A good logger is a piece of code that can do multiple things, ideally all at once:

• Help you log a message (duh!).
• Handle any type of variable (including objects) being logged. That means correct serialization of attributes.
• Add metadata to the message, such as its importance (or level, as it is commonly known), a timestamp, or the message's origin (the module, for instance, or the function name).
• Persist that message somewhere.
• Format the message for easier human interaction (e.g., add colors, bold words, etc.).

At a high level, this is exactly what you want to look for in any logger you either build or import into your code. Just make sure that you use one that's accessible throughout your code. This is crucial because another problem with an unsupervised logging strategy is that multiple developers often try to solve the same problem differently. You and your colleagues will inevitably each build your unique version of the ideal logger, tailored to your particular needs.

That is a problem right there, not only because you're repeating logic, but also because you're potentially handling some related issues in different ways. For instance:

• Message formatting
• Extra metadata
• Message persistence

Instead, ensure that you're all using the same logger, following the same standards, and doing the same thing with the output.

What to Do with Logged Data

A vital topic to cover when it comes to logging is what to do with logged data. Every time you log a message, you're generating data that needs to go somewhere.

That 'somewhere' can simply be the console — a volatile place where everything that's not actively watched or captured somehow gets lost. So if you're not looking at the log output, then you'll miss it. This means that storage-wise, you have it very simple; however, by losing the data, there is no chance for you to correctly troubleshoot your application when something goes wrong.

You have to think about your logs as pictures of the state of your system at any given time. The more pictures you have, the better your ability to re-live it.

That means we need to save our logs. But where? Saving into a local file can be dangerous because if you're not manually truncating those files, your hard drive might run out of disk space. The very solution you've used then ends up causing a big problem.

Ironic, isn't it?

Instead, consider using an external utility such as Logrotate — a Linux utility that allows you to manage your log files automatically. For instance, you can zip and rename your log files automatically by setting thresholds on files' age and sizes. When these triggers get fired, Logrotate will create a new, empty log file and "rotate" the old one so that it is archived. You can control how many archive files are created. When a set number is reached, the oldest one is deleted, and a new one added.

An alternative is to send the log messages to other platforms such as Loggly or Logz.io, which receive, index, and provide you with search functionality over your logs.

This, in turn, makes it very easy to traverse the full set of logs, especially when you're logging on multiple servers (for example, when you have copies of the same service).

Logs are a wonderful tool to use when things go wrong, but they require you to pay attention to something other than your code. Storage is one of the main aspects of logging that many people ignore — and they end up crashing their servers due to a lack of disk space. Make sure you have a storage strategy to go alongside your logging strategy, and you'll have no issues.

Logging Libraries for Node.js

Like with anything in JavaScript, there are way too many logging library options out there.

I got 6,219 results on NPM's site when searching 'logging'. The endless options can be intimidating.

That being said, only a few of these results are worth using, as they're actively maintained and used by millions of users. So let's focus on those options, and you can go from there.

Winston

Winston is, by far, my personal favorite. It's a very versatile library that integrates with major platforms when it
comes to storage.

Essentially, Winston is a logging library that allows you to:

• Create your own loggers
• Customize the output format and logging level
• Control how you'll store those logs
• Decide different storage options for different levels

For example, you could decide that error-level logs — those you want to keep an eye out for — are sent to DataDog. At the same time, you can determine that any info-level logs will go to a local file that gets rotated when it reaches 100Mb of size and display debug-level logs on the terminal.

Winston's plugin-based architecture means it stays relevant even after new logging products are released because developers create integrations with the plugins and publish them on NPM.

Creating a logger with Winston is as simple as doing the following:

const winston = require('winston');

const logger = winston.createLogger({
  level: 'info', //Sets the default level
  format: winston.format.json(), //Sets the default format
  defaultMeta: { service: 'user-service' }, //Adds extra meta-data
  transports: [ //Configures the transports, or essentially where do log messages go...
    //
    // - Write all logs with level `error` and below to `error.log`
    // - Write all logs with level `info` and below to `combined.log`
    //
    new winston.transports.File({ filename: 'error.log', level: 'error' }), //Error log files for error-level logs
    new winston.transports.File({ filename: 'combined.log' }), //Simple file for everything together
  ],
});

//
// If we're not in production then log to the `console` with the format:
// `${info.level}: ${info.message} JSON.stringify({ ...rest }) `
//
if (process.env.NODE_ENV !== 'production') {
  logger.add(new winston.transports.Console({
    format: winston.format.simple(),
  }));
}

Notice how, through the use of the createLogger method, we're creating a new instance of a Winston logger. And through the configuration object we pass to the method, we make sure this particular instance behaves as expected:

• The default level is going to be info.
• The format that every message will have is JSON.
• It'll also add one extra field to every logged message: service with the value "user-service".
• Error-type logs are saved into a specific file called error.log.
• And all logs, in general, will go to a file called combined.log.

That entire configuration will make your particular instance unique, and you can build as many as you want (although you'd normally build one).

Finally, an extra transport is added in case we're not in a production environment (we check this through the value of the environment variable NODE_ENV): the console. This means that if we're dealing with a non-production deployment, we'll send every log into the terminal, and the format for all messages will be plain text with no JSON-like structure. This is especially useful for debugging purposes.

Finally, simply use:

logger.info("This is an info message!");
logger.error("Something terrible happened, look out!");

As you can see, the magic methods appear. You don't have to worry about whether you're logging in a production environment, or if you want one of these messages to be saved into a file. It's all transparent to you now.

Check out this complete list of Winston integrations with external systems.

Logging

Logging is a basic yet functional logging library. It only works for your terminal, so you can't control where or how logs are stored through code.

That being said, nothing stops you from capturing the terminal's output and redirecting it to a file, to get rotated using logrotate.

Using this library is super easy. All you have to worry about is creating a logger around a particular feature, and then you'll have custom methods for each log level, just like with Winston.

import createLogger from 'logging';

const logger = createLogger('MyFeature');

logger.info('Interesting information you need to know');
logger.warn('Hmmm..., this data is not correct', { details });
logger.error('Not good.', 'Not good at all.', { err }, { context }, { etc });

/**
This would output:

[ MyFeature ] Interesting information you need to know
[ WARNING MyFeature ] Hmmm..., this data is not correct { details object }
[ ERROR MyFeature ] Not good. Not good at all. { err } { context } ...
*/

In the above code, we also have the same createLogger method we had with Winston. However, this time around, it's a bit simpler.

We only care about naming the feature we're logging (the parameter that the method receives), and that's it. The rest of the magic methods come back, but they all do pretty much the same thing — they log those messages to the terminal.

As I mentioned, this is a very basic library that doesn't do a lot — but what it does do, it does very well. External libraries can do the rest.

Log4js

If you're familiar with Java, you probably know about log4j. Log4js is an attempt to port that functionality into Node.js.

The creator's README does not recommend assuming that this library works like its Java counterpart — however, it's safe to assume certain similarities.

Much like Winston, Log4js is packed with possibilities and configuration options. You can decide how to format your logs and where to store them.

Its list of integrations is not as big — there are only 11 options available.

Don't get me wrong though, these are 11 more than Logging, and you probably only need one per project. You'll hardly ever need to consider sending your logs to different places, even if you had the chance to do so.

From the library's documentation:

const log4js = require("log4js");
log4js.configure({
  appenders: { cheese: { type: "file", filename: "cheese.log" } },
  categories: { default: { appenders: ["cheese"], level: "error" } }
});

const logger = log4js.getLogger("cheese");
logger.trace("Entering cheese testing");
logger.debug("Got cheese.");
logger.info("Cheese is Comté.");
logger.warn("Cheese is quite smelly.");
logger.error("Cheese is too ripe!");
logger.fatal("Cheese was breeding ground for listeria.");

Here, we have a mixture of Winston and Logging because, as you can see, we're configuring a specific instance of the logger.

We're setting up one particular file to contain all of our logs — cheese.log — and we're also adding a default error level (much like we did for Winston). However, we then create one particular logger instance around the "cheese" category (like we did with Logging).

This code will output the following to your terminal:

[2010-01-17 11:43:37.987] [ERROR] cheese - Cheese is too ripe!
[2010-01-17 11:43:37.990] [FATAL] cheese - Cheese was a breeding ground for listeria.

Why only two lines? Because, as you can see, the default level for the 'cheese' category is "error", everything below
that level only gets saved to the cheese.log file.

If you ask me, unless you're an ex-Java developer who's familiar with log4j, I would skip this one and go straight to Winston.

Are there more options? Absolutely: Bunyan, Pino, and others. It depends on what your particular logging needs are.

What to Log in Your Node.js Projects

Let's leave the actual libraries aside for now. It's important to understand that there is an unspoken standard between them all. You may have noticed mentions of "log-levels" and methods such as debug, error, info, and others from the small code snippets above.

You see, not every log message is created equal — they don't all have the same importance or relevance at any given point in time.

You'll want to see some messages every time your application runs because they'll let you know everything is working correctly. There are other messages that you'll only care about if things start to go wrong.

The basic log levels that most libraries tend to adopt are:

• Info — Meant for messages that display useful yet concise information. You want to use info-level messages to show that a process got called, but not what parameters it received or how long it ran.
• Error — This one's easy enough. When things don't work out, and you catch an error, you'll use an error level message to save as much detail about the error as you can. Remember, error messages need to be useful. See this post on long error messages to read more about how you can make error messages useful.
• Debug — This is the 'verbose' level. As you'll use this when you're debugging your application, you need a lot of details about what's happening. Here, you'd include things like full-stack trace dumps or list the full content of an array. Things that it doesn't make sense to see constantly, but you need to make sure that everything goes where it's supposed to go.

There might be other log levels depending on the library, such as warn — to indicate messages that live between an info state and an error state. In other words, warn flags something that needs attention — for example, a missing config file.

While you can still use default values, you could instead write something like this:

[Warn] Missing configuration file on ./config, using default values

This could be written as an info message as well, but an extra level of logging allows you to filter and organize the information a lot better.

You might also see a fatal level, which is worse than an error — for instance, a crash on your server (i.e., something you can't recover from) would be a perfect use case for fatal.

Finally, a level that goes beyond debug is trace. This level contains all the super detailed messages that you only want to see when something is wrong, and you need to understand what's happening inside your application.

An example is an Extract, Transform and Load (ETL) process, where you extract information from a source, transform it somehow and finally load it into a storage system (this could be a database, the file system, or anything in between).

If you start seeing that your data is corrupted at the end of this process, you need to understand when the corruption happened. You'll have to know exactly what happens to the data at each step, and that is where a trace level of logging can come in handy.

Once you're done checking your logs, you can revert to a less verbose default logging level. Let's look at that now.

Default Logging Level

We can't always log everything. This is another important concept to understand when defining our logging strategy.

Even if we split different log levels into different destinations, we can't always spend computational resources logging every detail of our business logic.

Logging hurts performance the more you do it, so keep that in mind as well.

So what do we do instead? The log levels mentioned above are sorted by priority, for example:

1. trace
2. debug
3. info
4. warn
5. error
6. fatal

If we want to use the less verbose levels, we could set the default level to info. Then, even if we had direct calls to the debug and trace methods, they would be ignored because the library would only pay attention to our default level and anything with higher priority.

In the same vein, if we only care about error messages for some reason, we can set the default level to error and get error and fatal logs, but nothing else. So we toggle certain levels based on a single value. The perfect use case for this is to enable different levels depending on our deployment environment.

Let's pretend we have three environments:

• Dev — where we test new features ourselves
• QA — where we let others test our features
• Prod — the final environment where we deploy our code once it's ready

We could have different default logging levels in each environment.

For example, trace could be a default for our Dev environment to get the most details about how our code executes. Only we care about that level, so it makes sense that it's only the default here.

For the QA environment, we could have the info level as our default, in case something goes wrong or we want to monitor what's happening during tests. We're assuming things work here, so we don't need the details provided by
debug or trace.

Finally, we'll only want to use the error level as default for our Prod environment because we only care about things going wrong. If nobody complains, we're good. This also provides the lowest possible performance loss since we're only logging when something bad happens.

You can control the default value with an environment variable, like this:

const winston = require('winston');

const logger = winston.createLogger({
  level: process.env.NODE_LOG_LEVEL || "info", //using the default log level or info if none provided
  //... rest of the implementation
});

The example above shows that you can grab any environment variable through the process.env global object. By default, if we can't find the variable, we use the "info" value.

You can set that directly on the execution of the script:

$ NODE_LOG_LEVEL=error node server.js

Or through a bash script where you export the variable directly:

$ export NODE_LOG_LEVEL=info

Wrap-up: Choose the Right Node.js Logger and Useful Error Messages

Any application you're developing requires a logging strategy. Luckily for us, Node.js has a bunch of very interesting and useful loggers. As long as you understand your use case and your strategy, you can then pick the right one for you.

As for your strategy, remember the two most important things to decide are:

1. What are you going to do with error messages?
2. How are you going to structure them?

Once you've answered those two questions, it just comes down to picking the right library and adding logging lines.

Check out this article for more tips on logging in your Node.js apps.

Happy coding!

P.S. If you liked this post, subscribe to our JavaScript Sorcery list for a monthly deep dive into more magical JavaScript tips and tricks.

P.P.S. If you need an APM for your Node.js app, go and check out the AppSignal APM for Node.js.

Fernando Doglio is an engineering manager, blogger, book author, and maker of software things. He loves writing, especially about software. Get in touch with him on his blog or Twitter.