A Complete Guide to Pino Logging in Node.js

Pino is a structured logging framework for Node.js that claims to be up to five times faster than competing frameworks in many cases. Due to its impressive performance and wealth of features, it is included by default in the open-source Fastify web server to handle all logging output. It's also easy to integrate Pino with any Node.js web framework of your choice.

All the standard features that expected in any logging framework are present in Pino, including log levels, formatting, and multiple log routing options. It is highly flexible and can be easily be extended to fit your requirements.

In this tutorial, you will learn how to create a logging service for your application with Pino. We'll discuss many of the features you'll use regularly, and how to customize them to achieve an optimal configuration for your use case. Once you're done reading this article, you will be well equipped to implement a production-ready logging setup in your Node.js application through Pino.

Prerequisites

Before proceeding with the rest of this article, ensure that you have a recent version of Node.js and npm installed locally on your machine. This article also assumes that you are familiar with the basic concepts of logging in Node.js.

Getting started with Pino

To get the most out of this tutorial, you should create a new Node.js project to experiment with the concepts we will be discussing. Start by creating a new directory, change into it and then initialize a Node.js project:

mkdir pino-logging && cd pino-logging

npm init -y

Afterwards, install the pino package from NPM using the command below:

npm install pino

Create a new logger.js file in the root of your project directory, and populate it with the following contents:

const pino = require('pino');

module.exports = pino({});

This code requires the pino package and exports a pino() function that takes two optional arguments, options and destination, and returns a logger instance. We'll explore all the different ways you can customize the Pino logger, but for now let's go ahead and use the exported logger in a new main.js file as shown below:

const logger = require('./logger');

logger.info('Hello, world!');

Once you save the file, execute the program using the following command:

node main.js

You should see the following output:

{"level":30,"time":1643365551573,"pid":5673,"hostname":"Kreig","msg":"Hello, world!"}

The first thing you'll notice about the output above is that it's in newline delimited JSON format (NDJSON) because Pino defaults to structured logging which is the recommended way to output logs in production contexts. You'll also notice that the log level, timestamp, hostname, and process id of the Node.js application is also included in the log entry in addition to the log message.

Prettifying JSON logs in development

While JSON is great for production use and is a fairly human-readable format, it may be difficult to find what you're looking for in development amongst all the property names and symbols (curly braces, commas, and quotes). To solve this problem, the Pino team developed the pino-pretty module which can be used to convert NDJSON entries to a more human readable output.

Go ahead and install the pino-pretty package through npm:

npm install pino-pretty --save-dev

The use of pino-pretty is not recommended in production, hence it's specification as a development dependency. Once the installation completes, you'll be able to access the pino-pretty command through npx:

npx pino-pretty --version

7.5.1

You can now pipe the output of your application to pino-pretty as shown below:

node main.js | npx pino-pretty

You should observe the output below. Notice how its shorter and more readable than the JSON output from the previous section despite containing the same information.

[1643663870617] INFO (19106 on Kreig): Hello, world!

Log levels in Pino

Each Pino logger instance comes with logging methods that represent a log level. The default levels are (ordered by ascending severity) trace, debug, info, warn, error, and fatal, and each of these have a corresponding method on the logger:

const logger = require('./logger');

logger.fatal('fatal');
logger.error('error');
logger.warn('warn');
logger.info('info');
logger.debug('debug');
logger.trace('trace');

When you execute the code above, you will get the following output:

{"level":60,"time":1643664517737,"pid":20047,"hostname":"Kreig","msg":"fatal"}
{"level":50,"time":1643664517738,"pid":20047,"hostname":"Kreig","msg":"error"}
{"level":40,"time":1643664517738,"pid":20047,"hostname":"Kreig","msg":"warn"}
{"level":30,"time":1643664517738,"pid":20047,"hostname":"Kreig","msg":"info"}

Notice how a number number represents each level, and each number is being incremented in 10s according to their severity. You'll also notice that no entry is emitted for the debug() and trace() methods. This is because the default level on a Pino logger is set to info which causes only info-level messages or those with a greater severity to be emitted, while lower severity levels are suppressed.

Setting the minimum log level is typically done when creating the logger and controlled through an environmental variable so that it's possible to change it in different environments without making code modifications.

const logger = require('./logger');

module.exports = pinoLogger({
  level: process.env.PINO_LOG_LEVEL || 'info',
});

If the PINO_LOG_LEVEL variable is set in the environment, that value will be used. Otherwise, it falls back to the info level.

