Zenn
📝

Node.jsのロガー「pino」の使い方メモ

2022/07/24に公開
Node.js
JavaScript
TypeScript
#
pino
tech

Node.jsのロガー「pino」について、忘備録を兼ねて簡単に使い方をメモします。

https://github.com/pinojs/pino

インストール

npm install pino

ログをファイルに書き込む設定

まず、ログをログファイルに書きこむことを試してみます。

設定ファイルとして次のlogger.jsファイルを用意します（destinationにログファイルのパスを指定します）。

logger.js
let pino = require('pino')

module.exports.logger = pino({
  level: 'trace',
  transport: {
    target: 'pino/file',
    options: {
      destination: 'logs/out.log',
      mkdir: true
    }
  }
})

Common JSで書いていますがESMでもOKです。

pino/fileトランスポートがログをファイルに書き込みます。トランスポートとはログが発生したときにログをどこに送るかの転送先になります。

公式の使用例に比べて少し設定が複雑に見えるかもしれません。pino.destinationを使うともっとシンプルに書けますが、後々の拡張を考えるとトランスポートを使う方法が良いと思いますのでこうしました。
pino.destinationとpino/fileトランスポートはインターフェースが異なるだけで、中身は同じもの（sonic-boom後述）です。

ロガーのインポート

設定したロガーは、logger.jsからインポートすれば利用できるようになります。

let { logger } = require('./logger.js')

ログレベル

先のlogger.jsファイルのlevelプロパティには出力したい最低のログレベルを設定します。デフォルトは本番環境向けにinfoになっていますので、traceとdebugは出力されません。開発環境ではtraceに設定しておいたほうが良いです。

ログレベルの一覧と対応付けられた数値はlogger.levelsで確認できます。

let { logger } = require('./logger.js')

console.log(logger.levels)
// {
//   labels: {
//     '10': 'trace',
//     '20': 'debug',
//     '30': 'info',
//     '40': 'warn',
//     '50': 'error',
//     '60': 'fatal'
//   },
//   values: { trace: 10, debug: 20, info: 30, warn: 40, error: 50, fatal: 60 }
// }

ログの出力

ログを出力するには、ログレベルごとにメソッドが用意されています。

app.js
let { logger } = require('./logger.js')

logger.trace('trace log')
logger.debug('debug log')
logger.info('info log')
logger.warn('warn log')
logger.error('error log')
logger.fatal('fatal log')

実行すると、ログファイルに1行ごとにJSON形式で出力されます。

出力
{"level":10,"time":1658630562576,"pid":200036,"hostname":"...","msg":"trace log"}
{"level":20,"time":1658630562578,"pid":200036,"hostname":"...","msg":"debug log"}
{"level":30,"time":1658630562578,"pid":200036,"hostname":"...","msg":"info log"}
{"level":40,"time":1658630562578,"pid":200036,"hostname":"...","msg":"warn log"}
{"level":50,"time":1658630562578,"pid":200036,"hostname":"...","msg":"error log"}
{"level":60,"time":1658630562578,"pid":200036,"hostname":"...","msg":"fatal log"}

プロパティは以下です。

プロパティ 説明
level ログレベルの数値
time UNIXタイムスタンプ（ミリ秒）
pid プロセスID
hostname OSのホスト名
msg 出力メッセージ

独自のプロパティを出力する

ログを出力する各メソッドの第一引数にオブジェクトを渡せば独自のプロパティを出力することができます。第二引数にはメッセージを指定します（省略可）。

app.js
let { logger } = require('./logger.js')

logger.trace({ domain: 'main' }, 'trace log')
出力
{"level":10,"time":1658633672743,"pid":174296,"hostname":"...","domain":"main","msg":"trace log"}

グループ化する

logger.child()で、独自のプロパティをデフォルトに持つロガーを作ることができます。

app.js
let { logger } = require('./logger.js')

let child = logger.child({ domain: 'main' })

child.trace('trace log')
child.info('info log')
出力
{"level":10,"time":1658636134712,"pid":214804,"hostname":"...","domain":"main","msg":"trace log"}
{"level":30,"time":1658636134713,"pid":214804,"hostname":"...","domain":"main","msg":"info log"}

Errorオブジェクトを出力

