Bug #9959: TracePoint can invoke inconsistent call event with bmethod

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: -
• ruby -v: 2.2
• Backport: 2.0.0: REQUIRED, 2.1: DONE

[ko1 (Koichi Sasada)]

define_method で定義したメソッド（以降、bmethod）を実行するとき、引数のエラーがあったとき、call イベントのみ発生し、return イベントが発生しない、という問題がありました。

  define_method(:method_test_argument_error_on_bmethod){|correct_key: 1|}

  def test_argument_error_on_bmethod
    events = []
    curr_thread = Thread.current
    TracePoint.new(:call, :return){|tp|
      next if curr_thread != Thread.current
      events << [tp.event, tp.method_id]
    }.enable do
      begin
        method_test_argument_error_on_bmethod(wrong_key: 2)
      rescue => e
        # ignore
      end
    end

    assert_equal [], events # should be empty.
  end

今だと、次のようになります。

TestSetTraceFunc#test_argument_error_on_bmethod [test_settracefunc.rb:1258]:
<[]> expected but was
<[[:call, :method_test_argument_error_on_bmethod]]>.

これは、Proc を実行する前に TracePoint(call) を発生するが、
例外で戻ろうとしたときに、まだ Proc が起動しておらず、フレームに情報がないため、
return イベントが発生しないため、起こります。

これを解決するために、bmethod 用の call/return イベントを発生する場所を調整しました。

Index: vm.c
===================================================================
--- vm.c	(revision 46463)
+++ vm.c	(working copy)
@@ -715,15 +715,17 @@
 		    const rb_block_t *blockptr, const NODE *cref,
 		    VALUE defined_class, int splattable)
 {
-    if (SPECIAL_CONST_P(block->iseq))
+    if (SPECIAL_CONST_P(block->iseq)) {
 	return Qnil;
+    }
     else if (BUILTIN_TYPE(block->iseq) != T_NODE) {
+	VALUE ret;
 	const rb_iseq_t *iseq = block->iseq;
 	const rb_control_frame_t *cfp;
 	int i, opt_pc, arg_size = iseq->arg_size;
-	int type = block_proc_is_lambda(block->proc) ?
-	  VM_FRAME_MAGIC_LAMBDA : VM_FRAME_MAGIC_BLOCK;
-
+	int type = block_proc_is_lambda(block->proc) ? VM_FRAME_MAGIC_LAMBDA : VM_FRAME_MAGIC_BLOCK;
+	const rb_method_entry_t *me = th->passed_bmethod_me;
+	th->passed_bmethod_me = 0;
 	cfp = th->cfp;
 
 	for (i=0; i<argc; i++) {
@@ -733,7 +735,7 @@
 	opt_pc = vm_yield_setup_args(th, iseq, argc, cfp->sp, blockptr,
 				     (type == VM_FRAME_MAGIC_LAMBDA) ? splattable+1 : 0);
 
-	if (th->passed_bmethod_me != 0) {
+	if (me != 0) {
 	    /* bmethod */
 	    vm_push_frame(th, iseq, type | VM_FRAME_FLAG_FINISH | VM_FRAME_FLAG_BMETHOD,
 			  self, defined_class,
@@ -740,8 +742,10 @@
 			  VM_ENVVAL_PREV_EP_PTR(block->ep),
 			  iseq->iseq_encoded + opt_pc,
 			  cfp->sp + arg_size, iseq->local_size - arg_size,
-			  th->passed_bmethod_me, iseq->stack_max);
-	    th->passed_bmethod_me = 0;
+			  me, iseq->stack_max);
+
+	    RUBY_DTRACE_METHOD_ENTRY_HOOK(th, me->klass, me->called_id);
+	    EXEC_EVENT_HOOK(th, RUBY_EVENT_CALL, self, me->called_id, me->klass, Qnil);
 	}
 	else {
 	    vm_push_frame(th, iseq, type | VM_FRAME_FLAG_FINISH,
@@ -756,7 +760,15 @@
 	    th->cfp->ep[-1] = (VALUE)cref;
 	}
 
-	return vm_exec(th);
+	ret = vm_exec(th);
+
+	if (me) {
+	    /* bmethod */
+	    EXEC_EVENT_HOOK(th, RUBY_EVENT_RETURN, self, me->called_id, me->klass, ret);
+	    RUBY_DTRACE_METHOD_RETURN_HOOK(th, me->klass, me->called_id);
+	}
+
+	return ret;
     }
     else {
 	return vm_yield_with_cfunc(th, block, self, argc, argv, blockptr);
Index: vm_insnhelper.c
===================================================================
--- vm_insnhelper.c	(revision 46462)
+++ vm_insnhelper.c	(working copy)
@@ -1615,17 +1615,11 @@
     rb_proc_t *proc;
     VALUE val;
 
-    RUBY_DTRACE_METHOD_ENTRY_HOOK(th, ci->me->klass, ci->me->called_id);
-    EXEC_EVENT_HOOK(th, RUBY_EVENT_CALL, ci->recv, ci->me->called_id, ci->me->klass, Qnil);
-
     /* control block frame */
     th->passed_bmethod_me = ci->me;
     GetProcPtr(ci->me->def->body.proc, proc);
     val = vm_invoke_proc(th, proc, ci->recv, ci->defined_class, ci->argc, argv, ci->blockptr);
 
-    EXEC_EVENT_HOOK(th, RUBY_EVENT_RETURN, ci->recv, ci->me->called_id, ci->me->klass, val);
-    RUBY_DTRACE_METHOD_RETURN_HOOK(th, ci->me->klass, ci->me->called_id);
-
     return val;
 }
 

これも、2.1, 2.0 で再現します。

[ko1 (Koichi Sasada)]

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

Applied in changeset r46464.

---

• vm.c (invoke_block_from_c): move call/return event timing for
  bmethod. It can invoke inconsistent call event if this call raises
  argument error.
  [Bug #9959]
• vm_insnhelper.c (vm_call_bmethod_body): ditto.
• test/ruby/test_settracefunc.rb: add a test.

[nagachika (Tomoyuki Chikanaga)]

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

Backported into ruby_2_1 branch at r47013.

[usa (Usaku NAKAMURA)]

• Status changed from Closed to Assigned

2.0.0にはそもそも th->passed_bmethod_me がなくて、現在のtrunkのelse節に相当する部分がないんですけど、どうしたもんでしょうか？

[naruse (Yui NARUSE)]

• Target version deleted (2.2.0)

[jeremyevans0 (Jeremy Evans)]

• Status changed from Assigned to Closed