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

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

この投稿で学べること

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

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

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

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

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

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

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

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

winstonをインストールする

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

yarn add winston

winstonを関数に組み込む

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

winstonの設定コード

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

index.js

const winston = require('winston')

const logger = winston.createLogger({
  level: 'silly', // 記録するログレベルの設定
  transports: [
    new winston.transports.Console(), // どこにログ出しするかの設定
  ],
})

createLoggerメソッドにはロガーの設定を渡します。levelは記録するログレベルで、次の7段階があります:

レベル	優先度(小さいほうが重要)
error	0
warn	1
info	2
http	3
verbose	4
debug	5
silly	6

levelに指定したログレベル以下のログが記録されるようになります。例えば、infoを設定すると、errorからinfoまでが記録され、http以降のログは記録されません。上のサンプルコードではsillyを設定しているので、全レベルが記録されます。

transportsの設定は、どこにログを出すかの設定です。winston.transports.Consoleはconsole.logなどと同等と考えてください。Console以外にもファイルに出したりもできますが、Google Cloud Functionsではファイルにログ出しするという運用は通常行いません。

ロギングするコード

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

index.js

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

関数の全体像

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

index.js

const winston = require('winston')

const logger = winston.createLogger({
  level: 'silly', // 記録するログレベルの設定
  transports: [
    new winston.transports.Console(), // どこにログ出しするかの設定
  ],
})

exports.loggingWithWinston = async (req, res) => {
  logger.error('errorのメッセージ')
  logger.warn('warnのメッセージ')
  logger.info('infoのメッセージ')
  logger.verbose('verboseのメッセージ')
  logger.debug('debugのメッセージ')
  logger.silly('sillyのメッセージ')

  res.send('OK')
}

関数をデプロイして試す

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

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

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

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

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

ちゃんとログがでているのが分かります。

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

今回記録したログはどれも「重大度」はDEFAULTになっています。これは、winston.transports.Consoleが内部でconsole.logなどを使っているためです。

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

では、どこにwinstonのログレベルが残っているのでしょうか？ ログエントリの詳細を開くと分かります。

このログはlogger.info()で記録したものですが、jsonPayload.levelに"info"とあるのが見て取れます。これが、winstonのログレベルです。

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

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

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

winstonのロギングメソッドは、第二引数にメタ情報を渡すことができます。メタ情報とは、ログメッセージに関連するデータのことです。ログメッセージがどういう状況で出たのかを後から分かるように、それに関連するデータを一緒に記録できるわけです。

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

index.js

const winston = require('winston')

const logger = winston.createLogger({
  level: 'silly', // 記録するログレベルの設定
  transports: [
    new winston.transports.Console(), // どこにログ出しするかの設定
  ],
})

exports.loggingWithWinston = 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.error('errorのメッセージ+object', object)
  logger.warn('warnのメッセージ+object', object)
  logger.info('infoのメッセージ+object', object)
  logger.verbose('verboseのメッセージ+object', object)
  logger.debug('debugのメッセージ+object', object)
  logger.silly('sillyのメッセージ+object', object)

  res.send('OK')
}

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

メタ情報はjsonPayloadのプロパティ組み込まれます。これにより運用時にログの状況を確認したり、ログのフィルタリングや分析に活用することができます。

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