Bug #21195: Crash when using IO#timeout

• Status: Closed
• Assignee: ioquatix (Samuel Williams)
• Target version: -
• Backport: 3.1: UNKNOWN, 3.2: REQUIRED, 3.3: DONE, 3.4: DONE

[nickamorim (Nick Amorim)]

We have adopted the IO#timeout feature in Dalli (ref) for I/O timeouts. We regularly see crashes in our CI environment that I was able to pinpoint to calling IO#gets with IO#timeout:

C Backtrace

_bk;t=1742524358337-- Threading information ---------------------------------------------------
_bk;t=1742524358337Total ractor count: 1
_bk;t=1742524358337Ruby thread count for this ractor: 10
_bk;t=1742524358337
_bk;t=1742524358337-- C level backtrace information -------------------------------------------
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_print_backtrace+0x8) [0x798534ef70c2] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_dump.c:823
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_vm_bugreport) /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_dump.c:1155
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_bug_without_die_internal+0x6b) [0x798534bf99b1] /tmp/ruby-build/ruby-3.4.2-pshopify2/error.c:1097
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_bug) /tmp/ruby-build/ruby-3.4.2-pshopify2/error.c:1115
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_syserr_new_path_in+0x30) [0x798534bf9ea2] /tmp/ruby-build/ruby-3.4.2-pshopify2/error.c:3927
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_syserr_fail_path_in+0xf) [0x798534cd8daf] /tmp/ruby-build/ruby-3.4.2-pshopify2/error.c:3915
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(io_fillbuf+0x99) [0x798534d22679] /tmp/ruby-build/ruby-3.4.2-pshopify2/io.c:2642
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(appendline+0x3d) [0x798534d250d5] /tmp/ruby-build/ruby-3.4.2-pshopify2/io.c:3954
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_io_getline_0) /tmp/ruby-build/ruby-3.4.2-pshopify2/io.c:4215
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_io_getline_1+0x21) [0x798534d25edb] /tmp/ruby-build/ruby-3.4.2-pshopify2/io.c:4273
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_io_getline) /tmp/ruby-build/ruby-3.4.2-pshopify2/io.c:4293
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_io_gets_m) /tmp/ruby-build/ruby-3.4.2-pshopify2/io.c:4387
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_call_cfunc_with_frame_+0x11f) [0x798534ecd7af] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_insnhelper.c:3794
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_sendish+0xbb) [0x798534ed6e6c] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_insnhelper.c:5961
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_exec_core) /tmp/ruby-build/ruby-3.4.2-pshopify2/insns.def:898
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_vm_exec+0x189) [0x798534ede289] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:2595
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_yield_values2+0x63) [0x798534ee2be3] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:1676
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_ensure+0xe6) [0x798534ce1116] /tmp/ruby-build/ruby-3.4.2-pshopify2/eval.c:1074
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_call_cfunc_with_frame_+0x11f) [0x798534ecd7af] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_insnhelper.c:3794
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_sendish+0xd3) [0x798534ec6da3] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_insnhelper.c:5961
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_exec_core+0x1151) [0x798534ed7e71] /tmp/ruby-build/ruby-3.4.2-pshopify2/insns.def:851
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_vm_exec+0x189) [0x798534ede289] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:2595
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_yield_with_cref+0x42) [0x798534ee3348] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:1676
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_yield) /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:1684
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_yield_0) /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_eval.c:1344
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_yield) /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_eval.c:1360
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_ary_collect+0x5c) [0x798534c1010c] /tmp/ruby-build/ruby-3.4.2-pshopify2/array.c:3645
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_call_cfunc_with_frame_+0x11f) [0x798534ecd7af] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_insnhelper.c:3794
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_sendish+0xd3) [0x798534ec6da3] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_insnhelper.c:5961
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_exec_core+0x1151) [0x798534ed7e71] /tmp/ruby-build/ruby-3.4.2-pshopify2/insns.def:851
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_vm_exec+0x189) [0x798534ede289] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:2595
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_yield_with_cref+0x42) [0x798534ee3348] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:1676
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_yield) /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:1684
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_yield_0) /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_eval.c:1344
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_yield) /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_eval.c:1360
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(RB_FL_TEST_RAW+0x0) [0x798534c0951c] /tmp/ruby-build/ruby-3.4.2-pshopify2/array.c:2641
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(RB_FL_ANY_RAW) ./include/ruby/internal/fl_type.h:520
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_array_len) ./include/ruby/internal/core/rarray.h:259
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_ary_each) /tmp/ruby-build/ruby-3.4.2-pshopify2/array.c:2640
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_call_cfunc_with_frame_+0x11f) [0x798534ecd7af] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_insnhelper.c:3794
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_sendish+0xd3) [0x798534ec6da3] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm_insnhelper.c:5961
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_exec_core+0x1151) [0x798534ed7e71] /tmp/ruby-build/ruby-3.4.2-pshopify2/insns.def:851
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(vm_exec_loop+0xa) [0x798534ede529] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:2622
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_vm_exec) /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:2601
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_vm_invoke_proc+0x66) [0x798534edf276] /tmp/ruby-build/ruby-3.4.2-pshopify2/vm.c:1770
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_proc_call_kw+0x6a) [0x798534dc825a] /tmp/ruby-build/ruby-3.4.2-pshopify2/proc.c:988
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(exec_end_procs_chain+0x44) [0x798534ce25cd] /tmp/ruby-build/ruby-3.4.2-pshopify2/eval_jump.c:105
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_ec_exec_end_proc) /tmp/ruby-build/ruby-3.4.2-pshopify2/eval_jump.c:121
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_ec_teardown+0xcc) [0x798534ce27bc] /tmp/ruby-build/ruby-3.4.2-pshopify2/eval.c:155
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(rb_ec_cleanup+0x144) [0x798534ce29f4] /tmp/ruby-build/ruby-3.4.2-pshopify2/eval.c:207
_bk;t=1742524358649/usr/local/ruby/lib/libruby.so.3.4(ruby_run_node+0x8d) [0x798534ce2e1d] /tmp/ruby-build/ruby-3.4.2-pshopify2/eval.c:319

