🦔

Pinoのtransportで複数targetを指定するならformatters.levelに注意

に公開

背景

Pinoを使ったロギングの設定ですが、CloudWatchのようなGUI上でフィルタリングができるツールへの出力の場合、単一のログストリームへ全てのレベルのログを出力しても問題ない、むしろ検索しやすいという認識なのですが、一方でファイルでのログ管理をしている場合に、レベルによってはファイルを分けて管理したいという考え方があると思います。
ログの設定などはあまり時間をかけたくないところだと思いますが、AIと一緒に実装してみて、つまずいてしまった場面があったので、どう実装するのがいいのかを自分の中で整理したく、こちらの記事に残そうと思います。

想定する対象読者

  • TypeScript/JavaScriptエンジニアの方
  • ロギングライブラリで何を使おうか検討中の方
  • Pinoで複数のtransport先を指定してログ管理でつまずきのある方

実行環境

  • Macbook Pro, Apple M1 Pro
  • Node.js v22.12.0
  • pnpm@10.12.2
  • pino@9.9.0
  • pino-pretty@13.1.1
  • pino-roll@3.1.0
  • tsx@4.20.5

つまずいてしまった実装

Pinoによる複数ファイル出力のための実装

まずAIにざっと複数のファイルにログを出力するためにPinoでの実装例を作成してもらいました。
先にお伝えすると、この実装では問題なくログファイルへの出力ができました。

import pino from "pino";

// 通常ログ用(info以上)
const infoTransport = {
  target: "pino-roll",
  level: "info",
  options: {
    file: "logs/app-info.log",
    frequency: "daily",
    mkdir: true,
    size: "10m"
  },
};

// エラーログ用
const errorTransport = {
  target: "pino-roll",
  level: "error",
  options: {
    file: "logs/app-error.log",
    frequency: "daily",
    mkdir: true,
    size: "10m"
  },
};

// pino loggerを作成
const logger = pino(
  {
    level: "info",
  },
  pino.transport({
    targets: [
      infoTransport,
      errorTransport,
    ],
  })
);

上記のコードをベースに私が実装しようとしたものをAIと一緒に作成したのが下記です。

ログが出力されなかった実装

import path from 'path';
import pino from 'pino';
import { NODE_ENVS } from '../../shared/constants';

// アプリケーション内で利用するロギング機能の抽象インターフェースを定義
export interface CustomLogger {
  info(msg: string, meta?: Record<string, any>): void;
  error(msg: string, meta?: Record<string, any>): void;
  warn(msg: string, meta?: Record<string, any>): void;
  debug(msg: string, meta?: Record<string, any>): void;
}

interface LogConfig {
  level: pino.Level;
  environment: string;
  prettyPrint: boolean;
}

// DI(依存性注入)のためにFactory関数として定義
export const createCustomLogger = (): CustomLogger => {
  const config: LogConfig = {
    level: (process.env.LOG_LEVEL ?? 'info') as pino.Level,
    environment: process.env.NODE_ENV ?? NODE_ENVS.DEVELOPMENT,
    prettyPrint: process.env.NODE_ENV === NODE_ENVS.DEVELOPMENT,
  };

  // 通常ログ用(info以上)
  const infoTransport: pino.TransportTargetOptions = {
    target: 'pino-roll',
    level: 'info',
    options: {
      file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
      frequency: 'daily',
      mkdir: true,
      size: '10m',
    },
  };

  // エラーログ用
  const errorTransport: pino.TransportTargetOptions = {
    target: 'pino-roll',
    level: 'error',
    options: {
      file: path.resolve(process.cwd(), 'logs', 'app-error.log'),
      frequency: 'daily',
      mkdir: true,
      size: '10m',
    },
  };

  // 開発環境用コンソールログ
  const prettyPrintTransport: pino.TransportTargetOptions = {
    target: 'pino-pretty',
    options: {
      colorize: true,
      translateTime: 'yyyy-MM-dd HH:mm:ss',
      ignore: 'pid,hostname',
    },
  };

  // pino loggerを作成
  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label) => ({ level: label }),
      },
    },
    pino.transport({
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    })
  );

  return {
    info: (msg: string, meta?: Record<string, any>) => pinoLogger.info(meta, msg),
    error: (msg: string, meta?: Record<string, any>) => pinoLogger.error(meta, msg),
    warn: (msg: string, meta?: Record<string, any>) => pinoLogger.warn(meta, msg),
    debug: (msg: string, meta?: Record<string, any>) => pinoLogger.debug(meta, msg),
  };
};

