bunyanでLambda(Node.js)のログを取ると、CloudWatch Logsで検索しやすそうだった

通常のconsole.logだと、CloudWatch Logsに１行ごとにログがでます。 JSON型のほうがCloudWatch Logsのクエリしやすいので、他の方法を探してみます。 Install npmからインス […]

通常のconsole.logだと、CloudWatch Logsに１行ごとにログがでます。

JSON型のほうがCloudWatch Logsのクエリしやすいので、他の方法を探してみます。

Install

npmからインストールします。

$ npm i -S bunyan bunyan-format

TypeScriptで使う場合は、＠typesも入れましょう。

$ npm i -D @types/bunyan @types/bunyan-format

使ってみる

シンプルに動かしてみます。

import bunyan from 'bunyan'
const logger = bunyan.createLogger({name: "myapp"});
logger.trace('hello')
logger.debug('hello')
logger.warn('hello')
logger.fatal('hello')

これの実行結果がこちら。


{"name":"myapp","hostname":"okamotombp.lan","pid":34214,"level":40,"msg":"hello","time":"2019-08-01T06:57:08.353Z","v":0}
{"name":"myapp","hostname":"okamotombp.lan","pid":34214,"level":60,"msg":"hello","time":"2019-08-01T06:57:08.353Z","v":0}

trace / debugは省略されているのがわかります。

bunyan-formatでリーダブルにする

levelは出ていますが、ぱっと見どのレベルかわかりませんので文字列にしてみましょう。

import bunyan from 'bunyan'
import bunyanFormat from 'bunyan-format'
const logger = bunyan.createLogger({
  name: "myapp",
  level: 'debug',
  stream: new bunyanFormat({
    outputMode: 'bunyan',levelInString: true }),
});

logger.trace('hi on trace')
logger.debug('hi on debug')
logger.info('hi on info')

こちらでは、levelが文字列化されています。

{"name":"myapp","hostname":"okamotombp.lan","pid":34214,"level":"DEBUG","msg":"hi on debug","time":"2019-08-01T06:58:37.349Z","v":0}
{"name":"myapp","hostname":"okamotombp.lan","pid":34214,"level":"INFO","msg":"hi on info","time":"2019-08-01T06:58:37.350Z","v":0}

levelは文字？数字？

身も蓋もないですが、ケースバイケースでしょう。

「warning以上のエラーを見る」や「info以下だけを見たい」のような「以上・以下」での検索がメインであれば、数字のほうが比較演算子１つでフィルタできて便利です。一方「Fatalだけ監視したい」のように見るものが決まっている場合は、文字列のほうが検索クエリを作りやすいでしょう。

サブコンポーネントのログであることを記録する

bunyanにはlog.childメソッドが用意されています。これを利用することで、サブコンポーネントにいることも記録できます。

import bunyan from 'bunyan'
import bunyanFormat from 'bunyan-format'
import uuid from 'uuid'
const log = bunyan.createLogger({
  name: "myapp",
  level: 'debug',
  stream: new bunyanFormat({
    outputMode: 'bunyan',levelInString: true }),
});

class Wuzzle {
  private log: any
  constructor(options: any) {
    this.log = options.log.child({widget_type: 'wuzzle'});
    this.log.info('creating a wuzzle')
  }
  woos() {
    this.log.warn('This wuzzle is woosey.')
  }
}

log.info('start');
// サブじゃないので記録されない
log.child({req_id: uuid.v4()}, true)
var wuzzle = new Wuzzle({log: log});
wuzzle.woos();
log.info('done');

このログには、widget_typeというプロパティのあるものが混ざります。

{"name":"myapp","hostname":"okamotombp.lan","pid":34214,"level":"INFO","msg":"start","time":"2019-08-01T07:12:20.835Z","v":0}
{"name":"myapp","hostname":"okamotombp.lan","pid":34214,"widget_type":"wuzzle","level":"INFO","msg":"creating a wuzzle","time":"2019-08-01T07:12:20.836Z","v":0}
{"name":"myapp","hostname":"okamotombp.lan","pid":34214,"widget_type":"wuzzle","level":"WARN","msg":"This wuzzle is woosey.","time":"2019-08-01T07:12:20.836Z","v":0}
{"name":"myapp","hostname":"okamotombp.lan","pid":34214,"level":"INFO","msg":"done","time":"2019-08-01T07:12:20.836Z","v":0}

Serializerで記録するとマズい情報を除外する

APIバックエンドやAlexaでは、時折記録するとまずい個人情報（パスワード・健康情報・位置情報など）がリクエストに混ざることがあります。これをそのまま記録するのはちょっとよろしくないので、Serializerで除外します。

import bunyan from 'bunyan'
import bunyanFormat from 'bunyan-format'
import uuid from 'uuid'
const log = bunyan.createLogger({
  name: "myapp",
  level: 'debug',
  serializers:{
    req: req => {
      if (!req.body) return req
      if (req.body.password) delete req.body.password
      return req
    },
    err: err => {
      const { name, message, stack} = err
      return {
        name,
        message,
        stack
      }
    }
  },
  stream: new bunyanFormat({
    outputMode: 'bunyan',levelInString: true }),
});

// HTTPリクエストの一部をイメージ
log.info({req: {
  method: 'POST',
  request_id: uuid.v4(),
  body: {
    username: 'user',
    password: 'secret'
  }
}})
// エラーが起きた
log.error(new Error('Some Error'))
// 普通のログ
log.warn('Some warning')

reqオブジェクトを渡した時は、req.body.passwordを除外する
Errorオブジェクトを渡した場合は必要な情報のみを出すようにする
それ以外のメッセージはそのまま出す

このようなことがSerializersで設定できます。