Node.js Microservice Architecture JSON Logging with Pino in Express.js

Logging remains one of the most effective techniques to gain insight into what is happening in a program. Furthermore, structured logging improves tracing and filtering. In this post, we add a JSON logger into the opinionated Node.js microservice architecture.

Pino is one of the better known JSON loggers in the Node.js ecosystem. We install it as a dependency.

npm install --save pino

We create a global logger object in a dedicated file src/logger.ts.

import pino from "pino";

export const logger = pino({
  level: "info",
});

This logger can be used throughout the application.

import { logger } from "./logger";

logger.info({ some: "data" }, "This is a test");

It outputs a single line with a JSON containing meta information on log level, time, process and host. Additionally, it embeds the custom JSON data and the log message.

{
  "level": 30,
  "time": 1646582909278,
  "pid": 12345,
  "hostname": "fboeller",
  "some": "data",
  "msg": "This is a test"
}

Logging incoming requests 🔗

There are log lines that we don't want to repeat throughout the application. For an application serving an HTTP API, it is useful to always have a log line for each incoming request. This way, we avoid that for some endpoints this log line is forgotten or that the logs are structurally different.

To achieve that, we define an Express.js middleware as a pre-request handler.

npm install --save express-pino-logger
npm install --save-dev @types/express-pino-logger

We create a file src/pre-request-handlers/log-request.ts that defines a middleware logRequest.

import expressPino from "express-pino-logger";

export const logRequest = expressPino({
  level: "info",
  enabled,
});

In the application src/app.ts, we register this middleware.

// ...

const app = express();

app.use(logRequest);

// ...

export default app;

Now, with a server being started with npm start and a request being sent with http http://localhost:3000/todos, we see a log line with information about the request and the response.

{
  "level": 30,
  "time": 1646583745857,
  "pid": 14865,
  "hostname": "fboeller",
  "req": {
    "id": 1,
    "method": "GET",
    "url": "/todos",
    "query": {},
    "params": {},
    "headers": {
      "host": "localhost:3000",
      "user-agent": "HTTPie/0.9.8",
      "accept-encoding": "gzip, deflate",
      "accept": "*/*",
      "connection": "keep-alive"
    },
    "remoteAddress": "::ffff:127.0.0.1",
    "remotePort": 48864
  },
  "res": {
    "statusCode": 200,
    "headers": {
      "x-powered-by": "Express",
      "content-type": "application/json; charset=utf-8",
      "content-length": "2",
      "etag": "W/\"2-l9Fw4VUd7kr8CvBat4zaMCqXZ2w\""
    }
  },
  "responseTime": 25,
  "msg": "request completed"
}

Note: By default, all header and query parameters are logged. Therefore, be careful, when access tokens are sent. In a later post on authentication, we will change the default serialization to exclude access tokens from logging.

Logging in the context of requests 🔗

On some occasions, you might want to log additional information in the context of an incoming request. In a controller, you might be tempted to call logger.info(...) to achieve that. However, once you want to trace a specific request in production, such a log line can not be associated with the request.

The express-pino-logger attaches a dedicated request logger request.log to the request object.

import { NextFunction, Request, Response } from "express";

export async function myController(
  request: Request,
  response: Response,
  next: NextFunction
): Promise<void> {
  request.log.info({ some: "data" }, "My custom log line");
}

With the usage of this logger, the log line includes an identical request id. This way, you can search for all log lines from a specific incoming request.

{
  "level": 30,
  "time": 1646588777952,
  "pid": 19777,
  "hostname": "fboeller",
  "req": {
    "id": 1,
    "method": "GET",
    "url": "/todos"
  },
  "some": "data",
  "msg": "My custom log line"
}

Request logging in tests 🔗

Once you use the logger request.log, you run into errors in the test cases.

expected 200 "OK", got 500 "Internal Server Error"

