Project

General

Profile

Actions

Bug #4387

closed

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

Added by kosaki (Motohiro KOSAKI) about 13 years ago. Updated over 11 years ago.

Status:
Closed
Target version:
ruby -v:
ruby 1.9.3dev (2011-02-09 trunk 30831) [i386-mswin32_100]
Backport:
[ruby-dev:43181]

Description

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

  1. 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を返している

の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

Actions #1

Updated by kosaki (Motohiro KOSAKI) about 13 years ago

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

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

Actions #2

Updated by kosaki (Motohiro KOSAKI) about 13 years ago

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

=end

Actions #3

Updated by usa (Usaku NAKAMURA) about 13 years ago

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

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

Actions #4

Updated by kosaki (Motohiro KOSAKI) about 13 years ago

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

Updated by kosaki (Motohiro KOSAKI) almost 13 years ago

  • Status changed from Open to Rejected

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

Updated by naruse (Yui NARUSE) almost 12 years ago

  • 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
    

Updated by ko1 (Koichi Sasada) over 11 years ago

  • Assignee set to naruse (Yui NARUSE)

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

Actions #8

Updated by naruse (Yui NARUSE) over 11 years 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]

Actions

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0Like0Like0Like0