Node.js Microservice Architecture Pino JSON logging of Axios HTTP requests

Other services can respond in unexpected ways or not be reachable at all. Therefore, we track the requests and responses to other services. This way, we can see if the source of an issue is within or outside of our service.

We configure the Pino JSON logger to log a reasonable amount of detail for each outgoing HTTP request and response.

Response Interceptor 🔗

Axios offers the concept of interceptors. A response interceptor is called after each incoming response.

We create an interceptor logResponse in a new module src/http/log-response.interceptor.ts. With the log level INFO, we log the status code, the HTTP method and the URL. With the log level DEBUG, we additionally log the response body.

import { AxiosResponse } from "axios";
import { logger } from "../logger";

export function logResponse(response: AxiosResponse): AxiosResponse {
  logger.info(
    {
      status: response.status,
      method: response.config?.method?.toUpperCase(),
      url: response.config?.url,
    },
    "Response"
  );
  logger.debug(
    {
      status: response.status,
      method: response.config?.method?.toUpperCase(),
      url: response.config?.url,
      body: response.data,
    },
    "Response Details"
  );
  return response;
}

We add a unit test to verify the format of the log lines.

import { AxiosResponse } from "axios";
import { logResponse } from "./log-response.interceptor";

jest.mock("../logger");

describe("logging responses", () => {
  it("should log a concise info and more debug info", () => {
    const logger = require("../logger").logger;
    logResponse({
      status: 200,
      data: {
        some: "response",
      },
      config: {
        data: {
          some: "request",
        },
        method: "get",
        url: "https://some.org/api",
      },
    } as AxiosResponse);
    expect(logger.error).not.toHaveBeenCalled();
    expect(logger.info).toHaveBeenCalledWith(
      {
        status: 200,
        method: "GET",
        url: "https://some.org/api",
      },
      "Response"
    );
    expect(logger.debug).toHaveBeenCalledWith(
      {
        status: 200,
        method: "GET",
        url: "https://some.org/api",
        body: {
          some: "response",
        },
      },
      "Response Details"
    );
  });
});

The function configureHttp is called in the main function of the application. We add the interceptor such that it is registered with Axios.

import axios from "axios";
// ...
import { logResponse } from "./log-response.interceptor";

export function configureHttp(): void {
  // ...
  axios.interceptors.response.use(logResponse);
}

Request interceptor 🔗

Locally, we are also interested in the outgoing request body. We add a request interceptor that logs the outgoing request in debug mode. This way, the observed log in npm start indicates an outgoing HTTP request.

import { AxiosRequestConfig } from "axios";
import { logger } from "../logger";

export function logRequest(request: AxiosRequestConfig): AxiosRequestConfig {
  logger.debug(
    {
      method: request.method?.toUpperCase(),
      url: request.url,
      body: request.data,
    },
    "Request"
  );
  return request;
}

We add a test to verify the logged JSON.

import { AxiosRequestConfig } from "axios";
import { logRequest } from "./log-request.interceptor";

jest.mock("../logger");

describe("logging requests", () => {
  it("should log a concise message and the full body in debug mode", () => {
    const logger = require("../logger").logger;
    logRequest({
      data: {
        some: "body",
      },
      method: "get",
      url: "https://some.org/api",
    } as AxiosRequestConfig);
    expect(logger.info).not.toHaveBeenCalled();
    expect(logger.error).not.toHaveBeenCalled();
    expect(logger.debug).toHaveBeenCalledWith(
      {
        method: "GET",
        url: "https://some.org/api",
        body: { some: "body" },
      },
      "Request"
    );
  });
});

In the axios configuration function configureHttp, we register the request interceptor.

import axios from "axios";
// ...
import { logRequest } from "./log-request.interceptor";
import { logResponse } from "./log-response.interceptor";

export function configureHttp(): void {
  // ...
  axios.interceptors.request.use(logRequest);
  axios.interceptors.response.use(logResponse);
}

Resulting log lines 🔗

We start the application locally with npm start. A request . ./local.sh && http DELETE http://localhost:3000/todos/6e5bad4c-7f1c-4ab4-9361-c6bd697b4257 Authorization:"Bearer $TOKEN1" results in a log line for the request and two log lines for the response. On production, only the response is logged.

npm start

DEBUG: Request
    method: "POST"
    url: "http://localhost:3001/notify/notifications"
    body: {
      "message": "Deleted todo 6e5bad4c-7f1c-4ab4-9361-c6bd697b4257"
    }
INFO: Response
    status: 200
    method: "POST"
    url: "http://localhost:3001/notify/notifications"
DEBUG: Response Details
    status: 200
    method: "POST"
    url: "http://localhost:3001/notify/notifications"
    body: {
      "message": "Notification created"
    }

Conclusion 🔗

We added a request and a response interceptor to Axios. Locally in debug mode, requests and responses are logged with their body. On production, there is only one log entry for the response of the request.

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