Ruby の Net::HTTP のタイムアウトにハマって、結局 Timeout について調べることになった件

外部API を実行するために、Net::HTTP で POST してたんだけど、
何故かタイムアウト値を設定しても適用されなかったので調べた時のメモ

下記が当初作ったコードで、ネットワークを接続しない状態で実行したところ、
何故か 20 秒たってやっとタイムアウトの例外 ( Net::OpenTimeout: execution expired ) が発生
open_timeout の 5 秒で例外が発生するんじゃないの？？

サンプル1

def post(url, request_body)
  uri = URI.parse(url)
  response = Net::HTTP.start(uri.host, uri.port, use_ssl: uri.scheme == 'https') {|http|
    http.open_timeout = 5
    http.read_timeout = 125
    http.post(uri.request_uri, request_body)
  }
end

調べたら、start() でこけてるのにその後ろで指定してもだめらしい。
http://moriq.tdiary.net/20080805.html

なるほど確かにと思い、下記のように new して start 前に設定するよう修正してみた

サンプル2

def post(url, request_body)
  uri = URI.parse(url)
  http = Net::HTTP.new(uri.host, uri.port)
  http.use_ssl = uri.scheme == 'https'
  http.open_timeout = 5
  http.read_timeout = 125
  response = http.start do
    http.post(uri.request_uri, request_body)
  end
end

これでやっと実現できるだろう思い、再度実行してみたが…
相変わらず、20 秒たっての例外発生。

これはソース読むしか無いと、net/http の接続する部分 ( 879行目 ) を読んでみた。

ソースの抜粋

net/http.rb

def connect
  # 省略
  # 省略
  # 省略
  s = Timeout.timeout(@open_timeout, Net::OpenTimeout) {
    TCPSocket.open(conn_address, conn_port, @local_host, @local_port)
  }
  # 省略
  # 省略
  # 省略
end

これ見る限り、タイムアウトの処理がちゃんと記載されている…
試しにコンソールで実行してみたところ、何故かタイムアウト値が効かない
なぜッッ！？！？！？！？！？

Timeout.timeout(5, Timeout::Error) {
  puts Time.zone.now.to_s
  s = TCPSocket.open('www.example.com', 80) rescue "#{$!.class.to_s}:#{$!.message}"
  puts Time.zone.now.to_s
  puts s if s.class == String #　エラーメッセージ表示用
  s.close if s.class == TCPSocket # Socket を閉じるため
}
2015-02-12 16:22:16 +0900
2015-02-12 16:22:56 +0900
Timeout::Error:execution expired

sleep で試してみた。

Timeout.timeout(5, Timeout::Error) {
  puts Time.zone.now.to_s
  sleep(10)
  puts Time.zone.now.to_s
} rescue puts "#{Time.zone.now.to_s} #{$!.class.to_s}:#{$!.message}"
2015-02-12 16:25:16 +0900
2015-02-12 16:25:21 +0900 Timeout::Error:execution expired

ちゃんと 5 秒でタイムアウトした
何かのバグなのかと色々調べてみた結果、Timeout の説明に下記のような文言があった

timeout による割り込みは Thread によって実現されています。 C 言語レベルで実装され、 Ruby のスレッドが割り込めない処理に対して timeout は無力です。 そのようなものは実用レベルでは少ないのですが、 Socket などは DNSの名前解決に時間がかかった場合割り込めません (resolv-replace を使用する必要があります)。 その処理を Ruby で実装しなおすか C 側で Ruby のスレッドを意識してあげる必要があります。

今回、ネットワークにつながず試したので、名前解決に時間がかかり、その処理中に timeout が割り込めなかったようだ

以下、実際にネットワークにつなげてみて timeout の動きを試してみた

接続できる場合

Timeout.timeout(5, Timeout::Error) {
  puts Time.zone.now.to_s
  s = TCPSocket.open('www.google.jp', 80) rescue "#{$!.class.to_s}:#{$!.message}"
  puts Time.zone.now.to_s
  puts s if s.class == String #　エラーメッセージ表示用
  s.close if s.class == TCPSocket # Socket を閉じるため
}
2015-02-12 17:15:46 +0900
2015-02-12 17:15:46 +0900

