ruby - Ruby Net::OpenTimeout 调用“puts”，奇怪的堆栈跟踪。多线程应用

Question

我的 Ruby 应用程序有以下 2 个堆栈跟踪。

第一个堆栈跟踪显示了在我的 http.rb 文件的第 161 行抛出的异常。在第 161 行，有一个puts()调用，正如您在异常下方的代码片段中看到的那样。堆栈跟踪还显示了对write()的调用，我认为这是一个低级 C 调用。第二个堆栈跟踪也用于puts()但在应用程序的不同部分。这一行实际上只是临时调试信息。在这里您可以看到我们正在使用 Monitor 来同步一些日志记录，因为它是一个多线程应用程序。

然而，例外是 Net::OpenTimeout 例外。我在其他地方确实有执行网络连接的代码，并且在其他地方有一个异常处理程序来捕获它们。

对“puts”的调用如何导致 Net::Timeout 异常？

文件描述符会发生什么有趣的事情吗？

Net::OpenTimeout , "执行过期", "[\"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/http.rb:161:in ' write '\", \"/Users/tomburnell/github /lemonitor/lib/monitoring/checks/http.rb:161:in ' puts'\", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/http.rb:161:in 'puts'\", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks /http.rb:161:in 'logResult'\", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/generic.rb:65:in 'rescue in call_check'\", \"/Users /tomburnell/github/lemonitor/lib/monitoring/checks/generic.rb:63:in 'call_check'\", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/generic.rb:46:in '按计划阻止'\", \"/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:218:in 'do_call'\", \"/用户/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:262:in 'trigger_now'\", \"/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:307:in 'block (3 levels) in start_work_thread'\", \"/Users/tomburnell/ .gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:310:in 'block (2 levels) in start_work_thread'\", \"/Users/tomburnell/.gem/gems/ rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:296:in 'loop'\", \"/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus /scheduler/jobs.rb:296:in 'block in start_work_thread'\"]",/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:296:in 'loop'\", \"/Users/tomburnell/.gem/gems/rufus -scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:296:in 'block in start_work_thread'\"]",/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:296:in 'loop'\", \"/Users/tomburnell/.gem/gems/rufus -scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:296:in 'block in start_work_thread'\"]",

   if !passed && @@previous_double_check.key?(@key) && !@@previous_double_check[@key]
      puts "#{@key} failed after double check"
      _passed=false
   elsif !passed 
     puts "#{@key} first attempt failed, but marking true"      # line 161           
      opts[:failedPendingDoubleCheck] = true
      _passed=true
   end

---

Net::OpenTimeout, "执行过期", "[\"lib/monitoring/monitor.rb:209:in write'\", \"lib/monitoring/monitor.rb:209:inputs'\", \"lib/monitoring/monitor.rb:209:in puts'\", \"lib/monitoring/monitor.rb:209:inblock (2 levels) in do_check '\", \"lib/monitoring/monitor.rb:208:in synchronize'\", \"lib/monitoring/monitor.rb:208:inblock in do_check'\", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/generic.rb:93:in logResult'\", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/http.rb:170:in logResult' \", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/generic.rb:65:in rescue in call_check'\", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/generic.rb:63:in call_check'\", \"/Users/tomburnell/github/lemonitor/lib/monitoring/checks/generic .rb:46:in block in schedule'\", \"/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:218:in do_call'\", \"/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:262:in trigger_now'\", \"/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:307:in 块（3 级） start_work_thread'\", \"/Users/tomburnell/. gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:310:inblock (2 levels) in start_work_thread'\", \"/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:296:in loop'\", \"/Users/tomburnell/.gem/gems/rufus-scheduler-3.5.2/lib/rufus/scheduler/jobs.rb:296:in `block in start_work_thread'\"]", 70196180003060]

    logger[:result] = lambda do |type, passed, opts|
      $logger_mutex.synchronize do
        puts "LOGGING RESULT " + Thread.current.object_id.to_s         # line 209
        log_event "METRIC ns=hc.check type=#{type} result=#{passed ? 'ok':'fail'} key=#{key.join('/').to_json} #{opts.map{|k,v|"#{k}=#{safe_to_json(v)}" if k and v}.compact.join(' ')}"
        $last_result = passed;
        puts "POST LOGGING RESULT " + Thread.current.object_id.to_s
      end
    end

---

