Google Functions & Node.js: console.logを使った最低限のロギング

この投稿では、Google Cloud Platform(GCP)のGoogle Cloud Functions(GCF)のNode.js環境で、`console.log`を使った最低限のロギング手法について解説します。

## この投稿で学ぶこと

* Google Cloud Functions & Node.jsでは、`console.log`で最低限のロギングは可能。
* 2行以上に渡るログは行ごとに分解されるので注意。
* jsonPayloadを意識すると、オブジェクトの構造をログに出すことも可能。

## GCFでは`console.log`でログを残せて、「ログビューア」で確認できる

まず、Google Cloud Functionsでどのようにロギングし、そのログをどうやって確認するのかを学びます。シンプルに1行のメッセージを`console.log`で記録してみましょう。

```javascript:index.js
exports.helloWorld = (req, res) => {
  console.log('helloWorld関数を実行しています。')
  res.send('Hello World!')
}
```

この`helloWorld`関数をGoogle Cloud Platformにデプロイします:

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

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

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

どのようなログが出たかは、GCPの管理コンソールの「Cloud Functions」を開き、「helloWorld」関数のメニューの「ログを表示」を開きます。

![CleanShot 2020-08-05 at 10.45.30@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/1053be9f-e030-4e1c-8580-9d22259cedf8.png)

開くと「ログビューア」が表示され、「クエリ結果」の部分にログの内容が表示されます:

![CleanShot 2020-08-05 at 10.49.09@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/190a2d4f-484c-2286-ce22-7d1dabe4556d.png)

ログが表示されるエリアを拡大してみると、`console.log`でロギングした「helloWorld関数を実行しています。」が記録されていることが分かります:

<img width="795" alt="CleanShot 2020-08-05 at 10.51.40@2x.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/b6fcd139-0729-5e97-e049-ed771653f864.png">

> :bulb: 関数が実行されてからログビューアに反映されるまで、数十秒の遅延があります。なので、関数実行後すぐにログビューアを開いてもログが出ていないかもしれません。その場合は、ログが出るまでログビューアのクエリ結果にある「現在の位置に移動」ボタンをクリックして新しいログの到着を待ちましょう。

ログは`>`のつまみを押すと、メタ情報を見ることができます:

![CleanShot 2020-08-05 at 10.57.42@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/8fd35497-1e1e-2307-6cd3-67f3e0bac301.png)

本稿では触れませんが、これらのメタ情報を活用してログを分析したりすることができます。

Node.js環境のGCFでは、`console.log`を使えば特にGCP側の設定をいじらなくてもログを確認できることが分かりました。

## console.logで2行以上出す場合は、ログが分割されてしまうので注意

`console.log`は複数行の文字列をロギングすることができますが、GCPで複数行のロギングをする場合は、ログが分割されてしまうので注意が必要です。どういうことか実験して確認してみましょう。

次の関数は複数行のログを吐くものです:

```javascript:index.js
exports.helloWorld = (req, res) => {
  console.log('1行目\n2行目\n3行目\n4行目\n5行目')
  res.send('Hello World!')
}
```

これをデプロイして呼び出してみると、ログビューアには次のようなログが残ります:

<img width="802" alt="CleanShot 2020-08-05 at 11.05.04@2x.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/b086dfc6-54ac-061b-4cfc-5d0b833519a8.png">

見ての通り、1回の`console.log`なのに、ログは5つ出来上がっています。`console.log`ごとに1つログができると思っていると、複数行になった場合、予想外のログになるので注意しましょう。

上の例だと、ログが複数行になっても問題ないですが、困る場合もあります。例えば、下の例のようにオブジェクトを`console.log`すると、

```javascript
exports.helloWorld = (req, res) => {
  console.log({
    boolean: true,
    number: 1,
    string: 'string',
    array: [1, 2, 3],
    object: {
      field1: 'aaaaaaaaaaaa',
      field2: 'aaaaaaaaaaaa',
      field3: 'aaaaaaaaaaaa',
    },
  })
  res.send('Hello World!')
}
```


ログがバラバラになってしまいビューアでの可読性が良くありませんし、ログをコピペするのも一手間だったりと、運用上の面倒くささが出てきます:

<img width="805" alt="CleanShot 2020-08-05 at 11.14.04@2x.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/1cde7214-a0e5-c044-8d87-a0117ebf6c7b.png">

この例では再現しませんでしたが、ログ行の順番が前後してしまうケースもあったりして、オブジェクトのようなネストした構造を安心して確認できないという問題もあったりします。

## オブジェクトを`console.log`するときは一旦JSONにすると、1ログになり、構造化もされる

複数行のログ、特にオブジェクトを`console.log`するときは、そのオブジェクトを一旦JSONにするといいです。JSONのログはGCPが特別扱いしてくれるので、ログが複数に分かれることが避けられ、おまけに、ログビューアでは構造化されて表示されるので見やすさも向上します。

例えば、下の関数のように、`JSON.stringify`でオブジェクトをJSON化した上で、`console.log`するようにします:

```javascript
exports.helloWorld = (req, res) => {
  console.log(
    JSON.stringify({
      boolean: true,
      number: 1,
      string: 'string',
      array: [1, 2, 3],
      object: {
        field1: 'aaaaaaaaaaaa',
        field2: 'aaaaaaaaaaaa',
        field3: 'aaaaaaaaaaaa',
      },
    }),
  )
  res.send('Hello World!')
}
```

この関数を実行し、そのログを確認すると1行のログにまとまっていることが分かります:

![CleanShot 2020-08-05 at 11.21.59@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/aa35d5b4-1173-011e-9ca7-b3cd352540c7.png)

加えて、ログを開いてみると、`jsonPayload`フィールドにオブジェクトが構造化されているのが分かります:

![CleanShot 2020-08-05 at 11.23.34@2x.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/889/4356f9f8-8446-2880-af75-ce5054030ee9.png)

## JSON.stringifyでデバッグできないオブジェクトもあるので注意

`JSON.stringify`すればどんなオブジェクトもデバッグできるかというと、そうでもないので注意してください。例えば、`Set`や`Map`はJSON化すると`{}`になってしまいます:

```javascript
const map = new Map([['a', 1], ['b', 2]])
const set = new Set([1, 2, 3])

console.log(map)
//=> Map(2) { 'a' => 1, 'b' => 2 }

console.log(set)
//=> Set(3) { 1, 2, 3 }

console.log(JSON.stringify(map))
//=> {}

console.log(JSON.stringify(set))
//=> {}
```

こうしたJSON化時に情報が失われるオブジェクトのロギングをGCPでどうやったらいいか、そのベストプラクティスは僕も分かっていません。もし、ご存じの方がいましたら教えてください。


## まとめ

* Google Cloud Functions & Node.jsでは、特に何も設定せずとも`console.log`で最低限のロギングは可能。
* 2行以上に渡るログは行ごとに分解されるので注意。
* jsonPayloadを意識したロギングをすれば、オブジェクトの構造をログに出すことも可能。

## 次に読む

* [Google Functions: console.infoやconsole.errorなどとログビューアの「重大度」の関係性 - Qiita](https://qiita.com/suin/items/d5d5d7199b62eed63bde)
* [Google Functions & Node.js: winstonで高レベルなロギングをする方法 - Qiita](https://qiita.com/suin/items/538914e47bbd4d9c4dab)
* [Google Functions & Node.js: bunyanで高レベルなロギングをする方法 - Qiita](https://qiita.com/suin/items/1f45d77672a7b6174465)