こちらの実装において、特にコンパイルエラーは発生しませんが、実際に動かしてみるとinfoのログはapp-info.logに、errorのログはerror-info.logに出力されず、意図した動きになりませんでした。
どうやら自分が付け加えたコードに問題があるようです。どこに問題があるか一見分からなかったので、ひとつずつプロパティをコメントアウトして問題点を特定します。

formatters.levelの指定の問題

formatters.levelの設定をコメントアウトすることでログが出力されたので、この設定に問題があることがわかりました。

  const pinoLogger = pino(
    {
      formatters: {
        level: (label) => ({ level: label }), // これが良くないらしい
    }
  );

ちなみにこの設定をする意図としては、デフォルトでlevelに出力される値が数値のログレベルとなっています。ログの可読性を上げるために、ログレベルをラベル表記したいためにこのフォーマットの指定を行っている、という経緯になります。

# デフォルトのログ
{"level":30}

# ログレベルのラベルと数値の対応表
{ label: 'trace', number: 10 }
{ label: 'debug', number: 20 }
{ label: 'info', number: 30 }
{ label: 'warn', number: 40 }
{ label: 'error', number: 50 }
{ label: 'fatal', number: 60 }

こちらの点についてAIに尋ねると下記の回答が返ってきました。

pinoでは、 formatters (特に formatters.level )と transport を同時に使用すると、ファイル出力が正常に動作しない既知の問題があります。これは以下の理由によるものです:

  1. Transport処理パスの違い : Transportは通常のログ出力とは異なるコードパスを通るため、formattersの変更が適用されない
  2. Level formatter問題 : formatters.level でlevelを文字列(label)に変更すると、transportが正しく処理できない
  3. シリアライゼーション問題 : Transportに渡される際に、formattersの変更が失われる

この点について言及されているページが見つかったのでぜひ下記も併せて確認してみてください。

https://stackoverflow.com/questions/76715489/pino-logger-not-logging-anything-when-setup-with-multiple-transports

https://github.com/pinojs/pino/issues/1353

上記のページを踏まえると下記のことがわかりました。

  • 複数のtransport先がある場合、formatters.levelのフォーマット指定において、labelをそのまま指定するとログが出力されない
  • 複数のtransport先がある場合でもlevelでないプロパティにlabelを指定するとログが出力される

transportが複数の場合に限りそのような挙動なのか、単一のtransportでも同様なのかを確認したくなったので、実際に動かしてみようと思います。
下記の組み合わせで整理してみましょう。

出力先の個数 実装 formatters.levelの指定
単数 transportプロパティに指定 (label) => ({ level: label })
複数 pino.transportに指定 (label) => ({ 'level-label': label })
- - (label, number) => ({ level: number, 'level-label': label })
- - (label, number) => ({ level: label, 'level-number': number })

結論として、下記のような結果となりました。(実際に試してみたコードはAppendixに載せました)

No. 出力先の個数 出力先の指定場所 formatters.level の指定 出力される
1 単数 transportプロパティに指定 (label) => ({ level: label }) Yes
2 単数 transportプロパティに指定 (label) => ({ 'level-label': label }) Yes
3 単数 transportプロパティに指定 (label, number) => ({ level: number, 'level-label': label }) Yes
4 単数 transportプロパティに指定 (label, number) => ({ level: label, 'level-number': number }) Yes
5 単数 pino.transportに指定 (label) => ({ level: label }) Yes
6 単数 pino.transportに指定 (label) => ({ 'level-label': label }) Yes
7 単数 pino.transportに指定 (label, number) => ({ level: number, 'level-label': label }) Yes
8 単数 pino.transportに指定 (label, number) => ({ level: label, 'level-number': number }) Yes
9 複数 transportプロパティに指定 (label) => ({ level: label }) No
10 複数 transportプロパティに指定 (label) => ({ 'level-label': label }) No
11 複数 transportプロパティに指定 (label, number) => ({ level: number, 'level-label': label }) No
12 複数 transportプロパティに指定 (label, number) => ({ level: label, 'level-number': number }) No
13 複数 pino.transportに指定 (label) => ({ level: label }) No
14 複数 pino.transportに指定 (label) => ({ 'level-label': label }) No
15 複数 pino.transportに指定 (label, number) => ({ level: number, 'level-label': label }) Yes
16 複数 pino.transportに指定 (label, number) => ({ level: label, 'level-number': number }) No

まとめ

ここまで調査した中で分かったこととしては、複数のtransport先を指定する場合で、ログレベルのラベルを出力したい場合、下記のようにformatters.levelを指定する必要があることが分かりました。

  • levelnumberを渡す
  • levelではない任意のプロパティに対してlabelを渡す

なお、transportをtargetsではなく、targetで単数指定する場合においてはこのようなformatters.levelの制約は当てはまりませんでした。

ここまでログを初期化するためにしては時間をかけてしまったように思いますが、もしも同じようなつまずきをしている方がいらっしゃれば、この記事が目に留まってくれると嬉しいです。

Appendix

調査で利用したコードは記事にまとめると冗長だと思ったため折りたたんで記載させていただきます。

組み合わせの調査で利用したコード

No.1

  const pinoLogger = pino({
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label) => ({ level: label }),
    },
    transport: {
      target: 'pino-roll',
      level: 'error',
      options: {
        file: path.resolve(process.cwd(), 'logs', 'app-error.log'),
        frequency: 'daily',
        mkdir: true,
        size: '10m',
      },
    },
  });
