Bug #9820

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

Added by Akira Tanaka 11 months ago. Updated 5 months ago.

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

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

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

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

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

Associated revisions

Revision 45911
Added by Nobuyoshi Nakada 11 months ago

signal.c: directly enqueue

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

Revision 45911
Added by Nobuyoshi Nakada 11 months ago

signal.c: directly enqueue

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

Revision 45912
Added by Nobuyoshi Nakada 11 months ago

thread.c: always deliver signal immediately

  • thread.c (ruby_kill): always deliver signal immediately, without check for main thread. no longer called in other context. [Bug #9820]

Revision 45912
Added by Nobuyoshi Nakada 11 months ago

thread.c: always deliver signal immediately

  • thread.c (ruby_kill): always deliver signal immediately, without check for main thread. no longer called in other context. [Bug #9820]

Revision 45918
Added by Nobuyoshi Nakada 11 months ago

test_process.rb: WIFEXITED and so on are system dependent

  • test/ruby/test_process.rb (test_status_kill): WIFEXITED and so on are available only if signal is supported by the system. [Bug #9820]

Revision 45918
Added by Nobuyoshi Nakada 11 months ago

test_process.rb: WIFEXITED and so on are system dependent

  • test/ruby/test_process.rb (test_status_kill): WIFEXITED and so on are available only if signal is supported by the system. [Bug #9820]

Revision 47345
Added by Tomoyuki Chikanaga 7 months ago

merge revision(s) r45911,r45912,r45917,r45918,r45919: [Backport #9820]

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

Revision 47818
Added by Nobuyoshi Nakada 6 months ago

signal.c: send signal unless handled

  • signal.c (rb_f_kill): should not ignore signal unless the default handler is registered. [Bug #9820]

Revision 47818
Added by Nobuyoshi Nakada 6 months ago

signal.c: send signal unless handled

  • signal.c (rb_f_kill): should not ignore signal unless the default handler is registered. [Bug #9820]

Revision 47832
Added by Nobuyoshi Nakada 6 months ago

signal.c: get rid of deadlock by discarded signals

  • signal.c (rb_f_kill): get rid of deadlock as unhandled and discarded signals do not make interrupt_cond signaled. based on the patch by Kazuki Tsujimoto at . [Bug #9820]

Revision 47832
Added by Nobuyoshi Nakada 6 months ago

signal.c: get rid of deadlock by discarded signals

  • signal.c (rb_f_kill): get rid of deadlock as unhandled and discarded signals do not make interrupt_cond signaled. based on the patch by Kazuki Tsujimoto at . [Bug #9820]

Revision 47956
Added by Tomoyuki Chikanaga 5 months ago

merge revision(s) r47818,r47832: [Backport #9820]

* signal.c (rb_f_kill): should not ignore signal unless the
  default handler is registered.   [Bug #9820]

* signal.c (rb_f_kill): get rid of deadlock as unhandled and
  discarded signals do not make interrupt_cond signaled.
  based on the patch by Kazuki Tsujimoto at .
  [Bug #9820]

History

#1 Updated by Akira Tanaka 11 months ago

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

#2 Updated by Nobuyoshi Nakada 11 months ago

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

#3 Updated by Nobuyoshi Nakada 11 months ago

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

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

#4 Updated by Akira Tanaka 11 months ago

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

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

#5 Updated by Nobuyoshi Nakada 11 months ago

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

#6 Updated by Akira Tanaka 11 months ago

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

#7 Updated by Nobuyoshi Nakada 11 months ago

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

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]

#8 Updated by Usaku NAKAMURA 9 months ago

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

#9 Updated by Tomoyuki Chikanaga 7 months ago

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

#10 Updated by Kazuki Tsujimoto 6 months ago

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

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

# これまでの挙動に戻すべきだと主張するほどのものではないですが
# これでシグナルが飛ばせるとデバッグの際に便利です。

#11 Updated by Akira Tanaka 6 months ago

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

#12 Updated by Tomoyuki Chikanaga 6 months ago

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

#13 Updated by Kazuki Tsujimoto 6 months ago

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

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

#14 Updated by Tomoyuki Chikanaga 5 months ago

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

Also available in: Atom PDF