Project

General

Profile

Actions

Bug #9820

closed

miniruby -e 'Process.kill(:INT, $$)' hang under cron

Bug #9820: miniruby -e 'Process.kill(:INT, $$)' hang under cron

Added by akr (Akira Tanaka) over 11 years ago. Updated about 11 years ago.

Status:
Closed
Assignee:
-
Target version:
-
ruby -v:
ruby 2.2.0dev (2014-05-09 trunk 45884) [x86_64-linux]
[ruby-dev:48203]

Description

最近、しばたさんが運用を始めた chkbuild で、
TestBeginEndBlock#test_propagate_signaled が hang しています。
http://chkbuild002.hsbt.org/chkbuild/ruby-trunk/log/20140509T060013Z.fail.html.gz

調べて再現コードを小さくしていった結果、

miniruby -e 'Process.kill(:INT, $$)'

というのを cron から動かしたときは hang し、
端末から動かしたときは hang しない、ということが判明しました。

strace した結果をみると、
cron 下では timer thread が prctl の直後に poll を呼び出してそれが終わらないという挙動なのに対し、
端末ではそのあたりで context switch が起きている、ような気がします。

strace の結果を strace.cron.log と strace.term.log として添付します。

なにかわかるひとはいますでしょうか?

% ./miniruby -v ruby 2.2.0dev (2014-05-09 trunk 45884) [x86_64-linux] % uname -mrsv Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 % lsb_release -idrc Distributor ID:	Debian Description:	Debian GNU/Linux 7.5 (wheezy) Release:	7.5 Codename:	wheezy 

なお、コミッタならしばたさんに頼むとそのマシンにアカウントを作ってくれる模様です。


Files

strace.cron.log (15.8 KB) strace.cron.log cron下で動かしたときのstraceのログ akr (Akira Tanaka), 05/09/2014 08:04 AM
strace.term.log (17.6 KB) strace.term.log 端末で動かしたときのstraceのログ akr (Akira Tanaka), 05/09/2014 08:04 AM

Updated by akr (Akira Tanaka) over 11 years ago Actions #1 [ruby-dev:48206]

さらに調べた結果、どうも cron から動かしたプログラムでは SIGINT の signal handler が
SIG_IGN になっているようです。

以下のようにして、端末からでも再現できました。
以下を実行すると hang します。

./miniruby -e 'trap(:INT, "IGNORE"); Process.kill(:INT, $$)' 

Ctrl-C で止められないのは少し面倒なので、SIGQUIT に変えて以下のようにしても同様です。

./miniruby -e 'trap(:QUIT, "IGNORE"); Process.kill(:QUIT, $$)' 

シグナルを無視する設定なのに、hang するのはバグだと考えられます。
workaround としては trap(:INT, "DEFAULT") すればいいわけですが、バグは直したほうがいいと思います。

なお、いつからそうなったか調べたところ、Ruby 2.1.0 からな感じです。
Ruby 2.0.0p481 では hang せず、すぐに終わります。
でも rubyci.org では 2.0.0 も hang しているじゃないかと思ってよく見直してみると、
2.0.0 で hang しているのは TestBeginEndBlock#test_propagate_signaled じゃなくて
TestIO_Console#test_noctty で、そっちはまた違う原因のようです。

Updated by nobu (Nobuyoshi Nakada) over 11 years ago Actions #2 [ruby-dev:48207]

r39819で、自分自身にシグナルを送ったときにはすぐシグナルを処理するために受信するまで待つようになっていますが、SIG_IGNの場合は送られないのでそこでずっと待機してしまうということのようです。
シグナルの遅延が予測できない以上、killする前にチェックするしかないですかねぇ。

Updated by nobu (Nobuyoshi Nakada) over 11 years ago Actions #3 [ruby-dev:48208]

元々シグナルがすぐ配送されるとは限らないわけで、とりあえずタイムアウトをつけてみるのはどうでしょうか。

diff --git i/thread.c w/thread.c index dfa91a8..209aff1 100644 --- i/thread.c +++ w/thread.c @@ -5180,10 +5180,11 @@ ruby_kill(rb_pid_t pid, int sig) * delivered immediately and synchronously. */ if ((sig != 0) && (th == vm->main_thread) && (pid == getpid())) { +	static const struct timespec limit = {0, 1000*1000}; /* 1ms */ 	GVL_UNLOCK_BEGIN();	native_mutex_lock(&th->interrupt_lock);	err = kill(pid, sig); -	native_cond_wait(&th->interrupt_cond, &th->interrupt_lock); +	native_cond_timedwait(&th->interrupt_cond, &th->interrupt_lock, &limit); 	native_mutex_unlock(&th->interrupt_lock);	GVL_UNLOCK_END(); } 

