RubyのNet::HTTPのリトライについて調べてみた

Railsで他のWebアプリと連携するAPIを開発していてサーバーからの応答が遅い場合に、リクエストが2回送信される現象があったので調べてみました。

Rubyでサーバーにリクエストするだけのテストプログラムを作って試してみます。

環境

ruby 2.3.0
ruby 2.5.1
macOS 10.12.6でruby 2.3.0と2.5.1のふたつの環境で試してみます。

テストプログラム

サーバー側は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

Ruby 2.3.0でテストプログラムを実行

まずタイムアウトしない状態で試してみます。
ruby 2.3.0でtest_http.rbを実行すると、「GET "/hoges.json"」を1回だけ受信しています。

サーバー側のログ出力

コンソール出力

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秒スリープさせてみます。
下記のようにRailsのコントローラでスリープさせて試してみます。

サーバー側の処理

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.5.1でテストプログラムを実行

Ruby 2.5.1でtest_http.rbを実行すると2.3.0と同様にリクエストが２回送られています。

コンソール出力

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)

ruby 2.5.1のNet::HTTP

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

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

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|
  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にして試してみます。

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.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にすると、サーバー側では「GET "/hoges.json"」を１回だけ受信するようになりました。

Net::HTTPのリトライ

RubyのNet::HTTPのデフォルトのリトライ数は1回で、
レスポンスが返ってこない場合は最初のリクエストから1分後にリトライしているようです。
Ruby 2.5からNet::HTTPにmax_retriesが追加されています。
max_retriesを0に設定するとリトライされずリクエストは1回だけ送信されています。

RubyのNet::HTTPのリトライについて気になったので調べてみました。