【IFTTT】Webhooksのトリガーがめちゃくちゃ遅いんだけど、どうなってるの？常にCheck nowをクリックしないといけないの？

最近、IFTTTでいろいろ遊んでいるのですが、今回は以下の記事でも紹介したように、IFTTTを使ってGoogle Apps Script（以降、GAS）→Webhooks→Twitterを実現していました。

www.pnkts.net

問題点
調査
まとめ

問題点

上の記事は、TwitterのAPI申請がめんどくさいので、代わりにIFTTTを使って指定したURLにPOSTするだけでツイートさせよう！という試みでした。もちろん、ちゃんとツイートはされるのですが、IFTTTで設定したAPIを蹴ってからツイートされるまでの遅延が激しいということ。ほんと、どれだけ待たせるんだ！？ってくらいの遅延です。

調査

ということで、Webhooksをトリガーにするとどのくらい遅延が発生するかを調べてみました！

フロー・構成

調査のために、今回は以下のような環境を作成してみました。

f:id:ponkotsu0605:20191004204811p:plain

フローとしては、以下のような流れになります。

定期的にGASからIFTTTで設定したWebhooksを叩く
IFTTT側ではWebhooksをトリガーとして、GASにリクエストを投げるイベントを発火させる
GAS側でリクエストを受け取り、スプレッドシートにログを残す

1. 定期的にGASからIFTTTで設定したWebhooksを叩く

GASからWebhooks側にリクエストを投げるときに、同時にリクエストを投げるときの時間（タイムスタンプ）をパラメータとして渡しています。

2. IFTTT側ではWebhooksをトリガーとして、GASにリクエストを投げるイベントを発火させる

トリガーをWebhooks、発火するイベントもWebhooksというなかなか使わなそうな組み合わせですね。具体的な設定としては、以下のようなスクリーンショットになります。 f:id:ponkotsu0605:20191004205950p:plain

Receive a web request

Event Name：trigger_test

ここは何でも良い文字列を設定します。

Make a web request

URL：GASで設定したURL Method：POST Body： {"type":"trigger_test","date": "{{Value1}}"}

受け取ったValue1をそのまま返すような設定で、ここでいうValue1はリクエストを投げるときのタイムスタンプを送っています。

3. GAS側でリクエストを受け取り、スプレッドシートにログを残す

受け取ったデータをスプレッドシートに挿入する形でINSERTしていきます。ログ用のテーブルに残す感じですね。そのときに、GASからIFTTTにリクエストをしたときのタイムスタンプがValue1として受け取れるので、そのタイムスタンプと、このリクエストを受け取ったときのタイムスタンプをログに残しておきます。このような残し方をすることで、どの時間に投げたリクエストがいつ発火されたかがわかるようになります。

Let's プログラミング

ということで、GASのソースコードを紹介したいと思います。

リクエストを投げる側

まずは、Webhooksにリクエストを投げる側です。

function checkTriggerTest() {
  var key = '[webhooksのKeyをここに入力]'
  var event = '[イベント名をここに入力]'
  var url = 'https://maker.ifttt.com/trigger/' + event + '/with/key/' + key
  var data = {'value1':new Date()};
  var headers = {
    "Content-Type": "application/json"
  };
  var options = {
    'method' : 'post',
    'headers' : headers,
    'payload' : JSON.stringify(data),
  };
  UrlFetchApp.fetch(url,options); 
}

このスクリプトを定期的に実行してみます。 WebhooksのKeyはIFTTTのWebhooksのページでドキュメントを開くと表示されます。イベント名は、ここでは trigger_test になります。

リクエストを受け取る側

次に、Webhooksからのリクエストを受け取る側です。

function doPost(e) {
  console.log(e.postData.getDataAsString())
  
  var params = JSON.parse(e.postData.getDataAsString());
  var type = params.type

  if (type == '[イベント名をここに入力]') {
    return logTriggerTest(params);
  }
}

function logTriggerTest(params) {
  var data = [params.date, new Date()]
  SpreadsheetApp.openById('[スプレッドシートのIDををここに入力]').getSheetByName('trigger').appendRow(data);
}

ログを残したいスプレッドシートのIDを入力します。

実際に記録されたログ

さて、上のスクリプトを実際に動かしてみましょう。

1回目の発火：1分毎に実行

とりあえず、まずは最小単位の1分ごとに実行をしてみました。 checkTriggerTest() を毎分実行するようなトリガーのタイムスケジュール設定をGAS上で設定します。

