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

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

[winston]: https://github.com/winstonjs/winston

## この投稿で学べること

1. winstonをGoogle Cloud Functionsの関数に組み込む方法
1. winstonのメソッドの呼び出し方
1. winstonでオブジェクトの値をロギングする方法
1. 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を使うことでより、高レベルのロギングができます。

> :bulb: `console.log`で行う低レベルなロギングについて知りたい方はこちら↓
> [Google Functions & Node.js: console.logを使った最低限のロギング - Qiita](https://qiita.com/suin/items/9554c70ed3571be0f08c)

### winstonをインストールする

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

```bash
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')
}
```

### 関数をデプロイして試す

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

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

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

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

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

<img width="798" alt="CleanShot 2020-08-06 at 09.37.28@2x.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/36a6ccce-7e3d-c7bc-8833-909924c73886.png">

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

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

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

> :bulb: `console.log`とGCPの「重大度」の関係性についての詳細は[Google Functions: console.infoやconsole.errorなどとログビューアの「重大度」の関係性](https://qiita.com/suin/items/d5d5d7199b62eed63bde)をご覧ください。

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

![CleanShot 2020-08-06 at 09.41.58@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/fd068ca9-6c16-5ca5-9ebc-8f4653872f62.png)

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

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

![CleanShot 2020-08-06 at 09.44.55@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/22195b2b-e098-83c4-7912-04535539ab1c.png)

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

![CleanShot 2020-08-06 at 09.48.30@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/431b83f5-3dd5-81d1-0f6c-b953c643fc33.png)

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

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')
}
```

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

![CleanShot 2020-08-06 at 09.59.53@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/90778c49-d91e-162c-d946-2f0933006ef7.png)

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

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