AWS SDKのリトライを確認する（Node.jsでローカルプロキシを立ててhttpをキャプチャする）

AWS SDKには、エラーが出た時にリトライする仕組みがある。
https://docs.aws.amazon.com/ja_jp/general/latest/gr/api-retries.html

各 AWS SDK は、自動再試行ロジックを実装しています。AWS SDK for Java は自動的にリクエストを再試行します。再試行は、ClientConfiguration クラスを使用して設定できます。たとえば、最小のレイテンシーで再試行なしでリクエストを実行するウェブページでは、再試行ロジックを停止させることがあります。再試行を無効にするには、ClientConfiguration クラスで 0 に値 maxErrorRetry を指定します。

このリトライの挙動を調べるには、レスポンスとして5XXを受け取る必要がある。
けど、AWS SDKを普通に使うとリクエスト先はAWSのサービスであって、AWSのサービスから意図的に5XXを返させることはできないので、リトライを引き起こせない。

ここで、SDKのリクエスト先をAWSじゃなく、5XXを返すエンドポイントにすれば、リトライの挙動を確認できる。
5XXを返すエンドポイントとしては、下記が便利。パスでもホスト名でもステータスコードを指定できる。
http://returnco.de/

例えば500を返してほしければ下記にアクセスする。
http://500.returnco.de

node.jsで確認

node.jsでリトライの挙動を見てみる。

リトライされた回数を見る

何回リトライされたかを見たいだけなら、AWS.config.loggerを使えばOK。
https://docs.aws.amazon.com/ja_jp/sdk-for-javascript/v2/developer-guide/logging-sdk-calls.html

例えば下記のコードを動かす。

var AWS = require('aws-sdk');
AWS.config.logger = console;

// var s3 = new AWS.S3();
var ep = new AWS.Endpoint('http://500.returnco.de');
var s3 = new AWS.S3({endpoint: ep});

var params = {};
s3.listBuckets(params, function(err, data) {
  if (err) console.log(err, err.stack); 
  else     console.log(JSON.stringify(data));
});

下記のようなログが出る。

[AWS s3 500 3.859s 3 retries] listBuckets({})

リトライ回数を変えてみる。リトライ回数の変更方法はドキュメントに記載がある。
https://docs.aws.amazon.com/sdk-for-javascript/v2/developer-guide/global-config-object.html

var ep = new AWS.Endpoint('http://500.returnco.de');
var s3 = new AWS.S3({endpoint: ep, maxRetries: 5});

ログに出てくるリトライ回数も変わっている。

[AWS s3 500 7.229s 5 retries] listBuckets({})

ちなみに、ログのメッセージを構築してるのは、SDKの下記の箇所（buildMessage）と思われる。
https://github.com/aws/aws-sdk-js/blob/master/lib/event_listeners.js#L508

リトライの詳細を確認する

追記:
よりカンタンな方法があった。リトライの詳細を確認するなら下記の方法の方が良いと思う。
https://www.weblog-beta.com/posts/aws-sdk-retry-with-send-event/

リトライ間隔とか、リトライした時の個々のレスポンスの詳細を確認したければ、httpのやりとりをローカルプロキシでキャプチャしてログを出すようにする。
「ローカルプロキシを設定するためのコード」と「AWS SDKでリクエストするコード」の2つを用意して、前者のコードでローカルプロキシを起動した状態で、後者のコードを実行することで、ローカルプロキシがログを記録してくれる。

ローカルプロキシは、Hoxyを使って用意する。
http://greim.github.io/hoxy/

まずHoxyをインストール。

$ npm install hoxy

リトライ間隔を確認する

ミリ秒まで確認するために、momentを入れておく。
http://momentjs.com/docs/#/displaying/format/

$ npm install moment

リトライ間隔を取得するための、ローカルプロキシの設定は下記。
下記のコードを実行すると、ローカルプロキシが8888ポートで起動する。

var hoxy = require('hoxy');
var proxy = hoxy.createServer().listen(8888);

var moment = require("moment");

