本稿では、Google Could Platform(GCP)のGoogle Cloud Functions(GCF)で、Node.jsのロギングライブラリbunyanを使ったログの記録方法を説明します。
この投稿で学べること
- bunyanをGoogle Cloud Functionsの関数に組み込む方法
- bunyanのメソッドの呼び出し方
- bunyanでオブジェクトの値をロギングする方法
- 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化すると文字列になったりしています。