From: Tanaka Akira Date: 2012-04-22T02:43:45+09:00 Subject: [ruby-dev:45541] drb SSL test timeout Debian wheezy において、test_drbssl.rb のテストで 100秒の timeout にひっかかります。 また、そのとき、プロセスが残ります。 % RUBYLIB=$PWD/lib ./ruby test/runner.rb test/drb/test_drbssl.rb -v -n test_01 Run options: -v -n test_01 # Running tests: TestDRbSSLAry#test_01 = 100.00 s = E TestDRbSSLCore#test_01 = 100.00 s = E Finished tests in 200.010763s, 0.0100 tests/s, 0.0000 assertions/s. 1) Error: test_01(TestDRbSSLAry): DRb::DRbConnError: drbssl://cirrus:51987 - # /home/ruby/tcstate/ruby/lib/drb/drb.rb:736:in `rescue in block in open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:730:in `block in open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:729:in `each' /home/ruby/tcstate/ruby/lib/drb/drb.rb:729:in `open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1191:in `initialize' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1171:in `new' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1171:in `open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1087:in `block in method_missing' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1105:in `with_friend' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1086:in `method_missing' /home/ruby/tcstate/ruby/lib/drb/extservm.rb:40:in `block in service' /home/ruby/tcstate/ruby/lib/monitor.rb:211:in `mon_synchronize' /home/ruby/tcstate/ruby/lib/drb/extservm.rb:37:in `service' /home/ruby/tcstate/ruby/test/drb/drbtest.rb:30:in `block in ext_service' /home/ruby/tcstate/ruby/test/drb/drbtest.rb:29:in `ext_service' /home/ruby/tcstate/ruby/test/drb/test_drbssl.rb:56:in `setup' 2) Error: test_01(TestDRbSSLCore): DRb::DRbConnError: drbssl://localhost:37949 - # /home/ruby/tcstate/ruby/lib/drb/drb.rb:736:in `rescue in block in open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:730:in `block in open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:729:in `each' /home/ruby/tcstate/ruby/lib/drb/drb.rb:729:in `open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1191:in `initialize' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1171:in `new' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1171:in `open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1087:in `block in method_missing' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1105:in `with_friend' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1086:in `method_missing' /home/ruby/tcstate/ruby/lib/drb/extservm.rb:40:in `block in service' /home/ruby/tcstate/ruby/lib/monitor.rb:211:in `mon_synchronize' /home/ruby/tcstate/ruby/lib/drb/extservm.rb:37:in `service' /home/ruby/tcstate/ruby/test/drb/drbtest.rb:30:in `block in ext_service' /home/ruby/tcstate/ruby/test/drb/drbtest.rb:29:in `ext_service' /home/ruby/tcstate/ruby/test/drb/test_drbssl.rb:39:in `setup' 2 tests, 0 assertions, 0 failures, 2 errors, 0 skips ruby -v: ruby 2.0.0dev (2012-04-20 trunk 35411) [x86_64-linux] zsh: exit 2 RUBYLIB=$PWD/lib ./ruby test/runner.rb test/drb/test_drbssl.rb -v -n test_01 このとき、以下のようにプロセスが残ります。 % ps auxww|grep ut_array_drbssl.rb akr 20203 0.0 0.0 4160 584 pts/13 S 02:23 0:00 sh -c /home/ruby/tcstate/ruby/ruby "/home/ruby/tcstate/ruby/test/drb/ut_array_drbssl.rb" druby://localhost:34266 ut_array_drbssl.rb akr 20206 0.0 0.2 51544 9248 pts/13 Sl 02:23 0:00 /home/ruby/tcstate/ruby/ruby /home/ruby/tcstate/ruby/test/drb/ut_array_drbssl.rb druby://localhost:34266 ut_array_drbssl.rb akr 20221 0.0 0.0 7372 888 pts/13 R+ 02:26 0:00 grep ut_array_drbssl.rb 環境は以下のとおりです。 % lsb_release -idrc Distributor ID: Debian Description: Debian GNU/Linux testing (wheezy) Release: testing Codename: wheezy % uname -mrsv Linux 3.2.0-2-amd64 #1 SMP Sun Apr 15 16:47:38 UTC 2012 x86_64 % ldd .ext/x86_64-linux/openssl.so linux-vdso.so.1 => (0x00007fff207ff000) libssl.so.1.0.0 => /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 (0x00007ff481225000) libcrypto.so.1.0.0 => /usr/lib/x86_64-linux-gnu/libcrypto.so.1.0.0 (0x00007ff480e41000) libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007ff480c24000) librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007ff480a1c000) libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007ff480818000) libcrypt.so.1 => /lib/x86_64-linux-gnu/libcrypt.so.1 (0x00007ff4805e0000) libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007ff48035e000) libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007ff47ffd7000) libz.so.1 => /usr/lib/x86_64-linux-gnu/libz.so.1 (0x00007ff47fdc0000) /lib64/ld-linux-x86-64.so.2 (0x00007ff4816f8000) 調べたところ、TCP の accept に成功した後、SSL の accept に失敗しているようです。 とりあえずその状況で TCP のソケットを close すれば、 タイムアウトじゃなくてすみやかに失敗するようにできました。 % svn diff --diff-cmd diff -x '-u -p' Index: lib/drb/ssl.rb =================================================================== --- lib/drb/ssl.rb (revision 35418) +++ lib/drb/ssl.rb (working copy) @@ -177,7 +177,11 @@ module DRb break if (@acl ? @acl.allow_socket?(soc) : true) soc.close end - ssl = @config.accept(soc) + begin + ssl = @config.accept(soc) + ensure + soc.close if $! + end self.class.new(uri, ssl, @config, true) rescue OpenSSL::SSL::SSLError warn("#{__FILE__}:#{__LINE__}: warning: #{$!.message} (#{$!.class})") if @config[:verbose] この状況で TCP のソケットを close することは正しい対処だとと思うのですが、いかがでしょうか。 なお、この変更後は下のように、実際の問題と思われる OpenSSL::SSL::SSLError でテストが失敗するようになります。 % RUBYLIB=$PWD/lib ./ruby test/runner.rb test/drb/test_drbssl.rb -v -n test_01 Run options: -v -n test_01 # Running tests: TestDRbSSLAry#test_01 = 0.06 s = E TestDRbSSLCore#test_01 = 0.07 s = E Finished tests in 0.140017s, 14.2840 tests/s, 0.0000 assertions/s. 1) Error: test_01(TestDRbSSLAry): DRb::DRbConnError: drbssl://cirrus:42554 - # /home/ruby/tcstate/ruby/lib/drb/drb.rb:736:in `rescue in block in open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:730:in `block in open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:729:in `each' /home/ruby/tcstate/ruby/lib/drb/drb.rb:729:in `open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1191:in `initialize' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1171:in `new' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1171:in `open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1087:in `block in method_missing' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1105:in `with_friend' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1086:in `method_missing' /home/ruby/tcstate/ruby/lib/drb/extservm.rb:40:in `block in service' /home/ruby/tcstate/ruby/lib/monitor.rb:211:in `mon_synchronize' /home/ruby/tcstate/ruby/lib/drb/extservm.rb:37:in `service' /home/ruby/tcstate/ruby/test/drb/drbtest.rb:30:in `block in ext_service' /home/ruby/tcstate/ruby/test/drb/drbtest.rb:29:in `ext_service' /home/ruby/tcstate/ruby/test/drb/test_drbssl.rb:56:in `setup' 2) Error: test_01(TestDRbSSLCore): DRb::DRbConnError: drbssl://localhost:48108 - # /home/ruby/tcstate/ruby/lib/drb/drb.rb:736:in `rescue in block in open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:730:in `block in open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:729:in `each' /home/ruby/tcstate/ruby/lib/drb/drb.rb:729:in `open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1191:in `initialize' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1171:in `new' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1171:in `open' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1087:in `block in method_missing' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1105:in `with_friend' /home/ruby/tcstate/ruby/lib/drb/drb.rb:1086:in `method_missing' /home/ruby/tcstate/ruby/lib/drb/extservm.rb:40:in `block in service' /home/ruby/tcstate/ruby/lib/monitor.rb:211:in `mon_synchronize' /home/ruby/tcstate/ruby/lib/drb/extservm.rb:37:in `service' /home/ruby/tcstate/ruby/test/drb/drbtest.rb:30:in `block in ext_service' /home/ruby/tcstate/ruby/test/drb/drbtest.rb:29:in `ext_service' /home/ruby/tcstate/ruby/test/drb/test_drbssl.rb:39:in `setup' 2 tests, 0 assertions, 0 failures, 2 errors, 0 skips ruby -v: ruby 2.0.0dev (2012-04-20 trunk 35411) [x86_64-linux] あとこの変更では、プロセスが残るのはそのままです。 drb が起動したプロセス (あるいは Process.detach が返したスレッド) を覚えていてくれると kill できるような気がするんですが、どうでしょうか。 -- [田中 哲][たなか あきら][Tanaka Akira]