rubyでサーバーと連携するAPIを開発していてサーバーからの応答が遅い場合に、
リクエストが２回送信される現象があったのでNet::HTTPのリトライについて気になったので調べてみました。

サーバー側はRailsで作成しクライアント側は
下記のようにget methodでリクエストを送信するテストプログラムで確認します。

test_http.rb

require 'net/http'

uri = URI.parse("http://localhost:3000/hoges.json")
req = Net::HTTP::Get.new(uri.path)
res = Net::HTTP.start(uri.host, uri.port) do |http|
  http.request(req)
end

これを実行すると下記のようにサーバーに１回だけGETでリクエストしています。

サーバー側のログ出力

Started GET "/hoges.json" for 127.0.0.1 at 2018-06-06 02:02:20 +0900
  ActiveRecord::SchemaMigration Load (0.3ms)  SELECT "schema_migrations".* FROM "schema_migrations"
Processing by HogesController#index as JSON
  Rendering hoges/index.json.jbuilder
  Hoge Load (0.2ms)  SELECT "hoges".* FROM "hoges"
  Rendered hoges/_hoge.json.jbuilder (1.8ms)
  Rendered hoges/_hoge.json.jbuilder (1.6ms)
  Rendered hoges/index.json.jbuilder (38.2ms)
Completed 200 OK in 96ms (Views: 71.0ms | ActiveRecord: 1.7ms)

サーバー側の応答を遅くしてみる

サーバー側ですぐに応答が返らないように90秒スリープさせてみます。

サーバー側の処理

def index
  @hoges = Hoge.all
  p "sleep start #{DateTime.now}"
  sleep(90)
  p "sleep end #{DateTime.now}"
end

リクエストがリトライされる

この状態でtest_http.rbを実行すると「GET "/hoges.json"」が２回リクエストきています。

Started GET "/hoges.json" for 127.0.0.1 at 2018-06-06 02:17:32 +0900
Processing by HogesController#index as JSON
"sleep start 2018-06-06T02:17:32+09:00"
Started GET "/hoges.json" for 127.0.0.1 at 2018-06-06 02:18:32 +0900
Processing by HogesController#index as JSON
"sleep start 2018-06-06T02:18:32+09:00"
"sleep end 2018-06-06T02:19:02+09:00"
  Rendering hoges/index.json.jbuilder
  Hoge Load (0.2ms)  SELECT "hoges".* FROM "hoges"
  Rendered hoges/_hoge.json.jbuilder (1.0ms)
  Rendered hoges/_hoge.json.jbuilder (0.5ms)
  Rendered hoges/index.json.jbuilder (6.6ms)
Completed 200 OK in 90028ms (Views: 19.7ms | ActiveRecord: 0.2ms)


"sleep end 2018-06-06T02:20:02+09:00"
  Rendering hoges/index.json.jbuilder
  Hoge Load (0.2ms)  SELECT "hoges".* FROM "hoges"
  Rendered hoges/_hoge.json.jbuilder (0.6ms)
  Rendered hoges/_hoge.json.jbuilder (0.4ms)
  Rendered hoges/index.json.jbuilder (5.2ms)
Completed 200 OK in 90027ms (Views: 19.2ms | ActiveRecord: 0.2ms)

Net::HTTP.startでリトライしているようです。

このときのrubyのバージョンは2.3.0

$ ruby -v
ruby 2.3.0p0 (2015-12-25 revision 53290) [x86_64-darwin15]

ruby 2.5.1のNet::HTTP

ruby 2.5.1のNet::HTTPにはmax_retriesが追加されています。
このへんの動きを確認してみます。

rbenvでruby 2.5.1に変更

$ rbenv local 2.5.1
$ ruby -v
ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-darwin16]

この状態でtest_http.rbを実行してみます。
ruby 2.5.1でもリクエストが２回あります。

Started GET "/hoges.json" for 127.0.0.1 at 2018-06-06 02:26:41 +0900
Processing by HogesController#index as JSON
"sleep start 2018-06-06T02:26:41+09:00"
Started GET "/hoges.json" for 127.0.0.1 at 2018-06-06 02:27:41 +0900
Processing by HogesController#index as JSON
"sleep start 2018-06-06T02:27:41+09:00"
"sleep end 2018-06-06T02:28:11+09:00"
  Rendering hoges/index.json.jbuilder
  Hoge Load (1.6ms)  SELECT "hoges".* FROM "hoges"
  Rendered hoges/_hoge.json.jbuilder (2.6ms)
  Rendered hoges/_hoge.json.jbuilder (0.6ms)
  Rendered hoges/index.json.jbuilder (15.9ms)
Completed 200 OK in 90047ms (Views: 33.1ms | ActiveRecord: 1.6ms)


"sleep end 2018-06-06T02:29:11+09:00"
  Rendering hoges/index.json.jbuilder
  Hoge Load (1.9ms)  SELECT "hoges".* FROM "hoges"
  Rendered hoges/_hoge.json.jbuilder (17.5ms)
  Rendered hoges/_hoge.json.jbuilder (1.3ms)
  Rendered hoges/index.json.jbuilder (81.6ms)
Completed 200 OK in 90152ms (Views: 121.6ms | ActiveRecord: 1.9ms)

test_http.rb

test_http.rbを修正し、max_retriesの値を確認してみます。

require 'net/http'

uri = URI.parse("http://localhost:3000/hoges.json")
req = Net::HTTP::Get.new(uri.path)
res = Net::HTTP.start(uri.host, uri.port) do |http|
  p "http.max_retries : #{http.max_retries}"
  http.request(req)
end

実行結果

$ ruby test_http.rb
"http.max_retries : 1"

max_retriesは1になっています。

max_retriesを0にして実行してみます。

require 'net/http'

uri = URI.parse("http://localhost:3000/hoges.json")
req = Net::HTTP::Get.new(uri.path)
res = Net::HTTP.start(uri.host, uri.port) do |http|
  http.max_retries = 0
  p "http.max_retries : #{http.max_retries}"
  http.request(req)
end

実行結果

Started GET "/hoges.json" for 127.0.0.1 at 2018-06-06 02:39:40 +0900
Processing by HogesController#index as JSON
"sleep start 2018-06-06T02:39:40+09:00"
"sleep end 2018-06-06T02:41:10+09:00"
  Rendering hoges/index.json.jbuilder
  Hoge Load (0.3ms)  SELECT "hoges".* FROM "hoges"
  Rendered hoges/_hoge.json.jbuilder (6.4ms)
  Rendered hoges/_hoge.json.jbuilder (7.8ms)
  Rendered hoges/index.json.jbuilder (24.4ms)
Completed 200 OK in 90055ms (Views: 43.5ms | ActiveRecord: 0.3ms)

max_retriesを0にするとリクエストは１回だけになりました。

---