これは特に問題なし

存在しないサブドメインの場合

Timeout.timeout(5, Timeout::Error) {
  puts Time.zone.now.to_s
  s = TCPSocket.open('hogehoge.google.jp', 80) rescue "#{$!.class.to_s}:#{$!.message}"
  puts Time.zone.now.to_s
  puts s if s.class == String #　エラーメッセージ表示用
  s.close if s.class == TCPSocket # Socket を閉じるため
}
2015-02-12 17:14:59 +0900
2015-02-12 17:14:59 +0900
SocketError:getaddrinfo: 名前またはサービスが不明です

ソッコー返ってきた。名前解決がすぐ出来たため ( 出来たと言っても、存在しないドメインだから名前解決が出来ず SocketError が発生 )、即例外が発生している

存在しないドメインでやってみた

Timeout.timeout(5, Timeout::Error) {
  puts Time.zone.now.to_s
  s = TCPSocket.open('www.google.jpp', 80) rescue "#{$!.class.to_s}:#{$!.message}"
  puts Time.zone.now.to_s
  puts s if s.class == String #　エラーメッセージ表示用
  s.close if s.class == TCPSocket # Socket を閉じるため
}
2015-02-12 17:14:34 +0900
2015-02-12 17:14:34 +0900
SocketError:getaddrinfo: 名前またはサービスが不明です

上と同じ理由で、ソッコー返ってきた。

次は、接続できないポートでやってみた

Timeout.timeout(5, Timeout::Error) {
  puts Time.zone.now.to_s
  s = TCPSocket.open('www.google.jp', 500) rescue "#{$!.class.to_s}:#{$!.message}"
  puts Time.zone.now.to_s
  puts s if s.class == String #　エラーメッセージ表示用
  s.close if s.class == TCPSocket # Socket を閉じるため
}
2015-02-12 17:19:58 +0900
2015-02-12 17:20:03 +0900
Timeout::Error:execution expired

timeout がきいた
ただし、TCPSocket.open 実行中 ( 名前解決は成功 ) に 5 秒立って Timeout::Error が割り込んで、その後ろの rescue でを拾ってるみたい
確かに割り込んでる
sleep 使ってそれを試してみた

Timeout.timeout(5, Timeout::Error) {
  puts Time.zone.now.to_s
  s = sleep(20) rescue "#{$!.class.to_s}:#{$!.message}"
  puts Time.zone.now.to_s
  puts s if s.class == String #　エラーメッセージ表示用
}
2015-02-12 17:36:43 +0900
2015-02-12 17:36:48 +0900
Timeout::Error:execution expired

sleep(20) 実行中に Timeout::Error が発生し、ちゃんと rescue できた。

今度は、sleep(20) ではなく、 sleep(2) を挟んでそれぞれで rescue してみる

Timeout.timeout(5, Timeout::Error) {
  puts Time.zone.now.to_s
  s1 = sleep(2) rescue "#{$!.class.to_s}:#{$!.message}"
  s2 = sleep(20)
  s3 = sleep(2) rescue "#{$!.class.to_s}:#{$!.message}"
  puts Time.zone.now.to_s
  puts s if s.class == String #　エラーメッセージ表示用
}
2015-02-12 17:55:43 +0900
Timeout::Error: execution expired
from (pry):211:in `sleep'

rescue できなかった。
timeout の動きとしては、やはり Timeout 内の実行中のメソッドで、Timeout::Error が発生した動きになってるみたい。

結論

net/http の open_timeout は 接続できないポートにアクセスした時や、相手方サーバーの負荷により、connection が張れない時などには有効で、そもそもサーバーが障害等でネットワークがつながってない状態では、DNS の名前解決により、timeout が割り込めず、タイムアウト値を設定しても、その秒数で処理を終了させることが出来ない。

後、 post の処理は、サンプル 2 を採用することにした