By Pavel Sheida
Last Validated on May 5 2021 · Originally Published on May 5, 2021 · Viewed 1.7k times

Introduction

Pino is a very low overhead Node.js JSON logger. It provides a simple, effective, and extremely fast way of logging. According to the benchmarks, it's the fastest logger for Node.js.

Furthermore, Pino has its extensible log level system, customizable logging targets, and opportunity to enable asynchronous logging for even faster logging. It's also worth mentioning that Pino has an excellent modules' ecosystem, maintained by the Pino team and its community.

In this tutorial we will explain how to install, setup and use Pino logger for your Express server.


Prerequisites

You will need:

  • Ubuntu 20.04 distribution including the non-root user with sudo access.
  • Node.js and NPM installed.
  • cURL installed.

Step 1 — Creating And Configuring NPM Package

NPM package is a file or directory that is described by a package.json file. We are going to use one to control the application's dependencies and Node.js behavior.

Let's create an NPM package via npm command:

npm init

In the process, you will be asked to enter package data, If you'd like to skip it, just click ENTER several times.

In the tutorial we will use ES6 modules. You can read more about them on the Mozilla pages. To force the package to use ES6 modules you have to edit the package.json file. Let's do it with nano:

nano package.json

In the file, you need to add the following line: "type": "module",. To exit nano press CTRL+X, then, to save the changes, press Y, then ENTER.

After the insertion, the package.json file should look like:

{
  "name": "your_package_name",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "type": "module",
  "scripts": {
    "test": "echo \\"Error: no test specified\\" && exit 1"
  },
  "author": "",
  "license": "ISC",
}

Step 2 — Installing Pino And Express

The first thing you have to do is to install Pino and Express. The installation of the libraries can be done in one command via npm:

npm install pino express

Furthermore, for convenient work with HTTP requests, you should install express-pino-logger — the fastest HTTP logger middleware for Express. Let's do it with npm:

npm install express-pino-logger

Step 3 — Creating An Express Server

After the installation, you are ready to create an Express server. The server will have 5 routes and will run on the 3000 port.

The following code needs to be written to the index.js file.

index.js
// import the express library
import express from "express";

// create an express application instance
const app = express();
// create a variable to store the port
const PORT = 3000;

// handle GET request coming on "/"
app.get("/", (req, res) => {
  // send a response message
  res.send("Your request has been handled!");
});

// handle GET request coming on "/development"
app.get("/development", (req, res) => {
  // send a response message
  res.send("You've accessed a debug link!");
});

// handle GET request coming on "/unsafe"
app.get("/unsafe", (req, res) => {
  // send a response message
  res.send("You've accessed an unsafe link!");
});

// handle GET request coming on "/dangerous"
app.get("/dangerous", (req, res) => {
  // send a response message
  res.send("You've accessed a dangerous link!");
});

// handle GET request coming on "/fatal"
app.get("/fatal", (req, res) => {
  // send a response message
  res.send("You've accessed a fatal link!");
});

// start the server on the specified port
app.listen(PORT);

Step 4 — Creating Logger

Now, let's create a Pino logger.

In Pino, every log message has an associated log level. The log level helps you understand the severity and urgency of the message. Each log level has an assigned integer representing the severity of the message.

Due to the rich configuration abilities of Pino, we can create an own log levels system for the application. You can get advanced information about custom log levels in the documentation.

Based on the functionality of our server, we've decided to create the following system:

  • Fatalfatal:  Used for reporting about errors that are forcing shutdown of the application.
  • Errorerror: Used for logging serious problems occurred during execution of the program.
  • Warning  — warn: Used for reporting non-critical unusual behavior.
  • Infoinfo: Used for informative messages highlighting the progress of the application for sysadmins and end users.
  • Debugdebug: Used for debugging messages with extended information about application processing.
  • HTTPhttp: Used for logging HTTP requests.

We will implement the logger with the log levels system in the logger.js file:

logger.js
// import a Pino library
import pino from "pino"

// log levels system
const levels = {
  http: 10,
  debug: 20,
  info: 30,
  warn: 40,
  error: 50,
  fatal: 60
};

// create a Pino logger
const logger = pino({
  // set the own levels
  customLevels: levels,
  // use only the custom levels
  useOnlyCustomLevels: true,
  // the minimum log level to be display
  level: "http"
});

// export the logger
export default logger;

Step 5 — Logging

Now, you can start using the created logger.

Let's append our code with logging and apply the express-pino-logger. The index.js file will look as follows:

// import the express library
import express from "express";
// import the HTTP logging middleware
import expressPinoLogger from "express-pino-logger";

// import the logger
import logger from "./logger.js";