pinoはErrorオブジェクトをそのまま出力できます。

app.js
let { logger } = require('./logger.js')

try {
  throw Error('msg')
} catch (err) {
  logger.error(err)
}
出力
{"level":50,"time":1658634277942,"pid":210872,"hostname":"...","err":{"type":"Error","message":"msg","stack":"Error: msg\n    at Object.<anonymous> (C:\\pinotest\\app.js:4:9)\n    at Module._compile (node:internal/modules/cjs/loader:1097:14)\n    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1149:10)\n    at Module.load (node:internal/modules/cjs/loader:975:32)\n    at Function.Module._load (node:internal/modules/cjs/loader:822:12)\n    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)\n    at node:internal/main/run_main_module:17:47"},"msg":"msg"}

sonic-boomについて

pino/fileトランスポートはsonic-boomとして実装は別のリポジトリになっています。そのためオプション機能はsonic-boomを参考にしてください。

https://github.com/pinojs/sonic-boom

特徴として、非同期ではログを一旦バッファに溜めておいてから、溜まったらファイルに書き込むという動きをすることがあります。もし出力したはずのログが書き込まれていないと思ったら任意のタイミングでlogger.flush()を実行するようにすると溜まっているログが書き込まれます。

ログファイルを解析する

pino/fileトランスポートで書き込まれたログファイルは、日付がUNIXタイムスタンプになっていますので人がそのまま読むのには向いていません。
その代わり、1行ごとにJSON形式になっているのでプログラムで簡単に扱うことができます。

プログラムを作らずに、すぐに確認したいという場合はjqコマンドとpino-prettyを組み合わせるのが便利です。
jqは出力するログをクエリで選択できます。
pino-prettyはpinoのログを人が見やすいように整えてくれます。

  • pino-prettyのインストール（jqは環境に合わせてインストールしてください）
npm install -g pino-pretty

例：エラーログだけを抽出する

cat logs/out.log | jq -c 'select(.level == 50)' | pino-pretty -t 'SYS:standard'

例：ある日付以降を抽出（日本時間の場合です。もっといい書き方ありそう）

cat logs/out.log | jq -c 'select(.time > ((\"2022-07-24T00:00:00Z\" | fromdate)) * 1000 - 32400000)' | pino-pretty -t 'SYS:standard'

ファイル以外に出力する

ログをslackに投げたり、ログローテーションしたりするには、誰かが作ったトランスポートを探すか、トランスポートを自作します。

自作トランスポートの作り方

pino-abstract-transportを使って簡単にトランスポートを作ることができます。pino-abstract-transportはpinoをインストールしたら別途インストールしなくても利用できます。

https://github.com/pinojs/pino-abstract-transport

コンソールに出力するだけのトランスポートはこうなります。

my_transport.js
let build = require('pino-abstract-transport')

module.exports = function(opts) {
  return build(function(source) {
    source.on('data', function(obj) {
      console.log(obj)
    })
  })
}

objにJSONとして出力されていたオブジェクトが入っていますので、これを好きなようにカスタマイズして好きなところに出力するだけです。

自作トランスポートの利用

作ったトランスポートはlogger.js設定時にtargetにファイル名を渡します。

logger.js
let pino = require('pino')

module.exports.logger = pino({
  level: 'trace',
  transport: {
    target: './my_transport.js'
  }
})

複数のトランスポートの利用

logger.js設定時にtargetsに複数のトランスポートを設定することができます。設定したすべてのトランスポートにログが出力されます。

このとき、最上位のlevelとは別に、各トランスポートでもlevelを設定する必要があります。しないとinfoになります。トランスポートごとにログレベルを調整できるように、このような仕様になっていると思われます。

logger.js
let pino = require('pino')

module.exports.logger = pino({
  level: 'trace',
  transport: {
    targets: [
      { target: './my_transport.js', level: 'error' },
      {
        target: 'pino/file',
        options: {
          destination: 'logs/out.log',
          mkdir: true
        },
        level: 'trace'
      }
    ]
  }
})

ブラウザでも使える

pinoはブラウザ上のJavaScriptでも使えますが、設定方法は異なります。
サーバーサイドほど複雑ではありませんのでドキュメントが参考になります。

Discussion