すると、一発目の記録発火タイミングが以下のようになりました。とても読みづらくてすみません。

2019-10-02T09:43:58.621Z 2019/10/02 19:33:39
2019-10-02T09:44:58.740Z    2019/10/02 19:33:40
2019-10-02T09:45:58.600Z    2019/10/02 19:33:41
2019-10-02T09:46:58.432Z    2019/10/02 19:33:42
2019-10-02T09:47:58.524Z    2019/10/02 19:33:43
2019-10-02T09:48:58.686Z    2019/10/02 19:33:44
2019-10-02T09:49:58.417Z    2019/10/02 19:33:45
2019-10-02T09:50:58.780Z    2019/10/02 19:33:46
2019-10-02T09:51:58.405Z    2019/10/02 19:33:47
2019-10-02T09:52:58.553Z    2019/10/02 19:33:48
2019-10-02T09:53:58.401Z    2019/10/02 19:33:49
2019-10-02T09:54:58.597Z    2019/10/02 19:33:50
2019-10-02T09:55:58.420Z    2019/10/02 19:33:51
2019-10-02T09:56:58.626Z    2019/10/02 19:33:52
2019-10-02T09:57:58.458Z    2019/10/02 19:33:53
2019-10-02T09:58:58.462Z    2019/10/02 19:34:04
2019-10-02T09:59:58.602Z    2019/10/02 19:34:04
2019-10-02T10:00:58.453Z    2019/10/02 19:34:05
2019-10-02T10:01:58.538Z    2019/10/02 19:34:06
2019-10-02T10:02:58.449Z    2019/10/02 19:34:07
2019-10-02T10:03:58.515Z    2019/10/02 19:34:08
2019-10-02T10:04:58.479Z    2019/10/02 19:34:09
2019-10-02T10:05:58.441Z    2019/10/02 19:34:10
2019-10-02T10:06:58.465Z    2019/10/02 19:34:11
2019-10-02T10:07:58.461Z    2019/10/02 19:34:12
2019-10-02T10:08:58.415Z    2019/10/02 19:34:13
2019-10-02T10:09:58.470Z    2019/10/02 19:34:14
2019-10-02T10:10:58.492Z    2019/10/02 19:34:15
2019-10-02T10:11:58.545Z    2019/10/02 19:34:16
2019-10-02T10:12:58.864Z    2019/10/02 19:34:17
2019-10-02T10:13:58.437Z    2019/10/02 19:34:19
2019-10-02T10:14:58.706Z    2019/10/02 19:34:20
2019-10-02T10:15:58.432Z    2019/10/02 19:34:21
2019-10-02T10:16:58.428Z    2019/10/02 19:34:22
2019-10-02T10:17:58.703Z    2019/10/02 19:34:23
2019-10-02T10:18:58.467Z    2019/10/02 19:34:24
2019-10-02T10:19:58.459Z    2019/10/02 19:34:25
2019-10-02T10:20:58.510Z    2019/10/02 19:34:26
2019-10-02T10:21:58.758Z    2019/10/02 19:34:27
2019-10-02T10:22:58.453Z    2019/10/02 19:34:28
2019-10-02T10:23:58.573Z    2019/10/02 19:34:29
2019-10-02T10:24:58.659Z    2019/10/02 19:34:30
2019-10-02T10:25:58.613Z    2019/10/02 19:34:32
2019-10-02T10:26:58.534Z    2019/10/02 19:34:33
2019-10-02T10:27:58.679Z    2019/10/02 19:34:34
2019-10-02T10:28:58.536Z    2019/10/02 19:34:35
2019-10-02T10:29:58.601Z    2019/10/02 19:34:36
2019-10-02T10:30:58.454Z    2019/10/02 19:34:37
2019-10-02T10:31:58.494Z    2019/10/02 19:34:39
2019-10-02T10:32:58.552Z    2019/10/02 19:34:40

ここからわかったことは、合計50件までがログとして記録されました。すなわち、定期的に50件までが実行されるということですね。

2回目の発火：実行頻度をへらして引き続き監視

さすがに1分ごとじゃ短かったので、30分間隔に頻度を減らしてみました。次の発動タイミングで残ったログは以下になります。また見にくいですね。

