async: Simple example with `puts` hangs depending on whether newlines included

Ruby 3.1.0, async 2.0.0

There’s a high probably that this isn’t actually a bug, but in case it is:

This example works:

Async do |t|
  puts "Root start\n"
  t.async do
    puts "Sleep 1 Start\n"
    sleep 1
    puts "Sleep 1 End\n"
  end
  t.async do
    puts "Sleep 2 Start\n"
    sleep 1
    puts "Sleep 2 End\n"
  end
  puts "Root end\n"
end

and produces the following

Root start
Sleep 1 Start
Sleep 2 Start
Root end
Sleep 1 End
Sleep 2 End

But the following example, which simply removes the newlines, hangs:

Async do |t|
  puts "Root start"
  t.async do
    puts "Sleep 1 Start"
    sleep 1
    puts "Sleep 1 End"
  end
  t.async do
    puts "Sleep 2 Start"
    sleep 1
    puts "Sleep 2 End"
  end
  puts "Root end"
end

Here’s the output it produces before it hangs:

Root start
Sleep 1 StartSleep 2 Start
Root end
Sleep 2 End

I’m guessing this has something to do with sharing the stdout IO object between Fibers, and that newlines flush the IO object to put it in a more usable state to pass to another fiber, but why would that cause a hang? Is that expected?

About this issue

Original URL
State: closed
Created 2 years ago
Reactions: 1
Comments: 36 (18 by maintainers)

Commits related to this issue

Fix kqueue event clobbering Fixes root issue desribed here: https://github.com/socketry/async/issues/137 The solution is to set the EV_UDATA_SPECIFIC flag on all kqueue events, which tells kqueue t... — committed to machty/io-event by machty 2 years ago
Fix kqueue event clobbering Fixes root issue desribed here: https://github.com/socketry/async/issues/137 The solution is to set the EV_UDATA_SPECIFIC flag on all kqueue events, which tells kqueue t... — committed to socketry/io-event by machty 2 years ago

Most upvoted comments

This should be completely fixed on Ruby head and in Ruby 3.2.0 when it is released.

ioquatix on Jun 3, 2022

It’s not good practice to write to the same IO from different fibers/threads generally.

IO#puts "x" internally corresponds to the following operations:

IO.write("x", "\n")

This internally maps to rb_writev_internal with io.c:

https://github.com/ruby/ruby/blob/0ca00e2cb74f9d07d27844d97c29c208caab95a7/io.c#L1180-L1200

However the fiber scheduler doesn’t support io vectors at this time… we might add support, or we might not. However, it’s totally valid to only write the first iov as a partial write and expect Ruby to retry.

However, in this case, Ruby actually assumes that the IO is not ready for writing, so instead of trying again it calls io_wait. This schedules the IO into the event loop and ultimately kqueue. This is basically unnecessary in this case.

Anyway, to cut a long story short, it maps to the following sequence of operations:

write("x")
io_wait(WRITABLE)
write("\n")

However in the fiber scheduler, io_wait is a switch point so you end up with two fibers doing this:

(A) write("x")
(A) io_wait(WRITABLE)
(B) write("x")
(B) io_wait(WRITABLE) -> overwrites (A)
(B) write("\n")
(A) hangs forever.

Ruby has a write_lock for multi-thread access to synchronous IO, i.e. $stdin, $stdout. But in this case, the locking isn’t around the whole operation, only the write operation, so we still break when io_wait occurs the 2nd time. I think we should fix this, personally.

ioquatix on Jan 8, 2022

I implemented the change I described above here and it fixes the issue (it produces the clean non-mangled output [and doesn’t hang]) https://github.com/ruby/ruby/commit/756b25466fda0c829498853cbd13c8ac97288bab

Output

Root start
Sleep 1 Start
Root end
Sleep 2 Start
Sleep 1 End
Sleep 2 End

machty on Jan 16, 2022

I’m on io-event v1.0.2 and do not see this issue.

output

Root start
Sleep 1 StartSleep 2 Start

Root end
Sleep 1 EndSleep 2 End

pbstriker38 on Jan 15, 2022

Here’s me running the whole thing include the ruby --version at the top:

ruby --version
ruby 3.2.0dev (2022-01-09T06:48:23Z :detached: 60af64b25b) [x86_64-darwin20]
(base) code :: irb
irb(main):001:0> require 'async'
=> true
irb(main):002:0> Async do |t|
irb(main):003:0*     puts "Root start"
irb(main):004:0>   t.async do
irb(main):005:1*         puts "Sleep 1 Start"
irb(main):006:1>       sleep 1
irb(main):007:1>       puts "Sleep 1 End"
irb(main):008:1>     end
irb(main):009:0>   t.async do
irb(main):010:1*         puts "Sleep 2 Start"
irb(main):011:1>       sleep 1
irb(main):012:1>       puts "Sleep 2 End"
irb(main):013:1>     end
irb(main):014:0>   puts "Root end"
irb(main):015:0> end
Root start
Sleep 1 StartSleep 2 Start
Root end
Sleep 2 End
^C/Users/machty/.rubies/ruby-head/lib/ruby/3.2.0/irb.rb:437:in `raise': abort then interrupt! (IRB::Abort)
	from /Users/machty/.gem/ruby/3.2.0/gems/async-2.0.0/lib/async/scheduler.rb:224:in `select'
	from /Users/machty/.gem/ruby/3.2.0/gems/async-2.0.0/lib/async/scheduler.rb:224:in `run_once'
	from /Users/machty/.gem/ruby/3.2.0/gems/async-2.0.0/lib/async/scheduler.rb:243:in `run'
	from /Users/machty/.gem/ruby/3.2.0/gems/async-2.0.0/lib/kernel/async.rb:48:in `Async'
	from (irb):2:in `<main>'
	from /Users/machty/.rubies/ruby-head/lib/ruby/gems/3.2.0/gems/irb-1.4.1/exe/irb:11:in `<top (required)>'
	from /Users/machty/.rubies/ruby-head/bin/irb:25:in `load'
	from /Users/machty/.rubies/ruby-head/bin/irb:25:in `<main>'

machty on Jan 10, 2022

https://github.com/ruby/ruby/pull/5419

ioquatix on Jan 8, 2022