Ruby Backtrace

_bk;t=1742524358337/tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/protocol/connection_manager.rb:157: [BUG] rb_sys_fail_path_in(io_fillbuf, fd:16 ) - errno == 0
_bk;t=1742524358337ruby 3.4.2 (2025-03-18 revision 20130836d0) +PRISM [x86_64-linux]
_bk;t=1742524358337
_bk;t=1742524358337-- Control frame information -----------------------------------------------
_bk;t=1742524358337c:0042 p:---- s:0206 e:000205 CFUNC  :gets
_bk;t=1742524358337c:0041 p:0007 s:0201 e:000200 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/protocol/connection_manager.rb:157
_bk;t=1742524358337c:0040 p:0005 s:0195 e:000194 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/protocol/meta/response_processor.rb:242
_bk;t=1742524358337c:0039 p:0003 s:0191 e:000190 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/protocol/meta/response_processor.rb:246
_bk;t=1742524358337c:0038 p:0003 s:0186 e:000185 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/protocol/meta/response_processor.rb:186
_bk;t=1742524358337c:0037 p:0007 s:0180 e:000179 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/protocol/meta/response_processor.rb:108
_bk;t=1742524358337c:0036 p:0025 s:0176 e:000175 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/protocol/meta.rb:232
_bk;t=1742524358337c:0035 p:0021 s:0171 e:000170 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/protocol/base.rb:37
_bk;t=1742524358337c:0034 p:0010 s:0163 e:000162 BLOCK  /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/options.rb:18 [FINISH]
_bk;t=1742524358337c:0033 p:---- s:0160 e:000159 CFUNC  :synchronize
_bk;t=1742524358337c:0032 p:0006 s:0156 e:000155 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/options.rb:17
_bk;t=1742524358337c:0031 p:0008 s:0150 e:000149 BLOCK  /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/client.rb:324 [FINISH]
_bk;t=1742524358337c:0030 p:---- s:0146 e:000145 CFUNC  :map
_bk;t=1742524358337c:0029 p:0011 s:0142 e:000141 METHOD /tmp/bundle/ruby/3.4.0/bundler/gems/dalli-fbd3cba210d9/lib/dalli/client.rb:324

Unfortunately, I was not able to build a reproducible test. I have tried running on both Ruby 3.4.1 and 3.4.2 with no luck. The crash happens here: https://github.com/Shopify/ruby/blob/v3.4.1-pshopify3/io.c#L2632-L2643.

Please let me know if there's any more information that I can provide :-)

[mame (Yusuke Endoh)]

Thank you, I could reproduce the issue.

$ ./miniruby -e '$stdin.read_nonblock(1, exception: false); trap(:HUP) { p :HUP }; Thread.new { sleep 1; Process.kill :HUP, $$ }; $stdin.timeout = 1; gets'
:HUP
-e:1: [BUG] rb_sys_fail_path_in(io_fillbuf, fd:0 <STDIN>) - errno == 0
ruby 3.5.0dev (2025-03-19T06:08:20Z master 6c7f721f1e) +PRISM [x86_64-linux]

