GAS でStackdriver Loggingを使う

ちょっとしたことの自動化のために Google Apps Script （GAS）で実装することがあるのだけど、時々、ちゃんと実行されているのかログを取りたいときがある。

これまでは、`Logger.log()`を使ったり、スプレッドシートに書き出していた。
`Logger.log()`だと、最後の実行時のものしか見れないし、表示もアレなのでたくさん出力すると探しづらい。スプレッドシートにシートに書き出すと、`Logger.log()`の問題点は解消できるが、課題解決に本質的でないコードを書かねばならない。

そう思っていたところに去年の夏頃に追加されたらしい[^1] Stackdriver Logging を見つけた。便利そうなので調べてみた。
[^1]: [G Suite Developers Blog: Stackdriver Logging for Google Apps Script is now available](https://gsuite-developers.googleblog.com/2017/08/stackdriver-logging-for-google-apps.html)

## 料金
Stackdirver は Google Cloud のサービスで残念ながら 2018/03/31以降課金をするそうだ。
でも次の無料枠があり、個人的な効率化のために動かす程度のGASならこの範囲に収まるだろうと思う。

- ログの上限： 毎月プロジェクトごとに 50 GB
- ログの保持期間： 7 日

上記は *基本階層* と呼ばれるプランで、これを超えるには*プレミアム階層*というプランに切り替えれば良いようだ。
詳しくは [料金  \|  Stackdriver ドキュメント  \|  Google Cloud Platform](https://cloud.google.com/stackdriver/pricing#service_tiers)を参照のこと。不意の課金への責任は負いかねるのであしからずご了承願いたい。

## ログ出力

ログの出力は標準的な次のレベルを設定できる。

|ログレベル|出力メソッド|
|---|---|
|DEBUG|`console.log()`|
|INFO|`console.info()`|
|WARN|`console.warn()`|
|ERROR|`console.error()`|

なんだ `console.log()`じゃないかと思う人も多いだろう。`Logger.log（）`より親しみを感じる仕様となっている。

これの他に、`console.time()`と`console.timeEnd()`という便利なメソッドも用意されている。
これは`console.time()`のコールと`console.timeEnd()`のコールの間の時間をログとして出力してくれる。

### どんなふうにログ出力されるのか？
次のコードを実行して出力されるログを見てみた。
それぞれのログレベルごとのメソッドはシグネチャが同じなので、使い方は同じだ。
以下に、引数の渡し方による出力の違いを記述する。

#### 置換文字を含むテキスト引数

置換プレースホルダーを含む文字列と、置き換える値を引数に渡す場合。

```javascript
console.log('テキスト引数の %s LEVEL Log: %s', 'DEBUG', 'なにか付加的な情報');
```
上記で出力したログは次の様になる。

![image.png](https://qiita-image-store.s3.amazonaws.com/0/32533/37929f55-15d1-4e2e-1289-6f658d65462c.png)

第１引数の中の置換プレースホルダー`%s`がそれぞれ置換された文字列が、ログの行ラベルに表示され、`textPayload`にも格納されている。
`severity:"DEBUG"`となっている。
なお、置換プレースホルダーは任意なので、単なるテキストを引数として渡せば、当たり前だがそのまま表示される。

#### オブジェクト引数

Javascriptのオブジェクトのみを引数として渡す次のようなコードの場合。

```javascript
console.info({message:'オブジェクト引数の INFO LEVEL Log', data: 'なにか付加的な情報'});
```
上記で出力したログは次の様になる。
![image.png](https://qiita-image-store.s3.amazonaws.com/0/32533/2f1c278d-3a52-fe89-921d-d28e01980f56.png)

引数のオブジェクトの`message`属性がログの行ラベルに表示され、オブジェクト全体が、`jsonPayload`に格納されている。
なお、`console.info()`なので、`severity:"INFO"`となっている。

#### message 属性を持たないオブジェクト

前節とおなじオブジェクトを引数として渡す場合だが、 `message`という属性を含まない場合はどうなるのか？

```javascript
console.warn({msg:'message キーを持たないオブジェクトの WARN LEVEL Log', data: 'なにか付加的な情報'});
```
上のコードで出力したログは次の様になる。
![image.png](https://qiita-image-store.s3.amazonaws.com/0/32533/2f66afe5-1928-5c7b-b532-610d692454d9.png)

この場合、オブジェクト全体がログの行ラベルとして表示される。
しかし、データ的にはオブジェクトが`jsonPayload`に格納されている形となる。
なお、`console.warn()`なので、`severity:"WARNING"`となっている。

#### Objectと置換の組み合わせ
```javascript
console.error({message:'Objectと置換の組み合わせ %s LEVEL Log', data: 'fuga %s'}, 'ERROR',4);
```
上記で出力したログは次の様になる。
![image.png](https://qiita-image-store.s3.amazonaws.com/0/32533/83d65855-8668-6dab-a42d-0547ef526712.png)

どうやら、第2引数以降を指定したときには、第1引数がオブジェクトではなく、文字列として扱われるようだ。
オブジェクトを渡したときのように`jsonPayload`ではなく、`textPayload`に引数が文字列として格納されている。
しかも、置換される位置が、実装した順序を保たない。
ということでこれはエラーにならないだけで、実際には使えない。
なお、`console.error()`なので、`severity:"ERROR"`となっている。

#### 実行時間の計測

`console.time()`と`console.timeEnd()`を利用する。
`console.time()`で計測を開始し、`console.timeEnd()`で計測を終了し、計測時間をログに出力する。対応する`console.time()`と`console.timeEnd()`には同じ文字列を引数に渡す必要があり、不一致の場合にはログは出力されない。

```javascript
var label = 'time tracking';
console.time(label);
console.timeEnd(label);
```
上のコードで出力されるログは次の様になる。
![image.png](https://qiita-image-store.s3.amazonaws.com/0/32533/2f09d61c-3fc7-7545-501e-dfae999402b2.png)

「ラベルの文字列＋計測時間」が `textPayload`に格納されるとともに、ログの行ラベルにも表示される。
`severity`は`DEBUG`となるようだ。
なお、ログが出力されるタイミングは `console.timeEnd()`のタイミングとなる。

## ログの参照
次のような関数を実行した場合のログ出力全体を見ていこう。

```javascript:logging
function logging(){
  var label = 'time tracking';
  console.time(label);

  // 置換文字を含むテキスト引数
  console.log('テキスト引数の %s LEVEL Log: %s', 'DEBUG', 'なにか付加的な情報');
  console.info('テキスト引数の %s LEVEL Log: %s', 'INFO', 'なにか付加的な情報');
  console.warn('テキスト引数の %s LEVEL Log: %s', 'WARN', 'なにか付加的な情報');
  console.error('テキスト引数の %s LEVEL Log: %s', 'ERROR', 'なにか付加的な情報');

  // オブジェクト引数
  console.log({message:'オブジェクト引数の DEBUG LEVEL Log', data: 'なにか付加的な情報'});
  console.info({message:'オブジェクト引数の INFO LEVEL Log', data: 'なにか付加的な情報'});
  console.warn({message:'オブジェクト引数の WARN LEVEL Log', data: 'なにか付加的な情報'});
  console.error({message:'オブジェクト引数の ERROR LEVEL Log', data: 'なにか付加的な情報'});

  // message キーを持たないオブジェクト
  console.log({msg:'message キーを持たないオブジェクトの DEBUG LEVEL Log', data: 'なにか付加的な情報'});
  console.info({msg:'message キーを持たないオブジェクトの INFO LEVEL Log', data: 'なにか付加的な情報'});
  console.warn({msg:'message キーを持たないオブジェクトの WARN LEVEL Log', data: 'なにか付加的な情報'});
  console.error({msg:'message キーを持たないオブジェクトの ERROR LEVEL Log', data: 'なにか付加的な情報'});

  // Objectと置換の組み合わせ
  console.log({message:'Objectと置換の組み合わせの %s LEVEL Log', data: 'fuga %s'}, 'DEBUG', 1);
  console.info({message:'Objectと置換の組み合わせ %s LEVEL Log', data: 'fuga %s'}, 'INFO', 2);
  console.warn({message:'Objectと置換の組み合わせ %s LEVEL Log', data: 'fuga %s'}, 'WARN', 3);
  console.error({message:'Objectと置換の組み合わせ %s LEVEL Log', data: 'fuga %s'}, 'ERROR',4);

  console.timeEnd(label);
}
```

GASのWebエディタのメニューの **表示 > Stackdirver Logging** を選択すると、Stackdriverのログコンソールが開く。

![image.png](https://qiita-image-store.s3.amazonaws.com/0/32533/a0d0f741-ae15-af3a-ece0-2ffa7a79822b.png)

先程のコードの出力は次の様になる。

![image.png](https://qiita-image-store.s3.amazonaws.com/0/32533/50995e39-fe0f-4a8d-e97e-55086dd104e9.png)

ログレベルごとに色違いのアイコンが表示され、わかりやすい。
行頭の `▶` をクリックすると前節で示したような展開した内容が参照できる。

更に、文字列で検索したり、次の様に、GAS内の特定の関数からの出力のみに絞り込むことができるので、求めるログが探しやすい。
![image.png](https://qiita-image-store.s3.amazonaws.com/0/32533/cd10bbbe-1b4e-cab0-ff8d-be147f685d4e.png)

ログレベル、時間によっても絞り込むことができ、便利そうだ。

## まとめ
- GASでも使える便利なログ管理の仕組みが追加された。
- 個人レベルなら無料で使えそう。
- `catch`したエラーオブジェクトをログに出力すればデバッグも捗りそう。

## 参考
- [Logging  \|  Apps Script  \|  Google Developers](https://developers.google.com/apps-script/guides/logging)
- [Class console  \|  Apps Script  \|  Google Developers](https://developers.google.com/apps-script/reference/base/console)
- [料金  \|  Stackdriver ドキュメント  \|  Google Cloud Platform](https://cloud.google.com/stackdriver/pricing#service_tiers)