2019-10-02T10:33:58.572Z 2019/10/03 1:34:08
2019-10-02T10:34:58.527Z    2019/10/03 1:34:10
2019-10-02T10:35:58.518Z    2019/10/03 1:34:11
2019-10-02T10:36:58.627Z    2019/10/03 1:34:12
2019-10-02T10:37:58.588Z    2019/10/03 1:34:14
2019-10-02T10:38:58.457Z    2019/10/03 1:34:15
2019-10-02T10:39:58.470Z    2019/10/03 1:34:16
2019-10-02T10:40:58.577Z    2019/10/03 1:34:17
2019-10-02T10:41:58.530Z    2019/10/03 1:34:19
2019-10-02T10:42:58.695Z    2019/10/03 1:34:20
2019-10-02T10:43:58.458Z    2019/10/03 1:34:21
2019-10-02T10:44:58.635Z    2019/10/03 1:34:23
2019-10-02T10:45:58.485Z    2019/10/03 1:34:24
2019-10-02T10:46:58.479Z    2019/10/03 1:34:25
2019-10-02T10:47:58.555Z    2019/10/03 1:34:27
2019-10-02T10:48:58.475Z    2019/10/03 1:34:28

1回目の実行時間が 2019/10/02 19:34:40 に対して、2回目の実行開始時間が 2019/10/03 1:34:08 とほぼ6時間後という結果になりました。また、左の列を比較してみると、前回のログの続きから実行されているのがわかります。すなわち、50件しか実行はしなかったけど、欠損はないということですね。今回は16件が記録されています。

3回目の発火：引き続き監視

引き続き待機します。と言っても、勝手に動いて勝手にスプシに記録されていくので、寝て起きたら終わっているんだけどね。

2019-10-03T12:27:58.547Z 2019/10/04 7:33:37
2019-10-03T12:57:58.724Z    2019/10/04 7:33:38
2019-10-03T13:27:58.514Z    2019/10/04 7:33:39
2019-10-03T13:57:58.778Z    2019/10/04 7:33:40
2019-10-03T14:27:58.490Z    2019/10/04 7:33:41
2019-10-03T14:57:58.429Z    2019/10/04 7:33:42
2019-10-03T15:27:58.507Z    2019/10/04 7:33:43
2019-10-03T15:57:58.509Z    2019/10/04 7:33:44
2019-10-03T16:27:58.608Z    2019/10/04 7:33:44
2019-10-03T16:57:58.547Z    2019/10/04 7:33:45
2019-10-03T17:27:58.629Z    2019/10/04 7:33:46
2019-10-03T17:57:58.544Z    2019/10/04 7:33:47
2019-10-03T18:27:58.527Z    2019/10/04 7:33:48
2019-10-03T18:57:58.414Z    2019/10/04 7:33:49
2019-10-03T19:28:00.938Z    2019/10/04 7:33:49
2019-10-03T19:57:58.422Z    2019/10/04 7:33:50
2019-10-03T20:27:58.466Z    2019/10/04 7:33:51
2019-10-03T20:57:58.511Z    2019/10/04 7:33:52
2019-10-03T21:27:58.466Z    2019/10/04 7:33:53
2019-10-03T21:57:58.433Z    2019/10/04 7:33:54
2019-10-03T22:27:58.537Z    2019/10/04 7:33:55

また6時間後に発火されました。そして、21件が実行されました。

4回目：何も考えずに流れで実行

もうちょい様子を見てみました。

2019-10-03T22:57:58.504Z 2019/10/04 13:37:15
2019-10-03T23:27:58.409Z    2019/10/04 13:37:16
2019-10-03T23:57:58.521Z    2019/10/04 13:37:17
2019-10-04T00:27:58.705Z    2019/10/04 13:37:18
2019-10-04T00:57:58.641Z    2019/10/04 13:37:19
2019-10-04T01:27:58.542Z    2019/10/04 13:37:20
2019-10-04T01:57:58.509Z    2019/10/04 13:37:21
2019-10-04T02:27:58.467Z    2019/10/04 13:37:22
2019-10-04T02:57:58.502Z    2019/10/04 13:37:23

同じく6時間後に実行されましたね。

考察

上記の実験結果より、以下のようなことが考えられます。

6時間毎にWebhooksのチェックが走るみたい
6時間の間に投げられた全てのリクエストを捌くわけではなく、キューに追加されていくイメージっぽい
そのキューのサイズ、実行される数は時間によって変わるっぽい

まとめ

タイトルにも書いてありますが、結局Webhooksをトリガーとしたときの実行が遅れる件、どのくらい遅れるかの問題の結果は、最大6時間遅れる、かなと。なので、上でも紹介した、WebhooksをトリガーとしてTwitterでツイートするスクリプトも最大6時間の遅延が発生してしまうことがわかりますね。