Bug #4387: test_socket_connect_nonblock(TestSocketAddrinfo) がまれに失敗する

• Status: Closed
• Assignee: naruse (Yui NARUSE)
• Target version: 2.0.0
• ruby -v: ruby 1.9.3dev (2011-02-09 trunk 30831) [i386-mswin32_100]

[kosaki (Motohiro KOSAKI)]

=begin
１割ぐらいの確率でtest-allが以下のエラーを吐きます

57. Error:
    test_socket_connect_nonblock(TestSocketAddrinfo):
    Errno::EINVAL: Invalid argument - connect(2)
    C:/ruby/trunk/test/socket/test_addrinfo.rb:163:in connect_nonblock' C:/ruby/trunk/test/socket/test_addrinfo.rb:163:in rescue in test_socket_con
    nect_nonblock'
    C:/ruby/trunk/test/socket/test_addrinfo.rb:158:in `test_socket_connect_nonbl
    ock'

なお、OSレベルでは WSAGetLastError() が WSAEINVALを返しています。

MSDNからそれっぽい部分をいくつかピックアップすると
http://msdn.microsoft.com/en-us/library/ms737625(v=vs.85).aspx

WSAEALREADY: A nonblocking connect call is in progress on the specified socket.
Note In order to preserve backward compatibility, this error is reported as
WSAEINVAL to Windows Sockets 1.1 applications that link to either Winsock.dll or
Wsock32.dll.
WSAEINVAL: The parameter s is a listening socket.

とあるので、
o selectが正しく動いておらず、connect完了する前に処理がもどってしまうので、connectがEINVALを返している
o selectはちゃんと動いているけど、connectがトチ狂ってEISCONNを返さずにEINVALを返している

の２択なんですが、どちらなのかは切り分けできませんでした。誰か良い案があれば教えてください。

これだけではアレなので、いくつか調査報告など

w3cのhttpのサンプルコードだと、EINVALはEISCONNと同等の処理をするようになっています。
http://www.w3.org/Library/src/HTTCP.c

NetBSDのconnectにも昔EINVALを返す問題があったそうですが、どう対処したのかはよく分かりませんでした
http://mail-index.netbsd.org/netbsd-bugs/2003/08/18/0002.html
↑ なんと報告者は Kambeさん

ruby-talkでそれっぽい話をしているログをみつけたのですが、こちらも結論分からず。
http://blade.nagaokaut.ac.jp/cgi-bin/scat.rb/ruby/ruby-talk/16632
=end

[kosaki (Motohiro KOSAKI)]

=begin
不思議なことに以下の２つはほぼ同等の処理をしているにも関わらず、test_connect_nonblockは失敗しません

test_nonblock.rb: test_connect_nonblock()
test_addrinfo.rb: test_socket_connect_nonblock()
=end

[kosaki (Motohiro KOSAKI)]

=begin
WSAConnect()はWSAEALREADYを返すべきタイミングでWSAEINVALを返すことはなさそうだったので、単純にconnectをWSAConnect()に置換してみたのですが、やっぱりWSAEINVALが帰ってきますねぇ。おてあげ

=end

[usa (Usaku NAKAMURA)]

=begin
これも見たことないですねえ。1割も確率があるなら私も踏んでよさそうなんですが。
Winsockの(あるいはOSの)バージョンによってはなんかタイミングバグがあるとかかしら。

ところで、ふと思ったんですけど、ウィルス対策ソフトとか何か入ってますか？
=end

[kosaki (Motohiro KOSAKI)]

=begin
Security Essentialをいったん外して実験してみました。再現率が有為に下がったのですが、まだ100回に一回ぐらい同様の現象が起きます。
確率が変わるのはSecurity Essentialが挙動を変えてるんじゃなく、localhostでのテストだからタイミングがちょっと変わっただけで挙動が変わってしまうというオチではないかと予想しています。
うーむ、Vistaが腐っていると思うべきなのだろうか。
=end

[kosaki (Motohiro KOSAKI)]

• Status changed from Open to Rejected

進展する気がしないので、いったんrejectしますね。

[naruse (Yui NARUSE)]

• Status changed from Rejected to Feedback

[ruby-list:38139] にもスレがありますね。

まとめると、

1. connect_nonblock を呼ぶ
   2.1. ECONNREFUSED が返る (localhost など結果が瞬間的に返る場合)
   2.2.1. EINPROGRESS が返る
   2.2.2. select で待つ→成功か失敗に収束
   2.2.3.1. EISCONN が返る (成功)
   2.2.3.2. EINVAL が返る (失敗)
   って事のようです。
   ここで EINVAL が返るのはFreeBSD や NetBSD もそうです。
   Linux の場合、とりあえず手元で試した「localhost の開いていないポートに接続」というケースでは、
   ECONNABORTED が返ってきました。

さて、ここでの悩みどころは改めて connect_nonblock して EINVAL が返ってきてしまうと、
もはや失敗した理由はわからなくなってしまう事です。
これは、例えば以下のように connect_nonblock の前に getsockopt すれば理由がわかります。
diff --git a/test/socket/test_addrinfo.rb b/test/socket/test_addrinfo.rb
index 3240b9d..1e047c9 100644
--- a/test/socket/test_addrinfo.rb
+++ b/test/socket/test_addrinfo.rb
@@ -159,6 +159,8 @@ class TestSocketAddrinfo < Test::Unit::TestCase
s2.connect_nonblock(ai)
rescue IO::WaitWritable
IO.select(nil, [s2])

•  r = s2.getsockopt(Socket::SOL_SOCKET, Socket::SO_ERROR)
  

•  assert_equal(0, r.int, "NOERROR is expected but #{r.inspect}")
   begin
     s2.connect_nonblock(ai)
   rescue Errno::EISCONN
  

[ko1 (Koichi Sasada)]

• Assignee set to naruse (Yui NARUSE)

誰に押しつけたモノだか迷ったのですが，とりあえず詳しそうななるせさんに振りました．
これ，どうするべきでしょうか．

[naruse (Yui NARUSE)]

• Status changed from Feedback to Closed
• % Done changed from 0 to 100

This issue was solved with changeset r37387.
Motohiro, thank you for reporting this issue.
Your contribution to Ruby is greatly appreciated.
May Ruby be with you.

---

Check if there is no error before reconnect [Bug #4387]