PINO_LOG_LEVEL=error node main.js

{"level":60,"time":1643665426792,"pid":22663,"hostname":"Kreig","msg":"fatal"}
{"level":50,"time":1643665426793,"pid":22663,"hostname":"Kreig","msg":"error"}

After creation, you can also change the minimum level on a logger. All you need to do is set logger.level to the name of the new level:

const logger = require('./logger');

logger.level = 'debug'; // only trace messages will be suppressed now

. . .

Each logging method has the following signature ([mergingObject], [message], [...interpolationValues]). As you can see, all the parameters are optional. Here's a demonstration of the different ways you can log using Pino:

logger.info('Upload successful!');

logger.info(
  { name: 'bucky.mp5', mime_type: 'video/mp4' },
  'Upload successful!'
);

logger.info(
  "Upload of file '%s' with mime type '%s' is successful!",
  'bucky.mp4',
  'video/mp4'
);

logger.info(
  { name: 'bucky.mp4', mime_type: 'video/mp4' },
  '%s: file upload succeeded.',
  'bucky.mp4'
);

The above snippets yield the following output:

{"level":30,"time":1643666334166,"pid":24322,"hostname":"Kreig","msg":"Upload successful!"}
{"level":30,"time":1643666456805,"pid":24635,"hostname":"Kreig","name":"bucky.mp4","mime_type":"video/mp4","msg":"Upload successful!"}
{"level":30,"time":1643666573494,"pid":25230,"hostname":"Kreig","msg":"Upload of file 'bucky.mp4' with mime type 'video/mp4' is successful!"}
{"level":30,"time":1643666732988,"pid":25766,"hostname":"Kreig","name":"bucky.mp4","mime_type":"video/mp4","msg":"bucky.mp4: file upload succeeded."}

The first argument can be a message string or an object. If it's an object, its enumerable properties will be merged into the JSON output, but if its a string, it will be placed in the msg property. If a message string contains printf-style placeholders (%s, %d, %o, etc), all arguments after the string will be serialized and interpolated according to the placeholders.

Customizing log levels in Pino

Pino does not restrict you to the default levels that it provides. Instead, you can easily change them as you see fit through a logger's customLevels property. For example, you can use the Syslog levels by creating an object that defines the integer priority of each level, then set the customLevels property on the logger to that object:

const pinoLogger = require('pino');

const levels = {
  emerg: 80,
  alert: 70,
  crit: 60,
  error: 50,
  warn: 40,
  notice: 30,
  info: 20,
  debug: 10,
};

module.exports = pinoLogger({
  level: process.env.PINO_LOG_LEVEL || 'info',
  customLevels: levels,
  useOnlyCustomLevels: true,
});

The useOnlyCustomLevels option ensures that Pino's original log levels are omitted in favour of the defined custom levels. At this point, you can log using your custom levels through their respective methods:

logger.emerg('Emergency');
logger.alert('Alert');
logger.crit('Critical');

which outputs:

{"level":80,"time":1643669711817,"pid":29472,"hostname":"Kreig","msg":"Emergency"}
{"level":70,"time":1643669711818,"pid":29472,"hostname":"Kreig","msg":"Alert"}
{"level":60,"time":1643669711818,"pid":29472,"hostname":"Kreig","msg":"Critical"}

The level in the JSON output above contains the level value instead of the string name like most other logging frameworks. To change this to their string equivalents, use the formatters configuration below to override the default:

. . .

module.exports = pinoLogger({
  level: process.env.PINO_LOG_LEVEL || 'info',
  customLevels: levels,
  useOnlyCustomLevels: true,
  formatters: {
    level: (label) => {
      return { level: label };
    },
  },
});

This change causes the level property on the output to become strings:

{"level":"emerg","time":1643696861193,"pid":30561,"hostname":"Kreig","msg":"Emergency"}
{"level":"alert","time":1643696861193,"pid":30561,"hostname":"Kreig","msg":"Alert"}
{"level":"crit","time":1643696861193,"pid":30561,"hostname":"Kreig","msg":"Critical"}

Storing log entries in a file

So far, we've seen that Pino outputs all its log entries to the Node.js console by default. Let's discuss how to change the destination to a log file for longer-term storage. You'll need to use the destination() method in the second argument to the pinoLogger() method as shown below:

