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

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

[bunyan]: https://github.com/trentm/node-bunyan

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

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

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

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

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

```bash
yarn add bunyan
```

### bunyanを関数に組み込む

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

#### bunyanの設定コード

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

```index.js
const bunyan = require('bunyan')

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

`createLogger`メソッドにはロガーの設定を渡します。[いろいろな設定が可能です](https://github.com/trentm/node-bunyan#constructor-api)が、必須設定の`name`フィールドだけ指定しておきます。

#### ロギングするコード

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

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

```

#### 関数の全体像

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

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

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

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

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

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

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

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

<img width="837" alt="CleanShot 2020-08-06 at 10.35.05@2x.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/ec8f0960-d58c-e8ac-3f32-f30f3f61bf15.png">

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

![](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/8a6c523f-afa0-e474-15d9-a91ea25fbe88.png)


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

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

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

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

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

![](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/d41e934f-caa9-517e-efec-7c90c4d3d14d.png)


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

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

![CleanShot 2020-08-06 at 10.43.55@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/07e77b32-e97e-5644-ecf2-e1d527859099.png)

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

![CleanShot 2020-08-06 at 10.47.19@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/6b2e21e0-5179-d498-c0c8-1818b38ae380.png)

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

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

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

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

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

![20200806105656@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/797378bc-af05-5d80-80b0-72a2c43f15e4.png)

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

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