search

ruby / timeout

Timeout provides a way to auto-terminate a potentially long-running operation if it hasn't finished in a fixed amount of time.
Other
146 stars 22 forks source link

Timeout fails with No live threads left. Deadlock? fatal error after making any API call with Faraday #28

Open docu-tyler-harris opened 1 year ago

docu-tyler-harris commented 1 year ago

This only occurs on Windows machines, to my knowledge and only in version 0.3.x

Script that reproduces this timeout_error.rb

require 'faraday'
require 'byebug'
temp = Faraday.get("https://google.com") # any api call, whether successful or not
byebug # *** while in byebug, tap up arrow several times to access Readline::HISTORY through byebug/interface
exit 0

On a windows machine, run the script ./timeout_error.rb

(byebug) *** CLICK UP ARROW A FEW TIMES ***
Traceback (most recent call last):
        26: from C:/sample_script/timeout_error.rb:6:in `<main>'
        25: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/context.rb:98:in `at_line'
        24: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/processors/command_processor.rb:55:in `at_line'
        23: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/processors/command_processor.rb:97:in `process_commands'
        22: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/processors/command_processor.rb:128:in `repl'
        21: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interface.rb:38:in `read_command'
        20: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interface.rb:55:in `read_input'
        19: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interface.rb:71:in `prepare_input'
        18: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:24:in `readline'
        17: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:36:in `with_repl_like_sigint'
        16: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:24:in `block in readline'
        15: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:53:in `without_readline_completion'
        14: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:24:in `block (2 levels) in readline'
        13: from C:/Ruby27-x64/lib/ruby/2.7.0/forwardable.rb:235:in `readline'
        12: from C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:188:in `readline'
        11: from C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:238:in `inner_readline'
        10: from C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:238:in `loop'
         9: from C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:239:in `block in inner_readline'
         8: from C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:270:in `read_io'
         7: from C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:270:in `loop'
         6: from C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:285:in `block in read_io'
         5: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:198:in `timeout'
         4: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:36:in `catch'
         3: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:36:in `catch'
         2: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:36:in `block in catch'
         1: from C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:184:in `block in timeout'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:184:in `synchronize': No live threads left. Deadlock? (fatal)
2 threads, 2 sleeps current:0x000001fdbd516810 main thread:0x000001fdbd516810
* #<Thread:0x000001fdbf05c3f0 sleep_forever>
   rb_thread_t:0x000001fdbd516810 native:0x000000000000026c int:1
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:184:in `synchronize'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:184:in `block in timeout'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:36:in `block in catch'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:36:in `catch'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:36:in `catch'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:198:in `timeout'
   C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:285:in `block in read_io'
   C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:270:in `loop'
   C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:270:in `read_io'
   C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:239:in `block in inner_readline'
   C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:238:in `loop'
   C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:238:in `inner_readline'
   C:/Ruby27-x64/lib/ruby/2.7.0/reline.rb:188:in `readline'
   C:/Ruby27-x64/lib/ruby/2.7.0/forwardable.rb:235:in `readline'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:24:in `block (2 levels) in readline'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:53:in `without_readline_completion'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:24:in `block in readline'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:36:in `with_repl_like_sigint'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interfaces/local_interface.rb:24:in `readline'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interface.rb:71:in `prepare_input'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interface.rb:55:in `read_input'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/interface.rb:38:in `read_command'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/processors/command_processor.rb:128:in `repl'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/processors/command_processor.rb:97:in `process_commands'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/processors/command_processor.rb:55:in `at_line'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/byebug-11.1.3/lib/byebug/context.rb:98:in `at_line'
   C:/sample_script/timeout_error.rb:6:in `<main>'
* #<Thread:0x000001fdc2d1bca0@Timeout stdlib thread C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:101 sleep_forever>
   rb_thread_t:0x000001fdc3040810 native:0x00000000000000a4 int:0
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:113:in `wait'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:113:in `block (2 levels) in create_timeout_thread'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:111:in `synchronize'
   C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/timeout-0.3.2/lib/timeout.rb:111:in `block in create_timeout_thread'
eregon commented 1 year ago

Thank you for the report. It doesn't look related to #17 to me at first sight.

I wondered if there could be a problem when nesting calls to Timeout.timeout{} but that doesn't seem an issue, the lock is not held during the block given to timeout.

