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で記録してみましょう。

index.js

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

index.js

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

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

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

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

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

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

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

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

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

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

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行のログにまとまっていることが分かります:

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

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

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

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
• Google Functions & Node.js: winstonで高レベルなロギングをする方法 - Qiita
• Google Functions & Node.js: bunyanで高レベルなロギングをする方法 - Qiita