node.js でエラーログをちゃんと出す(pino)

なんとなくやっていたらちゃんとログが出ていなくてエラー調査時に困った。
ロガーは pino を使用。
エラークラスは make-error-cause を使って、ベースの ApplicationError を作成。
投げ直すエラーはすべてこの ApplicationError を継承して作るようにしていた。

import { BaseError } from "make-error-cause";

class ApplicationError extends BaseError {}
class RequestFailedError extends ApplicationError {}

エラーの投げ直しとログ出しはこんな感じで

import pino from "pino";

const logger = pino();
const request = async () => {
  try {
    await fetch("/example");
  } catch (e) {
    throw e instanceof Error
      ? new RequestFailedError("Failed to request /example", e)
      : e;
  }
};
const main = async () => {
  try {
    await request();
  } catch (e) {
    logger.error(e);
  }
};

make-error-cause を使うと罠の多いエラー継承を普通に継承するだけでよくなり、エラーメッセージもつけられるようになる。
console.error を使うと make-error-cause のエラーは下記のように元となったエラーも合わせて表示してくれる。

RequestFailedError: Failed to request /example
    at /Users/airtoxin/repositories/s/src/logging.ts:25:9
    at step (/Users/airtoxin/repositories/s/src/logging.ts:48:23)
    at Object.throw (/Users/airtoxin/repositories/s/src/logging.ts:29:53)
    at rejected (/Users/airtoxin/repositories/s/src/logging.ts:21:65)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

The following exception was the direct cause of the above exception:

TypeError: Failed to parse URL from /example
    at new Request (/Users/airtoxin/repositories/s/node_modules/undici/lib/fetch/request.js:84:15)
    at Agent.fetch (/Users/airtoxin/repositories/s/node_modules/undici/lib/fetch/index.js:121:25)
    at fetch (/Users/airtoxin/repositories/s/node_modules/undici/index.js:102:22)
    at /Users/airtoxin/repositories/s/src/logging.ts:22:16
    at step (/Users/airtoxin/repositories/s/src/logging.ts:48:23)
    at Object.next (/Users/airtoxin/repositories/s/src/logging.ts:29:53)
    at /Users/airtoxin/repositories/s/src/logging.ts:23:71
    at new Promise (<anonymous>)
    at __awaiter (/Users/airtoxin/repositories/s/src/logging.ts:19:12)
    at request (/Users/airtoxin/repositories/s/src/logging.ts:20:17)

The following exception was the direct cause of the above exception:

TypeError: Invalid URL
    at new NodeError (node:internal/errors:371:5)
    at onParseError (node:internal/url:552:9)
    at new URL (node:internal/url:628:5)
    at new Request (/Users/airtoxin/repositories/s/node_modules/undici/lib/fetch/request.js:82:21)
    at Agent.fetch (/Users/airtoxin/repositories/s/node_modules/undici/lib/fetch/index.js:121:25)
    at fetch (/Users/airtoxin/repositories/s/node_modules/undici/index.js:102:22)
    at /Users/airtoxin/repositories/s/src/logging.ts:22:16
    at step (/Users/airtoxin/repositories/s/src/logging.ts:48:23)
    at Object.next (/Users/airtoxin/repositories/s/src/logging.ts:29:53)
    at /Users/airtoxin/repositories/s/src/logging.ts:23:71 {
  input: '/example',
  code: 'ERR_INVALID_URL'
}

pino を使ったエラーログもこれが出てくれることを期待するが、上記コードでエラーログを出してみると実際は

[1651700227725] ERROR (43608 on hexa.local): Failed to request /example
    err: {
      "type": "RequestFailedError",
      "message": "Failed to request /example",
      "stack":
          RequestFailedError: Failed to request /example
              at /Users/airtoxin/repositories/s/src/logging.ts:25:9
              at step (/Users/airtoxin/repositories/s/src/logging.ts:48:23)
              at Object.throw (/Users/airtoxin/repositories/s/src/logging.ts:29:53)
              at rejected (/Users/airtoxin/repositories/s/src/logging.ts:21:65)
              at processTicksAndRejections (node:internal/process/task_queues:96:5)
    }

と、投げ直したエラーの情報しか出してくれない。(見やすいように pino-pretty を掛けています)
情報を増やすために投げ直していたのに、これでは情報が減っていてむしろ投げ直さないほうがマシまである。

解決法

pino のエラーシリアライザをカスタム定義する。

import { fullStack } from "make-error-cause";

const logger = pino({
  serializers: {
    err(value) {
      if (value instanceof Error) {
        return fullStack(value);
      } else {
        return value;
      }
    },
  },
});

このロガーを使ってエラーログを出力すると

RequestFailedError: Failed to request /example
    at /Users/airtoxin/repositories/s/src/logging.ts:25:9
    at step (/Users/airtoxin/repositories/s/src/logging.ts:48:23)
    at Object.throw (/Users/airtoxin/repositories/s/src/logging.ts:29:53)
    at rejected (/Users/airtoxin/repositories/s/src/logging.ts:21:65)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

The following exception was the direct cause of the above exception:

TypeError: Failed to parse URL from /example
    at new Request (/Users/airtoxin/repositories/s/node_modules/undici/lib/fetch/request.js:84:15)
    at Agent.fetch (/Users/airtoxin/repositories/s/node_modules/undici/lib/fetch/index.js:121:25)
    at fetch (/Users/airtoxin/repositories/s/node_modules/undici/index.js:102:22)
    at /Users/airtoxin/repositories/s/src/logging.ts:22:16
    at step (/Users/airtoxin/repositories/s/src/logging.ts:48:23)
    at Object.next (/Users/airtoxin/repositories/s/src/logging.ts:29:53)
    at /Users/airtoxin/repositories/s/src/logging.ts:23:71
    at new Promise (<anonymous>)
    at __awaiter (/Users/airtoxin/repositories/s/src/logging.ts:19:12)
    at request (/Users/airtoxin/repositories/s/src/logging.ts:20:17)

The following exception was the direct cause of the above exception:

TypeError: Invalid URL
    at new NodeError (node:internal/errors:371:5)
    at onParseError (node:internal/url:552:9)
    at new URL (node:internal/url:628:5)
    at new Request (/Users/airtoxin/repositories/s/node_modules/undici/lib/fetch/request.js:82:21)
    at Agent.fetch (/Users/airtoxin/repositories/s/node_modules/undici/lib/fetch/index.js:121:25)
    at fetch (/Users/airtoxin/repositories/s/node_modules/undici/index.js:102:22)
    at /Users/airtoxin/repositories/s/src/logging.ts:22:16
    at step (/Users/airtoxin/repositories/s/src/logging.ts:48:23)
    at Object.next (/Users/airtoxin/repositories/s/src/logging.ts:29:53)
    at /Users/airtoxin/repositories/s/src/logging.ts:23:71 {
  input: '/example',
  code: 'ERR_INVALID_URL'
}

ちゃんとすべてのエラースタックが表示されている。
pino 以外のロガーでもシリアライザの定義はありそうなので、そのような箇所で make-error-cause の fullStack 関数を使ってやるようにすれば良いはず。