# 出力結果
{"level":"info", ...}

No.2

  const pinoLogger = pino({
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label) => ({ 'level-label': label }),
    },
    transport: {
      target: 'pino-roll',
      level: 'error',
      options: {
        file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
        frequency: 'daily',
        mkdir: true,
        size: '10m',
      },
    },
  });
# 出力結果
{"level-label":"info", ...}

No.3

  const pinoLogger = pino({
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label, number) => ({ level: number, 'level-label': label }),
    },
    transport: {
      target: 'pino-roll',
      level: 'error',
      options: {
        file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
        frequency: 'daily',
        mkdir: true,
        size: '10m',
      },
    },
  });
# 出力結果
{"level":30,"level-label":"info", ...}

No.4

  const pinoLogger = pino({
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label, number) => ({ level: label, 'level-number': number }),
    },
    transport: {
      target: 'pino-roll',
      level: 'error',
      options: {
        file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
        frequency: 'daily',
        mkdir: true,
        size: '10m',
      },
    },
  });
# 出力結果
{"level":"info","level-number":30, ...}

No.5

  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label) => ({ level: label }),
      },
    },
    pino.transport({
      target: 'pino-roll',
      level: 'error',
      options: {
        file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
        frequency: 'daily',
        mkdir: true,
        size: '10m',
      },
    })
  );
# 出力結果
{"level":"info", ...}

No.6

  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label) => ({ 'level-label': label }),
      },
    },
    pino.transport({
      target: 'pino-roll',
      level: 'error',
      options: {
        file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
        frequency: 'daily',
        mkdir: true,
        size: '10m',
      },
    })
  );
# 出力結果
{"level-label":"info", ...}

No.7

  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label, number) => ({ level: number, 'level-label': label }),
      },
    },
    pino.transport({
      target: 'pino-roll',
      level: 'error',
      options: {
        file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
        frequency: 'daily',
        mkdir: true,
        size: '10m',
      },
    })
  );
# 出力結果
{"level":30,"level-label":"info", ...}

No.8

  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label, number) => ({ level: label, 'level-number': number }),
      },
    },
    pino.transport({
      target: 'pino-roll',
      level: 'error',
      options: {
        file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
        frequency: 'daily',
        mkdir: true,
        size: '10m',
      },
    })
  );
# 出力結果
{"level":"info","level-number":30, ...}

No.9

  const pinoLogger = pino({
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label) => ({ level: label }),
    },
    transport: {
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    },
  });
# 出力結果
Error: option.transport.targets do not allow custom level formatters

No.10

  const pinoLogger = pino({
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label) => ({ 'level-label': label }),
    },
    transport: {
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    },
  });
# 出力結果
Error: option.transport.targets do not allow custom level formatters

No.11

  const pinoLogger = pino({
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label, number) => ({ level: number, 'level-label': label }),
    },
    transport: {
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    },
  });
# 出力結果
Error: option.transport.targets do not allow custom level formatters

No.12

  const pinoLogger = pino({
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label, number) => ({ level: label, 'level-number': number }),
    },
    transport: {
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    },
  });