Could you try with Ruby 3.0+? That differs in that Mutex is owned per Fiber, faraday or byebug likely use Fibers.

Could you try to minimize the example to avoid depending on gems? That should help to understand where the problem is. It could be a bug that Mutex misbehaves on Windows on CRuby, but that seems unlikely.

I don't have a Windows dev env, so I cannot really investigate myself if it's not reproducible on Linux.

docu-tyler-harris commented 1 year ago

Thanks for checking.

It will likely take me a while to find time to simplify this further. Using any version of byebug/faraday reproduces the issue, and only on timeout versions >= 0.3.0. I have no idea why the API call through faraday is needed before this will repro

Ruby 3.0+ is a goal for us, but our mono repo has some gem dependencies keeping us on 2.7 for the time being. Currently I'm forcing a downgrade of timeout to 0.2.x to workaround the issue until we can find a better solution.

eregon commented 1 year ago

Ruby 3.0+ is a goal for us, but our mono repo has some gem dependencies keeping us on 2.7 for the time being. Currently I'm forcing a downgrade of timeout to 0.2.x to workaround the issue until we can find a better solution.

Could you try your repro above on Ruby 3.0 on Windows and reply here whether it's also affected or not? That shouldn't require much work.

FYI in case it is related to #17, see https://github.com/ruby/timeout/issues/17#issuecomment-1451761281 (i.e., that should be fixed in CRuby IMO, let's see how that issue evolves).

andrewngo commented 8 months ago

I am seeing it on Ruby 3.2 and timeout 0.4.1 (on Windows Server) using the above example.

   1: require 'faraday'
   2: require 'byebug'
   3: temp = Faraday.get("https://google.com") # any api call, whether successful or not
   4: byebug # *** while in byebug, tap up arrow several times to access Readline::HISTORY through byebug/interface
=> 5: exit 0
(byebug) C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/timeout-0.4.1/lib/timeout.rb:181:in `synchronize': No live threads left. Deadlock? (fatal)
2 threads, 2 sleeps current:0x000001ab91efe660 main thread:0x000001ab91efe660
* #<Thread:0x000001ab91f99ff0 sleep_forever>
   rb_thread_t:0x000001ab91efe660 native:0x0000000000000220 int:0

* #<Thread:0x000001ab99429fa0@Timeout stdlib thread C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/timeout-0.4.1/lib/timeout.rb:98 sleep_forever>
   rb_thread_t:0x000001ab98b2dbf0 native:0x0000000000000364 int:0

        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/timeout-0.4.1/lib/timeout.rb:181:in `block in timeout'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/timeout-0.4.1/lib/timeout.rb:41:in `handle_timeout'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/timeout-0.4.1/lib/timeout.rb:195:in `timeout'
        from C:/Ruby32-x64/lib/ruby/3.2.0/reline.rb:430:in `read_2nd_character_of_key_sequence'
        from C:/Ruby32-x64/lib/ruby/3.2.0/reline.rb:408:in `block in read_io'
        from C:/Ruby32-x64/lib/ruby/3.2.0/reline.rb:390:in `loop'
        from C:/Ruby32-x64/lib/ruby/3.2.0/reline.rb:390:in `read_io'
        from C:/Ruby32-x64/lib/ruby/3.2.0/reline.rb:343:in `block in inner_readline'
        from C:/Ruby32-x64/lib/ruby/3.2.0/reline.rb:341:in `loop'
        from C:/Ruby32-x64/lib/ruby/3.2.0/reline.rb:341:in `inner_readline'
        from C:/Ruby32-x64/lib/ruby/3.2.0/reline.rb:284:in `readline'
        from C:/Ruby32-x64/lib/ruby/3.2.0/forwardable.rb:240:in `readline'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/interfaces/local_interface.rb:24:in `block in readline'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/interfaces/local_interface.rb:36:in `with_repl_like_sigint'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/interfaces/local_interface.rb:24:in `readline'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/interface.rb:71:in `prepare_input'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/interface.rb:55:in `read_input'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/interface.rb:38:in `read_command'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/processors/command_processor.rb:128:in `repl'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/processors/command_processor.rb:97:in `process_commands'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/processors/command_processor.rb:55:in `at_line'
        from C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/byebug-11.0.1/lib/byebug/context.rb:98:in `at_line'