proxy.intercept({
  phase: 'request'
}, function(req, resp, cycle) {
  console.log( moment().toISOString() );
});

上記のように設定しておくことで、このプロキシ経由でアクセスすると、プロキシにリクエストが到達したタイミングで、現在時刻をミリ秒単位までログ出力する。

次に、AWS SDKを、プロキシ経由でアクセスするように設定する。
https://docs.aws.amazon.com/sdk-for-javascript/v2/developer-guide/node-configuring-proxies.html
まずproxy-agentをインストール。

$ npm install proxy-agent

コードとしては、SDKを使っているコードで下記の行を書き足すだけでOK。

var proxy = require('proxy-agent');
AWS.config.update({
  httpOptions: { agent: proxy('http://localhost:8888') }
});

ローカルプロキシを起動した状態で、ローカルプロキシ経由でリクエストするコードを実行すると、ローカルプロキシが下記のようなログを吐いてくれる。

2018-02-12T05:37:00.666Z
2018-02-12T05:37:01.730Z
2018-02-12T05:37:02.526Z
2018-02-12T05:37:03.461Z
2018-02-12T05:37:04.569Z
2018-02-12T05:37:06.843Z

デフォルトでは、リトライ間隔はエクスポネンシャルバックオフで決まるので、徐々にリトライ間隔が伸びていることがわかる。

試しに、リトライ間隔を等間隔（1秒ごと）にしてみる。方法は下記のドキュメントに記載がある。
https://docs.aws.amazon.com/AWSJavaScriptSDK/latest/AWS/Config.html#retryDelayOptions-property
下記のコードを、AWS SDKでリクエストするコードに追加。

AWS.config.update({retryDelayOptions: {customBackoff: function(retryCount) {
  return 1000;
}}});

結果は下記。

2018-02-12T05:37:28.830Z
2018-02-12T05:37:30.602Z
2018-02-12T05:37:32.301Z
2018-02-12T05:37:34.010Z
2018-02-12T05:37:35.729Z
2018-02-12T05:37:37.468Z

ぴったり1秒間隔にはなっていないけど（遅延等あるので）、間隔がすべて1秒以上で、デフォルトの時のように増加傾向は見られないことがわかる。

コード全文は下記。

var AWS = require('aws-sdk');
AWS.config.logger = console;

var proxy = require('proxy-agent');
AWS.config.update({
  httpOptions: { agent: proxy('http://localhost:8888') }
});

AWS.config.update({retryDelayOptions: {customBackoff: function(retryCount) {
  return 1000;
}}});

var ep = new AWS.Endpoint('http://500.returnco.de');
var s3 = new AWS.S3({endpoint: ep, maxRetries: 5});

var params = {};
s3.listBuckets(params, function(err, data) {
  if (err) console.log(err, err.stack); 
  else     console.log(JSON.stringify(data));
});

リトライした際のそれぞれのレスポンスの詳細を確認する

レスポンスの詳細を見たい場合、ローカルプロキシを下記のように設定する。

var hoxy = require('hoxy');
var proxy = hoxy.createServer().listen(8888);

// https://developer.mozilla.org/ja/docs/Web/JavaScript/Reference/Errors/Cyclic_object_value
var seen = []; 
var replacer = function(key, value) {
  if (value != null && typeof value == "object") {
    if (seen.indexOf(value) >= 0) {
      return;
    }
    seen.push(value);
  }
  return value;
};

proxy.intercept({
  phase: 'response'
}, function(req, resp, cycle) {
  console.log(JSON.stringify(resp, replacer, 2));
});

respの中にレスポンスの情報が入っているので、これを出力すればレスポンスの詳細を見られる。
しかし、respでは循環参照が発生しているので、JSON.stringifyでそのまま文字列化しようとするとエラーが出る。
なので、循環参照をうまく回避するために、下記のページで紹介されているコード（replacer）を入れている。
https://developer.mozilla.org/ja/docs/Web/JavaScript/Reference/Errors/Cyclic_object_value