GAS でStackdriver Loggingを使う #GAS

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

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

そう思っていたところに去年の夏頃に追加されたらしい¹ Stackdriver Logging を見つけた。便利そうなので調べてみた。

料金

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

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

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

ログ出力

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

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

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

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

どんなふうにログ出力されるのか？

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

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

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

console.log('テキスト引数の %s LEVEL Log: %s', 'DEBUG', 'なにか付加的な情報');

上記で出力したログは次の様になる。

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

オブジェクト引数

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

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

上記で出力したログは次の様になる。

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

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

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

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

上のコードで出力したログは次の様になる。

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

Objectと置換の組み合わせ

console.error({message:'Objectと置換の組み合わせ %s LEVEL Log', data: 'fuga %s'}, 'ERROR',4);

上記で出力したログは次の様になる。

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

実行時間の計測

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

var label = 'time tracking';
console.time(label);
console.timeEnd(label);

上のコードで出力されるログは次の様になる。

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

ログの参照

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

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のログコンソールが開く。

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

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

更に、文字列で検索したり、次の様に、GAS内の特定の関数からの出力のみに絞り込むことができるので、求めるログが探しやすい。

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

まとめ

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

参考

G Suite Developers Blog: Stackdriver Logging for Google Apps Script is now available ↩