Slack SDKの公式ドキュメントのコードをそのまま利用したらサーバー障害で地獄を見た

Overview

みんな大好きSlack、私ももれなく処理結果等の通知で使用しています。
今まで何の不具合もなく使っていたはずなのですが、障害発生によってSlack SDKがやらかしてくれたので残しておきます。（今まで発生していたのを見逃していたのかもしれない）

最初に言っておきますが、絶対にドキュメント読むことなく公式ドキュメントのコードを使用することは避けてください。

Target reader

• Slack SDKを利用していて、Slack SDKのリトライポリシーを理解していない方。

Prerequisite

• Node.jsのバージョンはGoogle Cloud Function(GCF)に依存し、現時点ではV10系とする。
• Node.jsの例ではあるが、各SDKでもWebClientを利用していることから恐らく同様と考えられる。
• Node.jsのソースコードはesmというパッケージを導入し、import/exportで記述している。
• @slack/web-api: "5.8.0"

Body

何が起きたのか？

Slackでサーバートラブルが発生しました。
https://status.slack.com//2020-05/147dad376c8946ff

その結果簡単に終わる処理が9分動作しても完了せずタイムアウトしました。
更にFunctions自体もリトライでフォローするようになっているため、合計20分程度かけましたが処理はタイムアウトで終了しました。
私の場合は1つのインスタンスが20分動いただけですが、これが100とかだとすると結構いたいです。
また、正常終了が大前提だった場合は焦ることになったでしょう。

その時実行していたログが以下です。
間隔をあけながらリトライを繰り返しているようです。
間隔が次第に大きくなっていることから、意図的に作られた再試行だというのが読み取れます。

GCFは1回につき最大10分しか実行できないため、9分でタイムアウトさせています。

CloudFunctions.log

D 2020-05-13T00:01:01.868207720Z myfunction xxxxxxxx Function execution started myfunction xxxxxxxx 
A 2020-05-13T00:01:01.936Z myfunction xxxxxxxx start myfunction. 
A 2020-05-13T00:01:07.279Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
A 2020-05-13T00:01:08.898Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
A 2020-05-13T00:01:12.311Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
A 2020-05-13T00:01:17.444Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
A 2020-05-13T00:01:35.508Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
A 2020-05-13T00:01:56.226Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
A 2020-05-13T00:02:55.448Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
A 2020-05-13T00:04:45.895Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
A 2020-05-13T00:07:47.685Z myfunction xxxxxxxx [WARN]  WebClient:0 http request failed An HTTP protocol error occurred: statusCode = 503 myfunction xxxxxxxx 
D 2020-05-13T00:10:01.933989541Z myfunction xxxxxxxx Function execution took 540067 ms, finished with status: 'timeout' myfunction xxxxxxxx 

ソースコードは以下になります。
Slack関連の処理はほぼ公式ドキュメントそのままです。

utils/slack.js

import { WebClient } from '@slack/web-api';
import { token, conversationId as channel } from '../configs/slack';

const web = new WebClient(token);

const postMessageToChat = async (text) => {
    try {
        // See: https://api.slack.com/methods/chat.postMessage
        const res = await web.chat.postMessage({ channel, text });
        console.log('Message sent: ', res.ts);
    } catch (e) {
        console.error(e);
        // ignore error
        // throw e;
    }
};

export { postMessageToChat };

index.js

const requireEsm = require('esm')(module);
const { postMessageToChat } = requireEsm('./utils/slack');

exports.myfunction = async (data, context, callback) => {
    console.log(`start myfunction`);
    try {
        await postMessageToChat(`Start myfunction`); // ここがエラーの発生元

        // my code

        await postMessageToChat('End myfunction');

        console.log(`end myfunction`);
        callback();
    } catch (e) {
        console.error(e);
        callback(e);
    }
};

本来ならSlackに通知してすんなり終了する処理ですが、タイムアウトしてしまう悲劇に遭遇しました。
Slackがトラブルなら送信できないのはやむなしですが、どうしてweb.chat.postMessage()は終了しなかったのかが問題です。

どうやらリトライポリシーの設定が良くないようだ

issueを出そうと思い、issueをチェックしたりソースをざっと見ていた。
timeoutでは見つからなかったが、retryで検索するとどうもRetryPolicyはあるようだ。
これはpostMessage()でも使えるんじゃないか？と調査したら見えてきた不都合な真実…

自動リトライ
https://slack.dev/node-slack-sdk/web-api#automatic-retries

The WebClient comes with this queuing system out of the box, and its on by default! The client will retry a failed API method call up to 10 times, spaced out over about 30 minutes.

Google翻訳先生曰く

WebClientにはこのキューシステムが標準で付属しており、デフォルトでオンになっています。クライアントは、失敗したAPIメソッド呼び出しを最大10回再試行し、約30分以上間隔を空けます。

最大約30分使ってリトライとかおま

おれも何言っているかよくわからないんだがもう一度言っておく。
web.chat.postMessage()は障害発生時、最大約30分間応答しないということだ。
システムによってはどんどん応答待ちのスレッドが増加してくという怖いことになりかねない
（GCFは同時起動数が最大1000なので、10分間に1000回以上リクエストが来たらあふれそう）
時としておせっかい程始末に負えないものはないというのはこのことか！

ドキュメントを更に読むとオプションでこのリトライポリシーを変更可能とある。

const { WebClient, retryPolicies } = require('@slack/web-api');

const web = new WebClient(token, {
  retryConfig: retryPolicies.fiveRetriesInFiveMinutes,
});

よく見て頭に入れてほしい。
WebClientにリトライポリシーオプションを含んだ第二引数のないプログラムは間違っているといっても過言ではない。
このコードこそが導入部のサンプルコードとしてあるべきコードだと私は考える。
もちろん、場合によってはメッセージの送信が重要な位置づけになっているため、30分にわたりリトライが適している場合もある。
その場合は恐らくエラーの際にフォローするためのコードが入っているはず。

ちなみにSlackとWebClientのキーワードでQiitaの記事をググってみたが、各言語のサンプルあれど一つもリトライポリシーのオプション指定はなかった。
つまり、相当見落としているとみてもいいだろう。私自身も送信だけなので、公式ドキュメントをコピーして使っていただけだ。
公式ドキュメントを読むということはやっぱり大切だと痛感した。

リトライポリシーは以下の種類がある。Slackへの送信が失敗しても問題ないなら迷わずretryPolicies.rapidRetryPolicyだろう。
気に入るものがないなら自分でカスタマイズできそうなので、リンク先を見るといいと思われる。

retryConfig	説明
retryPolicies.tenRetriesInAboutThirtyMinutes	（デフォルト）
retryPolicies.fiveRetriesInFiveMinutes	5分間で5回試行
retryPolicies.rapidRetryPolicy	テストを高速に実行するために使用
{ retries: 0 }	再試行なし（その他のオプション）

ちなみにrapidRetryPolicyは高速というけどどの程度？というのが気になるところ。
これは以下のissueに答えがあって、約10msで10回リトライとあるので、1ms待機後にリトライしていると思われる。
再試行は10回するのに応答速度は再試行なしと比較してもそんなに劣らないと思われる。
https://github.com/slackapi/node-slack-sdk/issues/734

try 10 times in about 10ms

Conclusion

今回もまた改めて公式ドキュメントにしっかり目を通すことの大切さを学んだ。
公式ドキュメントの導入部のサンプルコードが時として牙をむくとか想像できなかった

これからレビューの際に見つけたらびしっと指摘できますね！
「再試行時も想定できないあなたはプロじゃない」

Have a great day!