线程 #92，停止原因 = 信号 SIGSTOP 帧 #0：0x00007fff68cb8a16 libsystem_kernel.dylib __psynch_cvwait + 10 frame #1: 0x00007fff68e81589 libsystem_pthread.dylib_pthread_cond_wait + 732 帧 #2：0x000000010e3bb179 libruby.2.6.dylib gvl_acquire_common [inlined] native_cond_timedwait(cond=<unavailable>, mutex=<unavailable>) at thread_pthread.c:529 frame #3: 0x000000010e3bb13a libruby.2.6.dylibgvl_acquire_common [内联] do_gvl_timer(vm=, th=) at thread_pthread.c2： 4: 0x000000010e3bb0eb libruby.2.6.dylib gvl_acquire_common(vm=0x00007fdcbb801c00, th=0x00007fdcc0e1b8e0) at thread_pthread.c:253 frame #5: 0x000000010e3b2ed1 libruby.2.6.dylibblocking_region_end [内联] gvl_acquire(vm=0x00007fdcbb801c00, th=) at thread_pthread.c:282 帧 #6: 0x000000010e3b2eb5 libruby.2.6.dylib rb_fwrite_io_blocking_region blocking_region_end(th=0x00007fdcc0e1b8e0, region=0x000070000b8f34b0) at thread.c:1415 frame #7: 0x000000010e3b2a70 libruby.2.6.dylib( internal_writev_func at io.c:1025), data1=0x000070000b8f3688, fd=<unavailable>) at thread.c:1566 frame #8: 0x000000010e2a927f libruby.2.6.dylib] rb_writev_internal(fd=, iov=, iovcnt=) at io.c:1078 frame #9: 0x000000010e2a9264 libruby.2.6.dylib io_fwritev [inlined] io_binwritev(iov=<unavailable>, iovcnt=<unavailable>, fptr=<unavailable>) at io.c:1614 frame #10: 0x000000010e2a8fef libruby.2.6.dylibio_fwritev(argc=, argv=, fptr=0x00007fdcbb531370) at io.c:1678 frame #11: 0x000000010e299de5 libruby.2.6.dylibio_writev(argc=2, argv=0x000070000b8f38c0, io=<unavailable>) at io.c:1723 frame #12: 0x000000010e3f42cc libruby.2.6.dylibvm_call0_body at vm_eval.c:86 frame #13: 0x000000010e3f41f7 libruby.2.6.dylib vm_call0_body [inlined] vm_call0_cfunc(ec=0x00007fdcc0e4c668, argv=0x000070000b8f38c0) at vm_eval.c:100 frame #14: 0x000000010e3f41f7 libruby.2.6.dylibvm_call0_body(ec=0x00007fdcc0e4c668, calling=, ci=, cc=, argv=0x000070000b8f38c0) at vm_eval.c:131 frame #15: 0x000000010e3f2740 libruby.2.6 .dylib rb_funcallv [inlined] rb_vm_call0(ec=<unavailable>, recv=<unavailable>, id=<unavailable>, argc=2, argv=<unavailable>, me =<unavailable>) at vm_eval.c:60 frame #16: 0x000000010e3f270d libruby.2.6.dylibrb_funcallv [内联] rb_call0(ec=0x00007fdcc0e4c668, recv=140586015886600, mid=8481, argc=2, argv=, scope=CALL_FCALL, self=140586015886600) 在 vm_eval.c:308 帧 #17.6.flibyrub00.026.f. dylib rb_funcallv [inlined] rb_call(recv=140586015886600, mid=8481, argc=2, argv=0x0000000000000000, scope=CALL_FCALL) at vm_eval.c:601 frame #18: 0x000000010e3f26f7 libruby.2.6.dylibrb_funcallv(recv=140586015886600, mid=8481, argc=2, argv=) at vm_eval.c:823 frame #19: 0x000000010e299813 libruby.2.6.dylib rb_io_puts(argc=<unavailable>, argv=0x0000000116750320, out=<unavailable>) at io.c:7756 frame #20: 0x000000010e3f42cc libruby.2.6.dylibvm_call0_body at vm_eval.c:86 frame #21: 0x000000020.e liby.1f.6.6 dylibvm_call0_body [inlined] vm_call0_cfunc(ec=0x00007fdcc0e4c668, argv=0x0000000116750320) at vm_eval.c:100 frame #22: 0x000000010e3f41f7 libruby.2.6.dylibvm_call0_body(ec=0x00007fdcc0e4c668, calling=, ci=, cc=, argv=0x0000000116750320) at vm_eval.c:131 frame #23: 0x000000010e3f2740 libruby.2.6.dylib rb_funcallv [inlined] rb_vm_call0(ec=<unavailable>, recv=<unavailable>, id=<unavailable>, argc=1, argv=<unavailable>, me=<unavailable>) at vm_eval.c:60 frame #24: 0x000000010e3f270d libruby.2.6.dylibrb_funcallv [inlined] rb_call0(ec=0x00007fdcc0e4c668, recv=140586015886600, mid =16017, argc=1, argv=, scope=CALL_FCALL, self=140586015886600) at vm_eval.c:308 frame #25: 0x000000010e3f26f7 libruby.2.6.dylib rb_funcallv [inlined] rb_call(recv=140586015886600, mid=16017, argc=1, argv=0x000070000b8f3a80, scope=CALL_FCALL) at vm_eval.c:601 frame #26: 0x000000010e3f26f7 libruby.2.6.dylibrb_funcallv(recv=140586015886600, mid=16017, argv= ) 在 vm_eval.c:823 帧 #27: 0x000000010e403311 libruby.2.6.dylib vm_call_cfunc [inlined] vm_call_cfunc_with_frame(ec=<unavailable>, reg_cfp=<unavailable>, ci=0x00007fdcbb56b0c0) at vm_insnhelper.c:1908 frame #28: 0x000000010e403224 libruby.2.6.dylibvm_call_cfunc(ec=, reg_cfp=, call=, ci=0x00007fdcbb56b0c0, cc=) 在 vm_insnhelper.c:1924 帧 #29: 0x00000002.6.e. dylibvm_exec_core(ec=<unavailable>, initial=<unavailable>) at insns.def:763 frame #30: 0x000000010e3fdd8e libruby.2.6.dylibrb_vm_exec(ec=0x00007fdcc0e4c668, mjit_enable_p=) at vm.c:0 frame #31: 0x000000010e3f6fce libruby.2.6.dylib`rb_yield [inlined] vm_yield at vm.c:1155

标签： rubymultithreadingexceptionfile-descriptor