Getting Started Quickly With Node.js Logging

Previously, we covered how to get started with logging in C#, Java, Python, and Ruby. Now, we’ll take a look at Node.js logging. As in the other articles, we’ll cover

  • How to log very basically.
  • What to log and why.
  • How to log using a logging framework.

We’ll also accompany everything with practical examples so you can get started with logging in Node.js quickly and easily.

Node.js Hexagon with Scalyr Colors

The Simplest Node.js Logging That Could Possibly Work

Let’s write a small Node.js application that logs incoming requests. For this demo, I’ll be using Visual Studio Code, but any editor or IDE will do.

Also, make sure you’ve installed the latest version of Node.js and npm. Currently, they’re at version 8.9.4 and 5.6.0, respectively.

Finally, we’ll have to run some commands from the command line. You can use the terminal of your choice. I use GitBash because it integrates nicely with Git, but you should be fine with the default terminal of your operating system.

Create a new folder and open a command line in it. Initialize a new project by running “npm init”:

This will result in several questions you need to answer. For the sake of this demo, most can be left empty so that the default values are used. The output will look like this:

In the above example, we’ve defined index.js as our entry point. So let’s create that file now. Open Visual Studio Code, and open the folder we’ve created:

 

In the left pane, you’ll see there aren’t any files or folders yet:

When you hover your mouse pointer over the left pane, you’ll see an icon to add a file:

To be clear, this is the icon we want to use:

Name the file index.js and press ENTER.

We’ll be writing a simple web application that returns an HTTP 200 result when called. First, we need the HTTP module:

let http = require('http');

Then, we need to create a server and let it listen to a port:

http.createServer(onRequest).listen(8080);

We passed a callback function to the “createServer” method, so let’s define that function. This function should accept a “request” and a “response” object. The request object can be used to investigate what the client sent to our server. The response object can be used to manipulate the response we’ll be sending back to the client. This is our simple onRequest function:

function onRequest(request, response) {
    response.writeHead(200);
    response.end();
}

The end result looks like this:

let http = require('http');

http.createServer(onRequest).listen(8080);

function onRequest(request, response) {
    response.writeHead(200);
    response.end();
}

Now you can run this from the command line by running “node index.js.” To check if everything is running fine, you can point a tool like Postman to “localhost:8080” and see that it returns an HTTP 200 result. If you don’t have Postman installed, your browser’s developer tools will do fine too.

For example, open Chrome and press F12. You will see the developer tools. Click on the “Network” tab and you’ll see all network traffic as it happens:

In the screenshot below, I’ve used Chrome to see the requests and responses to our demo application. As you can see, I get back my HTTP 200.

Stop the application by pressing CTRL+C.

The simplest way we can add logging now is to call “console.log”:

function onRequest(request, response) {
    console.log('A request was received');

    response.writeHead(200);
    response.end();
}

Start the application again (with “node index.js”). When you make your requests now, you’ll see the message in the console:

Notice how I received two requests: one for the URL I entered in the browser, and another for favicon.ico. This last request is a default one the browser makes. If you’re using Postman, you’ll only see one log message.

A logical extension to this simple example would be to log to a file. After all, we want to be able to read the logs in cases where we don’t have access to the console. Node.js has a filesystem API that provides the mechanism to achieve this. Make a call to “fs.appendFile” and continue handling the request in its callback:

let http = require('http');
let fs = require('fs');

http.createServer(onRequest).listen(8080);

function onRequest(request, response) {
    fs.appendFile('log.txt', 'A request was received\n', (err) => {
        response.writeHead(200);
        response.end();
    });
}

This code will result in the same message produced before it was appended at the end of a log.txt file.

Of course, there are many shortcomings to this code. For example, it has no concept of log levels (e.g., info, error, warn, trace, etc.). Another issue is that we can’t easily write a message to another medium (a database, an email, etc.). And in general, we shouldn’t be writing our own logging framework when existing libraries do a better job at it.

Let’s take a step back and figure out what it is we want to do.

What Is Application Logging?

In our first article in this “Getting Started Quickly” series, we defined application logging as follows:

Application logging involves recording information about your application’s runtime behavior to a more persistent medium.

So in our simple example, our log message actually did record information about our application’s runtime behavior (the fact that we received a request). And it did record this to a persistent medium (the filesystem).

What’s the Motivation for Logging?

So why, then, do we log? The definition of logging that we just revisited already contains this information, though it may not be obvious at first sight. Two pieces of information are important here: first, the fact that we record the behavior of our application, and second, that we record to a persistent medium.

Why a persistent medium? Because we want to get to the logs later. This can be hours, days, or even months later. And why do we want information about our application’s behavior? Because software is inherently complex, and as developers, we must admit we cannot foresee every situation our application will find itself in. Users may enter invalid data we didn’t think about. Our server may start having hardware issues. Other services we depend upon might stop working. Anything can happen.

Logging can provide us with all this information after the fact.

What Should You Log?

Let’s first recap the point made in our Python article about what you shouldn’t be logging. You shouldn’t log sensitive or personal data like account numbers, passwords, credit card numbers, encryption keys, social security numbers, and email addresses. This is especially important in light of recent measures taken in defense of customer privacy, like the EU’s GDPR. You can check out the OWASP’s cheat sheet for a more detailed read.