Updated by akr (Akira Tanaka) over 11 years ago Actions #4 [ruby-dev:48209]

自分自身に送るときは、即座に届かないと困ることがあった気がします。
例外が発生するはずがその先まで実行されてしまうとか。

思うに、自分自身(だけ)に送るときは signal を使わないで、直接 signal handler を呼ぶなり呼ばないなりすればいいんじゃないかという気がするんですが、どうですかねぇ。

Updated by nobu (Nobuyoshi Nakada) over 11 years ago Actions #5 [ruby-dev:48210]

SIG_IGNではないときだけ、というところでrace conditionになったりしないですかね。

Updated by akr (Akira Tanaka) over 11 years ago Actions #6 [ruby-dev:48211]

GVL があるので変なことはまず起こらない気がしますが、起こるとしたらどういう状況ですかね。

Updated by nobu (Nobuyoshi Nakada) over 11 years ago Actions #7 [ruby-dev:48215]

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

Applied in changeset r45911.


signal.c: directly enqueue

  • signal.c (rb_f_kill): directly enqueue an ignored signal to self,
    except for SIGSEGV and SIGBUS. [ruby-dev:48203] [Bug #9820]

Updated by usa (Usaku NAKAMURA) over 11 years ago Actions #8 [ruby-dev:48365]

  • Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN to 2.0.0: DONTNEED, 2.1: REQUIRED

Updated by nagachika (Tomoyuki Chikanaga) about 11 years ago Actions #9 [ruby-dev:48509]

  • Backport changed from 2.0.0: DONTNEED, 2.1: REQUIRED to 2.0.0: DONTNEED, 2.1: DONE

r45911, r45912, r45917, r45918 and r45919 were backported into ruby_2_1 branch at r47345.

Updated by ktsj (Kazuki Tsujimoto) about 11 years ago Actions #10 [ruby-dev:48592]

r45911から以下のコードを実行してもkill(2)が呼ばれないようになっています。
これは意図された変更でしょうか。

$ ruby -e 'Process.kill(:TRAP, $$)' 

これまでの挙動に戻すべきだと主張するほどのものではないですが

これでシグナルが飛ばせるとデバッグの際に便利です。

Updated by akr (Akira Tanaka) about 11 years ago Actions #11 [ruby-dev:48594]

Ruby 自身が signal handler を設定していたとき以外は実際に kill(2) したほうがよさそうですね。

Updated by nagachika (Tomoyuki Chikanaga) about 11 years ago Actions #12 [ruby-dev:48600]

  • Backport changed from 2.0.0: DONTNEED, 2.1: DONE to 2.0.0: DONTNEED, 2.1: REQUIRED

Updated by ktsj (Kazuki Tsujimoto) about 11 years ago Actions #13 [ruby-dev:48606]

> なかださん
修正ありがとうございます。

ただ、gdbでProcess.kill(:TRAP, $$)によるシグナルを受けた後にcontinueすると
ruby_kill内のnative_cond_waitで待機したままになります。

Rubyでsignal handlerを設定していない場合にはruby_killではなくkillを呼び出すようにすればよさそうですが、
何か問題あるでしょうか。

diff --git a/signal.c b/signal.c index 171f5ac..7a83dbc 100644 --- a/signal.c +++ b/signal.c @@ -487,7 +487,11 @@ rb_f_kill(int argc, const VALUE *argv) default: t = signal_ignored(sig); if (t) { -	if (t < 0) ruby_kill(pid, sig); +	if (t < 0) { + if (kill(pid, sig) < 0) { +	rb_sys_fail(0); + } +	} 	break; } signal_enque(sig); 

Updated by nagachika (Tomoyuki Chikanaga) about 11 years ago Actions #14 [ruby-dev:48643]

  • Backport changed from 2.0.0: DONTNEED, 2.1: REQUIRED to 2.0.0: DONTNEED, 2.1: DONE

r47818 and r47832 were backported into ruby_2_1 branch at r47956.

Actions

Also available in: PDF Atom