module.exports = pinoLogger(
  {
    level: process.env.PINO_LOG_LEVEL || 'info',
    customLevels: levels,
    useOnlyCustomLevels: true,
    formatters: {
      level: (label) => {
        return { level: label };
      },
    },
  },
  pinoLogger.destination(`${__dirname}/combined.log`)
);

Henceforth, all messages will be placed in a combined.log file in the project root instead of the Node.js console. Unlike Winston, Pino does not provide a built-in mechanism to rotate your log files. You'll need to rely on external tools such as Logrotate for this purpose.

Logging to multiple destinations in Pino

Logging to multiple storage locations at once is possible through the pinoLogger.multistream() method. You can use it to write log messages to the Node.js console and a log file using the snippet below:

. . .

const streams = [
  { stream: process.stdout },
  { stream: pinoLogger.destination(`${__dirname}/combined.log`) },
];

module.exports = pinoLogger(
  {
    level: process.env.PINO_LOG_LEVEL || 'info',
    customLevels: levels,
    useOnlyCustomLevels: true,
    formatters: {
      level: (label) => {
        return { level: label };
      },
    },
  },

  pinoLogger.multistream(streams)
);

Create custom destinations based on log level

When you use multiple streams as in the previous section, each log entry is duplicated across all the streams. However, you can redirect each entry to a particular location with a few tweaks. For example, you can cause each level to be emitted to a separate file so that emerg-level messages go to app-emerg.log, alert-level messages go to app-alert.log, and so on. Here's how to achieve this with Pino:

. . .

const streams = Object.keys(levels).map((level) => {
  return {
    level: level,
    stream: pinoLogger.destination(`${__dirname}/app-${level}.log`),
  };
});

module.exports = pinoLogger(
  {
    level: process.env.PINO_LOG_LEVEL || 'info',
    customLevels: levels,
    useOnlyCustomLevels: true,
    formatters: {
      level: (label) => {
        return { level: label };
      },
    },
  },

  pinoLogger.multistream(streams, {
    levels,
    dedupe: true,
  })
);

In the snippet above, we are iterating over the property names on our custom levels object and assigning an array of objects to the streams variable. Each object in the array contains a level property that is set to the level being iterated over, and a stream property is that is set to the return value of the destination() method.

In the second argument to multistream(), we're passing an object containing our custom log levels and a dedupe property which is set to true which ensures that each log entry is not duplicated to all the streams. Henceforth, each log message will be redirected to the appropriate location specified in the streams array.

Custom transports in Pino

Aside from logging to a file or the console, you may also log to custom locations like a database, log management tool, or other services. Here are some custom transports that you might want to check out:

• pino-mysql: stores logs in MySQL and MariaDB.
• pino-redis: sends logs to Redis.
• pino-pg: stores logs in PostgreSQL.
• pino-websocket: transport logs to a WebSocket server.

Ensure to read the Pino transport docs to learn more about transports and how to create your own if none of the available ones serve your need.

Adding context to your logs

The primary way to add contextual data to your log entries is through the mergingObject parameter on a logger method:

. . .

logger.error(
  {
    transaction_id: 'efui2e9',
    user_id: 'eu9j2qksa',
  },
  'Transaction failed: cc number is invalid'
);

The above snippet produces the following line in the app-error.log file:

{"level":"error","time":1643705730968,"pid":11254,"hostname":"Kreig","transaction_id":"efui2e9","user_id":"eu9j2qksa","msg":"Transaction failed: cc number is invalid"}

You can also create child loggers for the purpose of setting some default metadata on all log entries within a request, function, or module:

const logger = require('./logger');

const childLogger = logger.child({
  requestId: '83ed4675f1c53513c61a3b3b4e25b4c0',
});

childLogger.info(
  {
    file: 'boat.png',
    type: 'image/png',
  },
  'file upload successful'
);

This yields the following line in the app-info.log file:

{"level":"info","time":1643705627432,"pid":10851,"hostname":"Kreig","requestId":"83ed4675f1c53513c61a3b3b4e25b4c0","file":"boat.png","type":"image/png","msg":"file upload successful"}

Logging errors with Pino

You can log errors in Pino by passing the error as the first argument to the logging method, or as a property on mergingObject:

. . .

logger.error(new Error('ValidationError: email address in invalid'));

This will produce the output below in the app-error.log file. Notice how it includes an err property which contains the error message and the complete stack trace.