A good log message contains at least three things:

  • A timestamp.
  • A log level.
  • A descriptive message.

This helps you replay what happened in your mind. You can then also link the messages to pieces of your code to navigate through the calls that were made.

Let’s look back at our example. We could start changing our code to accommodate for what I mentioned above. But this would require quite some code, making our application more complex than necessary.

To make matters even more complex, you could decide you need to log to more than just a file. You might need to log to a database, an email address, or an online service.

Enter the Logging Framework

Pull quote--once you get into the details of logging, it isn't quite so straightforwardLogging is, in essence, quite simple. Write some message to a file, and you’re done. But once you get into the details of logging, it isn’t quite so straightforward anymore. As I’ve mentioned, there’s the matter of multiple destinations. But you need to address other issues, too:

  • How do you avoid the log file becoming too large?
  • Do we need to worry about file access permissions, concurrent file access, etc.?
  • Do we need to write our own code to add the timestamp, log levels, and other information?
  • What if I want to log certain messages to one medium and others to another medium?

When you look at it like that, the simple task of logging becomes quite a daunting one. And shouldn’t we be focusing on the business problem we’re trying to solve?

Luckily, other developers have worked out mature solutions that will most likely fit your needs. These solutions come in the form of a logging framework.

A logging framework is a package that allows you to log a message with one line of code.  All you need to do is set up some configuration first, and the library will make sure your log messages are consistent and contain all information you require.

Unlike Python or Ruby, Node.js does not have a built-in logging framework. But there are several npm packages that provide the functionality we need. Let’s look into one of them now.

Getting Started With Winston

The most popular logging framework in the NodeJS community at the moment is Winston. As I’m writing this, Winston is at version 3.0.0, although that’s a release candidate. Winston uses the term “transports” to define the destinations for your loggers. To quote the documentation, “A transport is essentially a storage device for your logs.” Also, “Each winston logger can have multiple transports configured at different levels.”

Let’s add Winston to our application. First, we need to install Winston by running npm at the command line:

Notice how I’m specifically installing a version here. When Winston 3.0.0 has been officially released, you’ll be able to just run “npm install winston.”

Next, require Winston:

let winston = require('winston');

Then we need to create a logger and configure it:

let logger = winston.createLogger({
    level: 'info',
    format: winston.format.combine(
        winston.format.timestamp(),
        winston.format.printf(info => {
            return `${info.timestamp} ${info.level}: ${info.message}`;
        })
    ),
    transports: [new winston.transport.Console()]
});

What’s happening here?

We’re creating a logger that will log everything above the log level “info.” If you’re unfamiliar with the concept of log levels, be sure to check out our article on log levels.

Next, we’re telling the logger what format to use. In Winston, you can combine formats. What this means in our example is that logging a message will create an object with a “level” and a “message” property. The call to “winston.format.timestamp()” will add a “timestamp” property. And the call to “printf” will print out our object in the provided format.

Finally, we added a transport. In this example, we’ll output to the console.

Putting this all together gives us the following code:

let http = require('http');
let winston = require('winston');

let logger = winston.createLogger({
    level: 'info',
    format: winston.format.combine(
        winston.format.timestamp(),
        winston.format.printf(info => {
            return `${info.timestamp} ${info.level}: ${info.message}`;
        })
    ),
    transports: [new winston.transports.Console()]
});

http.createServer(onRequest).listen(8080);

function onRequest(request, response) {
    logger.log('info', 'A request was received');
    response.writeHead(200);
    response.end();
}

When you run this example and make a request, you’ll see this:

If we also want to log to a file, we just add a second transport:

transports: [
    new winston.transports.Console(),
    new winston.transports.File({filename: 'app.log'})
]

Let’s run the app again and make a request. Now, take a look at the newly created app.log file, and you should see this line:

2018-03-12T19:37:14.015Z info: A request was received

What to Do Now?

We’ve now used Winston to perform some basic logging. You may notice it’s not doing much more than our initial custom-written solution. But the power of a logging framework like Winston lies in how configurable it is. You could easily configure it to write everything to a log file but have errors mailed to you. You can also write your own transport if none of the built-in ones work for you. But be sure to search npm first, because many custom transports have already been written for Winston.

What you should do now is add logging to your application and configure it as you go. Think about a sensible starting point for now, but change it as you encounter new requirements and possibilities. Experiment with formats, transports, and log levels. Definitely read the documentation because there’s more to Winston than what I’ve mentioned here.

There’s also more to logging than what we’ve covered in this article. As the title suggests, this is just a starting point. In the past, we’ve written about best practices in logging and also about practices you should avoid. And once you’re used to logging (and reading logs), you’ll want to move on and look into log aggregation and management.

Start logging today!

This post was written by Peter Morlion. Peter is a passionate programmer that helps people and companies improve the quality of their code, especially in legacy codebases. He firmly believes that industry best practices are invaluable when working towards this goal, and his specialties include TDD, DI, and SOLID principles.