# 出力結果
Error: option.transport.targets do not allow custom level formatters

No.13

  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label) => ({ 'level': label }),
      },
    },
    pino.transport({
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    })
  );
# 出力結果なし

No.14

  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label) => ({ 'level-label': label }),
      },
    },
    pino.transport({
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    })
  );
# 出力結果なし

No.15

  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label, number) => ({ level: number, 'level-label': label }),
      },
    },
    pino.transport({
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    })
  );
# 出力結果
{"level":30,"level-label":"info", ...}

No.16

  const pinoLogger = pino(
    {
      level: config.level,
      timestamp: pino.stdTimeFunctions.isoTime,
      base: {
        env: config.environment,
        service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
      },
      formatters: {
        level: (label, number) => ({ level: label, 'level-number': number }),
      },
    },
    pino.transport({
      targets: [
        infoTransport,
        errorTransport,
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    })
  );
# 出力結果なし

おまけ

この記事で上げているコードにおいて、info.logにもエラーログが出力されてしまっており。厳密にはinfo.logとerror.logにおいて適切にレベルによるログの分類ができていませんでした。
自分が調べた限りだと、pino-rollを使ってログローテーションしながら、ログレベルの上限を決めるようなログのフィルタリングの設定が見つかりませんでした。。

いまのところ、AIと一緒に見つけた推奨案としては個別のpinoインスタンスを作る、というものです。
下記のような実装に着地しました。
もっと良い方法をご存知の方がいらっしゃればぜひご教示いただけると嬉しいです!

import path from 'path';
import pino from 'pino';
import { NODE_ENVS } from '../../shared/constants';

export interface CustomLogger {
  info(msg: string, meta?: Record<string, any>): void;
  error(msg: string, meta?: Record<string, any>): void;
  warn(msg: string, meta?: Record<string, any>): void;
  debug(msg: string, meta?: Record<string, any>): void;
}

interface LogConfig {
  level: pino.Level;
  environment: string;
  prettyPrint: boolean;
}

export const createCustomLogger = (): CustomLogger => {
  const config: LogConfig = {
    level: (process.env.LOG_LEVEL ?? 'info') as pino.Level,
    environment: process.env.NODE_ENV ?? NODE_ENVS.DEVELOPMENT,
    prettyPrint: process.env.NODE_ENV === NODE_ENVS.DEVELOPMENT,
  };

  const basePinoLoggerOption: pino.LoggerOptions = {
    level: config.level,
    timestamp: pino.stdTimeFunctions.isoTime,
    base: {
      env: config.environment,
      service: `${process.env.npm_package_name}@${process.env.npm_package_version}`,
    },
    formatters: {
      level: (label, number) => ({ level: number, 'level-label': label }),
    },
  };

  // 開発環境用コンソールログ
  const prettyPrintTransport: pino.TransportTargetOptions = {
    target: 'pino-pretty',
    options: {
      colorize: true,
      translateTime: 'yyyy-MM-dd HH:mm:ss',
      ignore: 'pid,hostname',
    },
  };

  // 通常ログ用(info以上、error未満)
  const infoLogger = pino(
    basePinoLoggerOption,
    pino.transport({
      targets: [
        {
          target: 'pino-roll',
          level: 'info',
          options: {
            file: path.resolve(process.cwd(), 'logs', 'app-info.log'),
            frequency: 'daily',
            mkdir: true,
            size: '10m',
          },
        },
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    })
  );

  // エラーログ用
  const errorLogger = pino(
    basePinoLoggerOption,
    pino.transport({
      targets: [
        {
          target: 'pino-roll',
          level: 'error',
          options: {
            file: path.resolve(process.cwd(), 'logs', 'app-error.log'),
            frequency: 'daily',
            mkdir: true,
            size: '10m',
          },
        },
        ...(config.prettyPrint ? [prettyPrintTransport] : []),
      ],
    })
  );

  return {
    info: (msg: string, meta?: Record<string, any>) => infoLogger.info(meta, msg),
    error: (msg: string, meta?: Record<string, any>) => errorLogger.error(meta, msg),
    warn: (msg: string, meta?: Record<string, any>) => infoLogger.warn(meta, msg),
    debug: (msg: string, meta?: Record<string, any>) => infoLogger.debug(meta, msg),
  };
};

Discussion