{"level":"error","time":1643706943924,"pid":13185,"hostname":"Kreig","err":{"type":"Error","message":"ValidationError: email address in invalid","stack":"Error: ValidationError: email address in invalid\n    at Object.<anonymous> (/home/ayo/dev/betterstack/demo/snippets/main.js:3:14)\n    at Module._compile (node:internal/modules/cjs/loader:1097:14)\n    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1149:10)\n    at Module.load (node:internal/modules/cjs/loader:975:32)\n    at Function.Module._load (node:internal/modules/cjs/loader:822:12)\n    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)\n    at node:internal/main/run_main_module:17:47"},"msg":"ValidationError: email address in invalid"}

Handling uncaught exceptions and unhandled promise rejections

Pino used to provide an exit logging mechanism that uses pino.final() to reliably and synchronously flush every log line before the process exits when an uncaughtException or unhandledRejection event is detected. However, this method is deprecated in Node.js v14+ as Pino now automatically registers handlers for the exit and beforeExit events so that the stream is flushed before the process exits.

This means you can listen for the relevant events and do any logging without using a special final() method:

process.on('uncaughtException', (err) => {
  logger.error(err);
  process.exit(1);
});

process.on('unhandledRejection', (err) => {
  logger.error(err);
  process.exit(1);
});

Asynchronous logging with Pino

By default, Pino logs entries directly to each output stream through a sequence of blocking operations. It also provides an asynchronous mode on a destination that buffers log entries and writes them in chunks to enable even faster performance. To enable this mode, change the string argument to pino.destination() to an object, and set the sync property to false as shown below:

. . .

const streams = Object.keys(levels).map((level) => {
  return {
    level: level,
    stream: pinoLogger.destination({
      dest: `${__dirname}/app-${level}.log`,
      sync: false,
    }),
  };
});

. . .

Note that when async mode is enabled, the most recently buffered log entries to be lost if the Node.js application exits unexpectedly before they are written to the output stream.

Logging HTTP requests with Pino

Pino integrates with a variety of Node.js web frameworks such as Express, Fastify, Koa, and others. For example, you can use the pino-http package with Express:

const express = require('express');
const logger = require('./logger');
const axios = require('axios');
const pinoHTTP = require('pino-http');

const app = express();

app.use(pinoHTTP());

app.get('/crypto', async (req, res) => {
  try {
    const response = await axios.get(
      'https://api2.binance.com/api/v3/ticker/24hr'
    );

    const tickerPrice = response.data;

    res.json(tickerPrice);
  } catch (err) {
    logger.error(err);
    res.status(500).send('Internal server error');
  }
});

app.listen('4000', () => {
  console.log('Server is running on port 4000');
});

Install the required dependencies using the command below:

npm install express axios pino-http

Afterwards, start the server on port 4000 and send requests to the /crypto route through curl or Postman. You'll observe the following output per request from the pinoHTTP middleware:

{"level":30,"time":1643713279157,"pid":20111,"hostname":"Kreig","req":{"id":1,"method":"GET","url":"/crypto","query":{},"params":{},"headers":{"host":"localhost:4000","user-agent":"curl/7.68.0","accept":"*/*"},"remoteAddress":"::ffff:127.0.0.1","remotePort":34668},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"985325","etag":"W/\"f08ed-YDuVyS90og/43t3+shbyepfI2QM\""}},"responseTime":2629,"msg":"request completed"}

The pinoHTTP() middleware function uses its logger instance by default, and that's why the request logs are sent to the Node.js console. You can reuse our custom logger instance by setting the logger property as shown below:

. . .

app.use(
  pinoHTTP({
    logger,
  })
);

. . .

Afterwards, the log entries from the pinoHTTP() middleware will conform to the options set in the logger.js file, which means they will be placed in the app-info.log file. You can further customize the output of pino-http by taking a look at its API documentation.

Conclusion

In this article, we've covered everything you need to know about Node.js logging with Pino. If you'd like to learn more about what Pino can do for you, consult their official documentation pages.

Thanks for reading, and happy coding!

Article by

Ayooluwa Isaiah

Ayo is a technical content manager at Better Stack. His passion is simplifying and communicating complex technical ideas effectively. His work was featured on several esteemed publications including LWN.net, Digital Ocean, and CSS-Tricks. When he's not writing or coding, he loves to travel, bike, and play tennis.

Got an article suggestion? Let us know

Next article

A Complete Guide to Winston Logging in Node.js

Learn how to start logging with Winston in Node.js and go from basics to best practices in no time.

→

This work is licensed under a Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License.