-- Control frame information -----------------------------------------------
c:0004 p:---- s:0013 e:000012 CFUNC  :gets
c:0003 p:---- s:0010 e:000009 CFUNC  :gets
c:0002 p:0030 s:0006 E:001150 EVAL   -e:1 [FINISH]
c:0001 p:0000 s:0003 E:002500 DUMMY  [FINISH]

-- Ruby level backtrace information ----------------------------------------
-e:1:in '<main>'
-e:1:in 'gets'
-e:1:in 'gets'

-- Threading information ---------------------------------------------------
Total ractor count: 1
Ruby thread count for this ractor: 1

-- C level backtrace information -------------------------------------------
./miniruby(rb_print_backtrace+0x8) [0x5618fa77f4da] /home/mame/work/ruby/vm_dump.c:835
./miniruby(rb_vm_bugreport) /home/mame/work/ruby/vm_dump.c:1167
./miniruby(rb_bug_without_die_internal+0x58) [0x5618fa458f35] /home/mame/work/ruby/error.c:1097
./miniruby(rb_bug) /home/mame/work/ruby/error.c:1115
./miniruby(rb_syserr_new_path_in+0x2d) [0x5618fa4593f8] /home/mame/work/ruby/error.c:3955
./miniruby(rb_syserr_fail_path_in+0xf) [0x5618fa542f5f] /home/mame/work/ruby/error.c:3943
./miniruby(io_fillbuf+0xb9) [0x5618fa599cb9] /home/mame/work/ruby/io.c:2642
*snip*

When IO#timeout is set, it seems that internal_read_func may return -1 but errno remains 0.

The following patch will prevent that. Is this patch OK? @nobu (Nobuyoshi Nakada)

diff --git a/io.c b/io.c
index 3edb15ab7f..7dc92a5498 100644
--- a/io.c
+++ b/io.c
@@ -1192,7 +1192,7 @@ internal_read_func(void *ptr)
     ssize_t result;

     if (iis->timeout && !iis->nonblock) {
-        if (io_internal_wait(iis->th, iis->fptr, 0, RB_WAITFD_IN, iis->timeout) == -1) {
+        if (io_internal_wait(iis->th, iis->fptr, ETIMEDOUT, RB_WAITFD_IN, iis->timeout) == -1) {
             return -1;
         }
     }

[mame (Yusuke Endoh)]

• Status changed from Open to Assigned
• Assignee set to ioquatix (Samuel Williams)

Ah, the code was written by @ioquatix (Samuel Williams). @ioquatix (Samuel Williams) Could you review the patch?

[ioquatix (Samuel Williams)]

Thanks @mame (Yusuke Endoh) I will review it today.

[ioquatix (Samuel Williams)]

@mame (Yusuke Endoh) your reproduction is extremely useful, thanks.

The fix you provided isn't quite right, I believe the correct fix is https://github.com/ruby/ruby/pull/12961.

[mame (Yusuke Endoh)]

Thanks, I am sure you are right as I do not have a good enough understanding of the code around this.

• Status changed from Assigned to Closed

Applied in changeset git|5f77f9bea61fb4cc8447a76e191fdfb28f076862.

---

Fix handling of error/errno in io_internal_wait. (#12961)

[Bug #21195]

[ioquatix (Samuel Williams)]

• Status changed from Closed to Assigned
• Backport changed from 3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN, 3.4: UNKNOWN to 3.1: UNKNOWN, 3.2: REQUIRED, 3.3: REQUIRED, 3.4: REQUIRED

[ioquatix (Samuel Williams)]

I have requested backport 3.2+. Thanks!

@nickamorim thanks for your bug report!

[ioquatix (Samuel Williams)]

• Status changed from Assigned to Closed

[alanwu (Alan Wu)]

• Backport changed from 3.1: UNKNOWN, 3.2: REQUIRED, 3.3: REQUIRED, 3.4: REQUIRED to 3.1: UNKNOWN, 3.2: REQUIRED, 3.3: REQUIRED, 3.4: DONE

[nagachika (Tomoyuki Chikanaga)]

• Backport changed from 3.1: UNKNOWN, 3.2: REQUIRED, 3.3: REQUIRED, 3.4: DONE to 3.1: UNKNOWN, 3.2: REQUIRED, 3.3: DONE, 3.4: DONE

ruby_3_3 51dee044c1cb079a463118c5113ae9fdf96e463e merged revision(s) 5f77f9bea61fb4cc8447a76e191fdfb28f076862.