[ruby-dev:45541] drb SSL test timeout
From:
Tanaka Akira <akr@...>
Date:
2012-04-21 17:43:45 UTC
List:
ruby-dev #45541
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 - #<RuntimeError: execution expired>
/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 - #<RuntimeError:
execution expired>
/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 - #<OpenSSL::SSL::SSLError:
SSL_connect SYSCALL returned=5 errno=0 state=unknown state>
/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 -
#<OpenSSL::SSL::SSLError: SSL_connect SYSCALL returned=5 errno=0
state=unknown state>
/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]