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

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: ruby 2.2.0dev (2014-05-09 trunk 45884) [x86_64-linux]
• Backport: 2.0.0: DONTNEED, 2.1: DONE

[akr (Akira Tanaka)]

最近、しばたさんが運用を始めた 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

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

[akr (Akira Tanaka)]

さらに調べた結果、どうも 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 で、そっちはまた違う原因のようです。

[nobu (Nobuyoshi Nakada)]

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

[nobu (Nobuyoshi Nakada)]

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

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();
     }

[akr (Akira Tanaka)]

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

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

[nobu (Nobuyoshi Nakada)]

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

[akr (Akira Tanaka)]

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

[nobu (Nobuyoshi Nakada)]

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

[usa (Usaku NAKAMURA)]

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

[nagachika (Tomoyuki Chikanaga)]

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

[ktsj (Kazuki Tsujimoto)]

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

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

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

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

[akr (Akira Tanaka)]

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

[nagachika (Tomoyuki Chikanaga)]

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

[ktsj (Kazuki Tsujimoto)]

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

ただ、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);

[nagachika (Tomoyuki Chikanaga)]

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