Logging in Node.js! Why, How and What?

•4 min read
nodejsfastify
Back

Ever heard of "Production is down!". The moment you heard that, the only thought that would've come to your mind is - My day is now ruined We need to fix it and quickly.

In this post, I'll explain What is logging? How to setup logging? and What data to log? through fastify (opens in a new tab), express (opens in a new tab) as the server framework and pino (opens in a new tab) as the logging framework for Node.js.

Logging

Logging is a technique that allows anyone to see and observe what's going on inside a service or application whether it's a server, database or a process running in the background.

It also enables reporting of crashes or failures like server outage, so that we can quickly fix those issue by looking into those logs and finding the root cause.

How to log?

With fastify, logging comes out-of-the-box (opens in a new tab) and it uses pino under the hood. Here's how you can use it:

npm install fastify
const fastify = require("fastify")({
    // this will enable the request logging
    logger: true,
});
 
fastify.get("/", async () => "Ok");
 
fastify.get("/log", async (req, reply) => {
    // custom log
    req.log.info("this is a custom log message");
 
    return "Ok";
});
 
fastify.listen({ port: 8080 });

Now run the server from the terminal

node server.js

And, visit http://localhost:8080 (opens in a new tab) in the browser and see the logs printing, or http://localhost:8080/log (opens in a new tab) to see the custom log message.

{"level":30,"time":1654844524714,"pid":17118,"hostname":"DESKTOP","msg":"Server listening at http://127.0.0.1:8080"}
{"level":30,"time":1654844542572,"pid":17118,"hostname":"DESKTOP","reqId":"req-1","req":{"method":"GET","url":"/","hostname":"localhost:8080","remoteAddress":"127.0.0.1","remotePort":45384},"msg":"incoming request"}
{"level":30,"time":1654844542577,"pid":17118,"hostname":"DESKTOP","reqId":"req-1","res":{"statusCode":200},"responseTime":4.297284999862313,"msg":"request completed"}
{"level":30,"time":1654844632191,"pid":17118,"hostname":"DESKTOP","reqId":"req-2","req":{"method":"GET","url":"/log","hostname":"localhost:8080","remoteAddress":"127.0.0.1","remotePort":45414},"msg":"incoming request"}
{"level":30,"time":1654844632192,"pid":17118,"hostname":"DESKTOP","reqId":"req-2","msg":"this is a custom log message"}
{"level":30,"time":1654844632192,"pid":17118,"hostname":"DESKTOP","reqId":"req-2","res":{"statusCode":200},"responseTime":0.5779439993202686,"msg":"request completed"}

However, If you are using express (opens in a new tab) you need to install express-pino-logger (opens in a new tab)

npm install express express-pino-logger
const app = require("express")();
const pino = require("express-pino-logger")();
 
// Enables logging by registering it as a middleware
app.use(pino);
 
app.get("/", (req, res) => {
    res.send("Ok");
});
 
app.get("/log", (req, res) => {
    // custom log
    req.log.info("this is a custom log message");
 
    req.send("Ok");
});
 
app.listen(3000);

By default fastify logs request and response separately unlike the express which logs both at the same time

What to log?

For a server environment, having observability on the request <-> response life cycle is very crucial. Everything depends on this life cycle working flawlessly, if something happens in-between then we need to make sure that we can get an idea when things went wrong. Things that we could/should log are:

process.on("unhandledRejection", (err) => {
    // Here we can just use `console` instead of `pino`
    console.error(err);
 
    process.exit(1);
});

What not to log?

But, don't go and start logging everything you find. There are certain precautions we have to take to do logging in an ethical manner and protect your user's data.

const fastify = require("fastify")({
    // We can also use the pino's configuration
    // https://github.com/pinojs/pino/blob/master/docs/api.md#pinooptions-stream
    logger: {
        redact: [
            "req.headers.authorization",
            "req.headers.token",
            "req.headers.cookie",
        ],
    },
});
 
fastify.get("/", async () => "Ok");
 
fastify.listen({ port: 8080 });

With express

const app = require("express")();
const pino = require("express-pino-logger")({
    redact: [
        "req.headers.authorization",
        "req.headers.token",
        "req.headers.cookie",
    ],
});
 
app.use(pino);

Now, those header will be removed before everything gets logged.

Best Practices

npm install -D pino-pretty
{
    // ...
    "scripts": {
        "start": "node server.js",
        "dev": "node server.js | pino-pretty"
    }
}