Google Functions & Node.js: bunyanで高レベルなロギングをする方法

本稿では、Google Could Platform(GCP)のGoogle Cloud Functions(GCF)で、Node.jsのロギングライブラリbunyanを使ったログの記録方法を説明します。

この投稿で学べること

1. bunyanをGoogle Cloud Functionsの関数に組み込む方法
2. bunyanのメソッドの呼び出し方
3. bunyanでオブジェクトの値をロギングする方法
4. bunyanで記録したログの読み方

この投稿では説明しないこと

• bunyanを使ってStackDriverにロギングする方法
• bunyanを使ってStackDriverに「重要度」をつけながらロギングする方法

bunyanとStackDriverを組み合わせると、より自由度が高く分析しやすい構造でロギングすることが可能なりますが、この投稿ではそれについては説明しません。bunyanを単純にCloud Functionsで使うだけでも高レベルなロギングができて便利です。本稿はそこにフォーカスして説明することにします。

Cloud Functionsにてbunyanでロギングする方法

bunyanはロギングを抽象化したライブラリで、GCPに限ったものではなく、Node.jsのアプリケーションのロギングを手助けするものです。ログの出力先を、コンソールやファイルなど指定できたり、ログのレベル(INFO, WARN, ERROR)などを指定しながらロギングできるAPIが生えていて便利です。

GCFではconsole.logでもロギングできますが、低レベルなロギングしかできません。bunyanを使うことでより、高レベルのロギングができます。

console.logで行う低レベルなロギングについて知りたい方はこちら↓
Google Functions & Node.js: console.logを使った最低限のロギング - Qiita

bunyanをインストールする

まずロギングライブラリのbunyanをインストールします:

yarn add bunyan

bunyanを関数に組み込む

次にbunyanを関数に組み込みます。

bunyanの設定コード

"bunyan"モジュールからbunyanオブジェクトを取り出し、createLoggerメソッドでロガーを作ります。

const bunyan = require('bunyan')

const logger = bunyan.createLogger({ name: 'my-function' })

createLoggerメソッドにはロガーの設定を渡します。いろいろな設定が可能ですが、必須設定のnameフィールドだけ指定しておきます。

ロギングするコード

bunyanの設定コードを書いたら、今度は関数実行時にロギングするコードを書きます。先程作成したloggerオブジェクトのメソッドを呼び出すことで、ロギングができます。

exports.loggingWithBunyan = async (req, res) => {
  logger.fatal('fatalのメッセージ')
  logger.error('errorのメッセージ')
  logger.warn('warnのメッセージ')
  logger.info('infoのメッセージ')
  logger.debug('debugのメッセージ')
  logger.trace('traceのメッセージ')
}

関数の全体像

以上のbunyanの設定コードとロギングするコードを組み合わせてると関数が完成します。次が完成形のコードです:

const bunyan = require('bunyan')

const logger = bunyan.createLogger({ name: 'my-function' })

exports.loggingWithBunyan = async (req, res) => {
  logger.fatal('fatalのメッセージ')
  logger.error('errorのメッセージ')
  logger.warn('warnのメッセージ')
  logger.info('infoのメッセージ')
  logger.debug('debugのメッセージ')
  logger.trace('traceのメッセージ')
  res.send('OK')
}

関数をデプロイして試す

実装ができたので、関数をデプロイします:

gcloud functions deploy loggingWithBunyan --runtime=nodejs12 --trigger-http

デプロイが完了したら、関数を呼び出してみます:

curl https://asia-northeast1-${PROJECT}.cloudfunctions.net/loggingWithBunyan

関数のログビューアを開き、ちゃんとログが出ているか見てみます:

JSONらしきものが記録されていることが分かります。ログエントリを開いて詳細を見てみます:

これは、logger.fatal()で記録したログエントリです。これを見ると、メッセージがしっかり記録されていることが分かります。

bunyanのログレベルの情報はどこ？

今回記録したログはログビューア上の「重大度」がどれもDEFAULTになっています。これは、bunyanが内部でconsole.logなどを使っているためです。

console.logとGCPの「重大度」の関係性についての詳細はGoogle Functions: console.infoやconsole.errorなどとログビューアの「重大度」の関係性をご覧ください。

では、どこにbunyanのログレベルが残っているのでしょうか？ 先程のログエントリ詳細を見返してみましょう。

このログはlogger.fatal()で記録したものですが、jsonPayload.levelに60とあるのが見て取れます。これが、bunyanのログレベルfatalを指す値です。

ちなみに、ログビューアではjsonPayload.levelの値でフィルタリングすることができます。値をクリックするとメニューが出てくるので、その中から「一致エントリを表示」をクリックします:

すると、クエリが更新され、値に一致するログエントリのみに絞り込まれます:

オブジェクトの値をログに出す

bunyanのロギングメソッドに渡せるのは、文字列に限ったものではありません。オブジェクトを渡すこともできます。

下の例では、ログメッセージと一緒に記録したいオブジェクトをロギングするものです:

const bunyan = require('bunyan')

const logger = bunyan.createLogger({ name: 'my-function' })

exports.loggingWithBunyan = async (req, res) => {
  const object = {
    boolean: true,
    number: 1,
    string: 'string',
    array: [true, 1, 'string'],
    object: { a: true, b: 1, c: 'string' },
    set: new Set([true, 1, 'string']),
    date: new Date(),
  }

  logger.fatal({ message: 'fatalのメッセージ+object', object })
  logger.error({ message: 'errorのメッセージ+object', object })
  logger.warn({ message: 'warnのメッセージ+object', object })
  logger.info({ message: 'infoのメッセージ+object', object })
  logger.debug({ message: 'debugのメッセージ+object', object })
  logger.trace({ message: 'traceのメッセージ+object', object })

  res.send('OK')
}

この関数をデプロイして、呼び出してみるとログビューア上でオブジェクトの値を確認できます:

オブジェクトはjsonPayloadのプロパティで参照できます。これにより運用時にログの状況を確認したり、ログのフィルタリングや分析に活用することができます。

注意点として、記録できるオブジェクトはJSON.stringifyできる値のみという点です。上の例ではSetオブジェクトをオブジェクトに含めていますが、SetはJSON化すると{}になるのでログからは情報が欠けてしまっています。また、DateオブジェクトはJSON化すると文字列になったりしています。