Bug #4387

test_socket_connect_nonblock(TestSocketAddrinfo) がまれに失敗する

Added by Motohiro KOSAKI about 3 years ago. Updated over 1 year ago.

[ruby-dev:43181]
Status:Closed
Priority:Normal
Assignee:Yui NARUSE
Category:core
Target version:2.0.0
ruby -v:ruby 1.9.3dev (2011-02-09 trunk 30831) [i386-mswin32_100] Backport:

Description

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

57) Error:
testsocketconnectnonblock(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 testsocketcon
nectnonblock'
C:/ruby/trunk/test/socket/test
addrinfo.rb:158:in `testsocketconnect_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を返している

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

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

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

Associated revisions

Revision 37387
Added by Yui NARUSE over 1 year ago

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

History

#1 Updated by Motohiro KOSAKI about 3 years ago

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

testnonblock.rb: testconnectnonblock()
test
addrinfo.rb: testsocketconnect_nonblock()
=end

#2 Updated by Motohiro KOSAKI about 3 years ago

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

=end

#3 Updated by Usaku NAKAMURA about 3 years ago

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

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

#4 Updated by Motohiro KOSAKI about 3 years ago

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

#5 Updated by Motohiro KOSAKI almost 3 years ago

  • Status changed from Open to Rejected

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

#6 Updated by Yui NARUSE almost 2 years ago

  • Status changed from Rejected to Feedback

にもスレがありますね。

まとめると、
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 が返ってきました。

さて、ここでの悩みどころは改めて connectnonblock して EINVAL が返ってきてしまうと、
もはや失敗した理由はわからなくなってしまう事です。
これは、例えば以下のように connect
nonblock の前に getsockopt すれば理由がわかります。
diff --git a/test/socket/testaddrinfo.rb b/test/socket/testaddrinfo.rb
index 3240b9d..1e047c9 100644
--- a/test/socket/testaddrinfo.rb
+++ b/test/socket/test
addrinfo.rb
@@ -159,6 +159,8 @@ class TestSocketAddrinfo < Test::Unit::TestCase
s2.connectnonblock(ai)
rescue IO::WaitWritable
IO.select(nil, [s2])
+ r = s2.getsockopt(Socket::SOL
SOCKET, Socket::SOERROR)
+ assert
equal(0, r.int, "NOERROR is expected but #{r.inspect}")
begin
s2.connect_nonblock(ai)
rescue Errno::EISCONN

#7 Updated by Koichi Sasada over 1 year ago

  • Assignee set to Yui NARUSE

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

#8 Updated by Yui NARUSE over 1 year ago

  • 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]

Also available in: Atom PDF