Since the logRequest middleware is not registered in the test cases, there is no object log defined on request and hence a call to request.log.info(...) fails. However, registering the logRequest middleware causes log lines in the test cases. This reduces the readability of the test results and is therefore valuable to avoid.

The middleware expressPino exposes an option enabled to disable the logger. We adjust the logRequest function in the file src/pre-request-handlers/log-request.ts to use that option.

import expressPino from "express-pino-logger";

export const logRequest = (enabled: boolean) =>
  expressPino({
    level: "info",
    enabled,
  });

In the application src/app.ts, the value true is passed such that the logger is enabled.

// ...

const app = express();

app.use(logRequest(true));

// ...

export default app;

In the server function of the file src/test.functions.ts, the logger is turned off.

import express, { Express } from "express";
// ...

export function server(configure: (express: Express) => void): Express {
  const app = express();
  app.use(logRequest(false));
  // ...
  return app;
}

This way, request.log is now defined in test cases. The tests don't fail anymore and still no log lines are logged in tests.

Request-independent logging in tests 🔗

Also, calls to logger.info and alike should not lead to log lines in tests. Mocking the module logger.ts allows both to suppress the log lines and also spy on the calls to the logger.

jest.mock("./logger", () => ({
  logger: {
    info: jest.fn(),
    error: jest.fn(),
  },
}));

Now, expectations towards the logger can be formulated.

expect(request("./logger").error).toHaveBeenCalledTimes(1);

Prettify log lines 🔗

Looking at a single-lined colorless JSON log in your local shell might not be the desired user experience you wish to have in your daily work.

Server listening on port 3000!
{"level":30,"time":1646585672385,"pid":16618,"hostname":"fboeller","req":{"id":1,"method":"GET","url":"/todos","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"HTTPie/0.9.8","accept-encoding":"gzip, deflate","accept":"*/*","connection":"keep-alive"},"remoteAddress":"::ffff:127.0.0.1","remotePort":49494},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"2","etag":"W/\"2-l9Fw4VUO7kr8CvBlt4zaMCqXZ0w\""}},"responseTime":20,"msg":"request completed"}

Fortunately, there is a tool pino-pretty for that.

npm install --save-dev pino-pretty

This shell tool takes input from stdin, makes it prettier and outputs it to stdout. In the scripts of the package.json, we pipe the output of the server watch to pino-pretty with some reasonable default parameters.

{
  "scripts": {
    "_nodemon": "nodemon --legacy-watch --watch ./dist --inspect=0.0.0.0:9229 dist/main.js -- server | npx pino-pretty -i time,hostname,module,__in,name,pid"
  }
}

In the development server npm start, the output of the logs is now more readable.

Server listening on port 3000!

INFO: request completed
    req: {
      "id": 1,
      "method": "GET",
      "url": "/todos",
      "query": {},
      "params": {},
      "headers": {
        "host": "localhost:3000",
        "user-agent": "HTTPie/0.9.8",
        "accept-encoding": "gzip, deflate",
        "accept": "*/*",
        "connection": "keep-alive"
      },
      "remoteAddress": "::ffff:127.0.0.1",
      "remotePort": 49602
    }
    res: {
      "statusCode": 200,
      "headers": {
        "x-powered-by": "Express",
        "content-type": "application/json; charset=utf-8",
        "content-length": "2",
        "etag": "W/\"2-l9Fw4VUO7kr8CvBlt4zaMCqXZ0w\""
      }
    }
    responseTime: 21

Note: Add a reasonable default call to pino-pretty on every command that outputs JSON log in your package.json. Whether you start the application locally or you retrieve production logs, you'll always want to have it formatted.

Conclusion 🔗

We added a structured logger pino to the Node.js microservice architecture. It logs every incoming request with the express-pino-logger and allows to define custom logs inside and outside of the context of requests. In test cases, the logger does not pollute the test output. Locally, the structured logs are prettified with pino-pretty.

Become a GitHub sponsor to access the code of this post as a GitHub repo.