// create an express application instance
const app = express();
// create an instance of the middleware
const eplMiddleware = expressPinoLogger({
  // specify the logger
  logger: logger,
  // level to log
  useLevel: "http"
});

// apply the middleware
app.use(eplMiddleware);

// create a variable to store the port
const PORT = 3000;

// handle GET request coming on "/"
app.get("/", (req, res) => {
  // send a response message
  logger.info("A root link has been accessed!");
  res.send("Your reuest has been handled!");
});

// handle GET request coming on "/development"
app.get("/development", (req, res) => {
  logger.debug("A debug link has been accessed!");
  // send a response message
  res.send("You've accessed a debug link!");
});

// handle GET request coming on "/unsafe"
app.get("/unsafe", (req, res) => {
  logger.warn("An unsafe link has been accessed!");
  // send a response message
  res.send("You've accessed an unsafe link!");
});

// handle GET request coming on "/dangerous"
app.get("/dangerous", (req, res) => {
  logger.error("A dangerous link has been accessed!");
  // send a response message
  res.send("You've accessed a dangerous link!");
});

// handle GET request coming on "/fatal"
app.get("/fatal", (req, res) => {
  logger.fatal("A fatal link has been accessed!");
  // send a response message
  res.send("You've accessed a fatal link!");
});

// start the server on the specified port
app.listen(PORT);

At the moment, all logs will go to the console.


Step 6 — Writing Logs

By default, Pino writes structured in JSON format logs to the console. This grants you plenty of methods for how to write them to files. The most common way is pino-tee — a lightweight tool for writing logs into multiple files. You can read more about it in the documentation.

However, in some cases, you may prefer another JSON processor, such as JQ or comment-json.

Let's install pino-tee via npm:

npm install pino-tee

According to the application logic, we need, at least, 4 logging targets:

  • error.log: For storing logs with error and fatal levels.
  • combined.log: For storing combined server logs of different levels.
  • http.log: For storing only HTTP logs.
  • Console: For displaying all logs.
tee.js
// import the file system library
import fs from "fs";

// import the tee library
import tee from "pino-tee";

const stream = tee(process.stdin);

// create a logging target for HTTP logs
stream.tee(
  fs.createWriteStream("./http.log", {flags: "a"}),
  line => line.level === 10
);

// create a logging target for logs of different levels
stream.tee(
  fs.createWriteStream("./combined.log", {flags: "a"}),
  "info"
)

// create a logging target for errors and fatals
stream.tee(
  fs.createWriteStream("./error.log", {flags: "a"}),
  "error"
)

// redirect the stream to stdout
stream.pipe(process.stdout)

Due to the fact that the Pino logger sends all the output to the console, we can pipe the output to a pino-tee log processor with the following command:

node index.js | node tee.js

Using node index.js | node tee.js, we pipe the output from node index.js — the logs to the node tee.js input. You can read more about piping in Bash on linuxhint.


Step 7 — Testing

Now, it's time to test our code. We will imitate users' requests via cURL — a command-line tool that developers use to transfer data to and from a server.

First things first, start the server via node:

node index.js

The command will occupy your terminal. To continue testing, you have to open a new terminal window.


Step 7.1 — Testing The HTTP Logging

The application will log all requests, including ones with an error. Therefore, we will try to access non-existing paths  http://localhost:3000/foo and http://localhost:3000/boo via curl:

curl "<http://localhost:3000/foo>"
curl "<http://localhost:3000/boo>"

Now, you can display the contents of the http.log file.

The simplest way to do it is cat. The command prints the contents of the specified file to the console.

cat http.log

The output should be similar to:

Output
{"level":10,"time":1617312815220,"pid":31525,"hostname":"username","req":{"id":1,"method":"GET","url":"/foo","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51888},"res":{"statusCode":404,"headers":{"x-powered-by":"Express","content-security-policy":"default-src 'none'","x-content-type-options":"nosniff","content-type":"text/html; charset=utf-8","content-length":142}},"responseTime":20,"msg":"request completed"}
{"level":10,"time":1617312819350,"pid":31525,"hostname":"username","req":{"id":2,"method":"GET","url":"/boo","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51892},"res":{"statusCode":404,"headers":{"x-powered-by":"Express","content-security-policy":"default-src 'none'","x-content-type-options":"nosniff","content-type":"text/html; charset=utf-8","content-length":142}},"responseTime":1,"msg":"request completed"}

Step 7.2 — Testing The Server Logging

There are 5 handled paths in the application. We will try to access each of them via curl:

curl "<http://localhost:3000/>"
curl "<http://localhost:3000/development>"
curl "<http://localhost:3000/unsafe>"
curl "<http://localhost:3000/dangerous>"
curl "<http://localhost:3000/fatal>"

The output should look like:

Output
Your request has been handled!
You've accessed a debug link!
You've accessed an unsafe link!
You've accessed a dangerous link!
You've accessed a fatal link!

To ensure, that everything works correctly, let's check the log files via cat.

First, look at the contents of the error.log file:

cat error.log

The output will look like:

Output
{"level":50,"time":1617312903694,"pid":31525,"hostname":"username","msg":"A dangerous link has been accessed!"}
{"level":60,"time":1617312908370,"pid":31525,"hostname":"username","msg":"A fatal link has been accessed!"}

Second, check the combined.log file:

cat combined.log

The output will look like:

Output
{"level":30,"time":1617312885970,"pid":31525,"hostname":"username","msg":"A root link has been accessed!"}
{"level":40,"time":1617312898670,"pid":31525,"hostname":"username","msg":"An unsafe link has been accessed!"}
{"level":50,"time":1617312903694,"pid":31525,"hostname":"username","msg":"A dangerous link has been accessed!"}
{"level":60,"time":1617312908370,"pid":31525,"hostname":"username","msg":"A fatal link has been accessed!"}

If you open the terminal where the server is running, you will see all the logs, including the debug ones. It should be something like this:

Output
{"level":10,"time":1617312815220,"pid":31525,"hostname":"username","req":{"id":1,"method":"GET","url":"/foo","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51888},"res":{"statusCode":404,"headers":{"x-powered-by":"Express","content-security-policy":"default-src 'none'","x-content-type-options":"nosniff","content-type":"text/html; charset=utf-8","content-length":142}},"responseTime":20,"msg":"request completed"}
{"level":10,"time":1617312819350,"pid":31525,"hostname":"username","req":{"id":2,"method":"GET","url":"/boo","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51892},"res":{"statusCode":404,"headers":{"x-powered-by":"Express","content-security-policy":"default-src 'none'","x-content-type-options":"nosniff","content-type":"text/html; charset=utf-8","content-length":142}},"responseTime":1,"msg":"request completed"}
{"level":30,"time":1617312885970,"pid":31525,"hostname":"username","msg":"A root link has been accessed!"}
{"level":10,"time":1617312885981,"pid":31525,"hostname":"username","req":{"id":3,"method":"GET","url":"/","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51902},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"29","etag":"W/\\"1d-HF6yQkM3hf620mG28S8gmOyIGDU\\""}},"responseTime":12,"msg":"request completed"}
{"level":20,"time":1617312892842,"pid":31525,"hostname":"username","msg":"A debug link has been accessed!"}
{"level":10,"time":1617312892843,"pid":31525,"hostname":"username","req":{"id":4,"method":"GET","url":"/development","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51904},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"29","etag":"W/\\"1d-Am+Et5WypTvvBn9MXreF20MVKzo\\""}},"responseTime":1,"msg":"request completed"}
{"level":40,"time":1617312898670,"pid":31525,"hostname":"username","msg":"An unsafe link has been accessed!"}
{"level":10,"time":1617312898672,"pid":31525,"hostname":"username","req":{"id":5,"method":"GET","url":"/unsafe","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51906},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"31","etag":"W/\\"1f-AHFYse973hBEs5tdUEY5gDXNSq0\\""}},"responseTime":2,"msg":"request completed"}
{"level":50,"time":1617312903694,"pid":31525,"hostname":"username","msg":"A dangerous link has been accessed!"}
{"level":10,"time":1617312903695,"pid":31525,"hostname":"username","req":{"id":6,"method":"GET","url":"/dangerous","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51908},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"33","etag":"W/\\"21-Siw2wAcCNbEYwpmTcSmyhUAdWZQ\\""}},"responseTime":2,"msg":"request completed"}
{"level":60,"time":1617312908370,"pid":31525,"hostname":"username","msg":"A fatal link has been accessed!"}
{"level":10,"time":1617312908371,"pid":31525,"hostname":"username","req":{"id":7,"method":"GET","url":"/fatal","headers":{"host":"localhost:3000","user-agent":"curl/7.71.1","accept":"*/*"},"remoteAddress":"::1","remotePort":51910},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"29","etag":"W/\\"1d-PuL0OsPgm8Wi4fZ/GWqtfshPcio\\""}},"responseTime":1,"msg":"request completed"}

Now, you should stop the server by pressing CTRL+C in the server terminal.


Conclusion

Servers, like any application, require timely bug fixes and support. This becomes a serious problem without a good logging system. Besides, by logging HTTP requests, you can analyze common user problems and provide timely assistance.

In this tutorial, you've configured an Express server with a complex logging system using Pino — a fast and simple Node.js logging library, and express-pino-logger — the fastest HTTP request logger middleware for Node.js.

The server logging won't be a daunting task for you anymore!