Bug #14634: Queue#push seems to crash after fork

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-linux]
• Backport: 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: DONE

[zetaben (Benoit Larroque)]

Hello,

We are providing an agent that uses dynamic instrumentation to provide additional security checks on Rails applications.

We recently received issues from one of our customers that just upgraded from Ruby 2.4 to 2.5.0 on Heroku about segfault coming from inside the gem. These seemed to happen randomly when our agent was pushing to a Ruby Queue (that is consumed by our reporting thread).

We managed to reproduced this issue locally using the customer application code. It seems to happen regularly to the first Queue#push done by the instrumented Unicorn worker just after startup:

• Master start-up
• Our agent starts, connects to our backend, apply instrumentation, creates the queue and starts listening on it (Queue#pop interrupted by a Timeout in an infinite loop)
• Master fork and launch worker
• Worker starts to answer HTTP traffic
• Agent detects that reporting thread is dead (because of fork) and restarts a thread listening on the same Queue instance but in the new process
• Worker handles another HTTP request and tries to Queue#push some metrics to Queue instance

==> Ruby then crashes with either:

• Most often: [BUG] pthread_mutex_lock: Invalid argument (EINVAL)
• Sometime with [BUG] Segmentation fault at 0x0000000000000038

Both being located to:

c:0052 p:---- s:0384 e:000383 CFUNC  :push

which would be the C-func that pushes in the Queue.

I'm attaching the stripped bug report traces to ticket.

We found a workaround by actually recreating a new Queue instance on agent start in the worker (So it does not happen on a brand new Queue after forking).

Also, the first workaround we tried though was copying the pure Ruby Queue implementation from previous Ruby versions (circa 2.0.0). This actually didn't work and lead to a similar crash happening this time on the ConditionVariable

2018-03-21T22:53:41.973451+00:00 app[web.2]: /app/vendor/bundle/ruby/2.5.0/gems/sqreen-1.11.2/lib/sqreen/backported_queue.rb:24: [BUG] pthread_mutex_lock: Invalid argument (EINVAL)
2018-03-21T22:53:41.973454+00:00 app[web.2]: ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-linux]
2018-03-21T22:53:41.973456+00:00 app[web.2]:
2018-03-21T22:53:41.973457+00:00 app[web.2]: -- Control frame information -----------------------------------------------
2018-03-21T22:53:41.973462+00:00 app[web.2]: c:0057 p:---- s:0407 e:000406 CFUNC  :signal
2018-03-21T22:53:41.973466+00:00 app[web.2]: c:0056 p:0017 s:0403 e:000402 BLOCK  /app/vendor/bundle/ruby/2.5.0/gems/sqreen-1.11.2/lib/sqreen/backported_queue.rb:24 [FINISH]
2018-03-21T22:53:41.973473+00:00 app[web.2]: c:0055 p:---- s:0400 e:000399 CFUNC  :synchronize
2018-03-21T22:53:41.973481+00:00 app[web.2]: c:0054 p:0008 s:0396 e:000395 BLOCK  /app/vendor/bundle/ruby/2.5.0/gems/sqreen-1.11.2/lib/sqreen/backported_queue.rb:22 [FINISH]
2018-03-21T22:53:41.973489+00:00 app[web.2]: c:0053 p:---- s:0393 e:000392 CFUNC  :handle_interrupt
2018-03-21T22:53:41.973502+00:00 app[web.2]: c:0052 p:0022 s:0388 e:000387 METHOD /app/vendor/bundle/ruby/2.5.0/gems/sqreen-1.11.2/lib/sqreen/backported_queue.rb:21
2018-03-21T22:53:41.973507+00:00 app[web.2]: c:0051 p:0031 s:0383 e:000382 METHOD /app/vendor/bundle/ruby/2.5.0/gems/sqreen-1.11.2/lib/sqreen/capped_queue.rb:22

While putting my ideas in order when writing this bug report I finally managed to find a way to reproduce the issue in a simple Ruby script. Please find it attached with matching Ruby trace report.

Nota this script does not crash in the following Ruby version on my computer:
ruby 2.3.0p0 (2015-12-25 revision 53290) [x86_64-linux]
ruby 2.4.3p205 (2017-12-14 revision 61247) [x86_64-linux]

but does crash under:
ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-linux]

Let me know if I can help further

Finally, thanks for writing & maintaining such an awesome language !

[zetaben (Benoit Larroque)]

• Subject changed from Queue#push seems to crash to Queue#push seems to crash after fork

[normalperson (Eric Wong)]

[e-mail] wrote:

https://bugs.ruby-lang.org/issues/14634

This seems identical to [Bug #14578] (sorry, my fault)
Can you try r62852 in ruby_2_5 branch (or r62668 in trunk)?
Thanks.

[zetaben (Benoit Larroque)]

• File rev62852.txt rev62852.txt added

Hello Eric,

I just tried compiling & running with r62852 on my computer. I still have the same issue:

/versatile/queue2.rb:62: [BUG] pthread_mutex_lock: Invalid argument (EINVAL)    
ruby 2.5.0p43 (2018-03-19 revision 62852) [x86_64-linux]                        
                                                                                
-- Control frame information -----------------------------------------------    
c:0003 p:---- s:0014 e:000013 CFUNC  :push 

(please find full trace attached)

Looking a bit through the issues earlier, I actually found that https://bugs.ruby-lang.org/issues/14474 was having very similar symptoms as my issue but the offending test seemed not really related (threads only no queue). I forgot to mention this in my initial report, sorry!

[normalperson (Eric Wong)]

[e-mail] wrote:

I just tried compiling & running with r62852 on my computer. I still have the same issue:

/versatile/queue2.rb:62: [BUG] pthread_mutex_lock: Invalid argument (EINVAL)    
ruby 2.5.0p43 (2018-03-19 revision 62852) [x86_64-linux]                 

Thanks. Still my bug :< Fix coming in a few.

Looking a bit through the issues earlier, I actually found
that https://bugs.ruby-lang.org/issues/14474 was having very
similar symptoms as my issue but the offending test seemed not
really related (threads only no queue). I forgot to mention
this in my initial report, sorry!

Ah, thanks. I wonder if autoload cause that.... Will check in a
bit.

[normalperson (Eric Wong)]

• Backport changed from 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: UNKNOWN to 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: REQUIRED

• Status changed from Open to Closed

Applied in changeset trunk|r62934.

---

thread_sync.c: avoid reaching across stacks of dead threads

rb_ensure is insufficient cleanup for fork and we must
reinitialize all waitqueues in the child process.

Unfortunately this increases the footprint of ConditionVariable,
Queue and SizedQueue by 8 bytes on 32-bit (16 bytes on 64-bit).

[ruby-core:86316] [Bug #14634]

[normalperson (Eric Wong)]

Eric Wong [e-mail] wrote:

[e-mail] wrote:

I just tried compiling & running with r62852 on my computer. I still have the same issue:

/versatile/queue2.rb:62: [BUG] pthread_mutex_lock: Invalid argument (EINVAL)    
ruby 2.5.0p43 (2018-03-19 revision 62852) [x86_64-linux]                 

Thanks. Still my bug :< Fix coming in a few.

Can you try r62934? Thanks.

Looking a bit through the issues earlier, I actually found
that https://bugs.ruby-lang.org/issues/14474 was having very
similar symptoms as my issue but the offending test seemed not
really related (threads only no queue). I forgot to mention
this in my initial report, sorry!

Ah, thanks. I wonder if autoload cause that.... Will check in a
bit.

Ugh, tired and I still have other stuff to do :< I guess it's
less urgent

[zetaben (Benoit Larroque)]

$ ./tool/runruby.rb  --version
ruby 2.6.0dev (2018-03-27 trunk 62934) [x86_64-linux]
$ ./tool/runruby.rb ~/AgentRuby/bin/queue2.rb 
8640.47011093644200: Starting
8640.47011093738780: Consumer parent thread 47011093739080
8640.47011093644200: Forking
8645.47011093708060: Consumer thread 47011093739080
8645.47011093644200: finished child
8640.47011093644200: finished parent

That seem to have fixed it! Newbie question, do you plan to backport it to 2.5.x series also ?

Thanks for the awesome response time!

[normalperson (Eric Wong)]

[e-mail] wrote:

That seem to have fixed it! Newbie question, do you plan to backport it to 2.5.x series also ?

Thanks for the confirmation. I'm not too happy about the memory
increase for such objects; but I will work on that next month.

naruse handles the backporting for 2.5 branch.

Thanks for the awesome response time!

No prob, just lucky since I've been offline a lot, lately.

[normalperson (Eric Wong)]

Eric Wong [e-mail] wrote:

[e-mail] wrote:

That seem to have fixed it! Newbie question, do you plan to backport it to 2.5.x series also ?

Thanks for the confirmation. I'm not too happy about the memory
increase for such objects; but I will work on that next month.

naruse handles the backporting for 2.5 branch.

I guess we missed the merge window for 2.5.1

Fwiw, I consider doing fork after creating threads to be
dangerous and bug-prone in any language. AFAIK, pthreads
implementations do not support it, even.

Ruby currently can support this because of GVL; but I'm not sure
how well we can support this pattern in the future.

Just to reiterate:

Thread.new; fork;	 # unsafe
fork; Thread.new;	 # safe

For the fork+exec case, we use vfork+exec via Process.spawn to
ensure backtick and system() work inside Threads. (Similarly,
POSIX has posix_spawn(3)).

[zetaben (Benoit Larroque)]

I guess we missed the merge window for 2.5.1
Too bad! next time one then !

Fwiw, I consider doing fork after creating threads to be
dangerous and bug-prone in any language. AFAIK, pthreads
implementations do not support it, even.

Ruby currently can support this because of GVL; but I'm not sure
how well we can support this pattern in the future.

Just to reiterate:

Thread.new; fork; # unsafe
fork; Thread.new; # safe

For the fork+exec case, we use vfork+exec via Process.spawn to
ensure backtick and system() work inside Threads. (Similarly,
POSIX has posix_spawn(3)).

Thanks for the detailed infos ! I'll see if I can tune our design with this in mind.

[zetaben (Benoit Larroque)]

• File cons_defined_sigsev.txt cons_defined_sigsev.txt added

Hello @normalperson (Eric Wong),

The customer just sent me another crasher report (segfault). It happens in another location in Ruby on Module.const_defined?. I looked at the ruby code while going through the crasher trace, and it seems that it's using a very similar pattern (wait list + rb_ensure) near line 2192 in rb_autoload_load (on trunk).
From what I got from the r62934 commit, the rb_ensure pattern might here also not be sufficient after a fork.
I'm sorry though, I have no reproduction script yet.
This happens on a newly updated Ruby 2.5.1

I attached the crasher log. To my non-expert eye, it really felt like the same bug happening in another place, but if you want me to open another dedicated ticket I'll be happy to.

[normalperson (Eric Wong)]

Thanks. I suspected autoload was a problem; too :x I'll try to
take a look at it in the coming days (sorry, many things going
on...) If you can start with a small test case that would be
much appreciated. Thanks again.

But really, forking after creating threads is a terrible idea
(outside of Process.spawn/system/backtick)

[normalperson (Eric Wong)]

[e-mail] wrote:

The customer just sent me another crasher report (segfault).
It happens in another location in Ruby on
Module.const_defined?. I looked at the ruby code while going
through the crasher trace, and it seems that it's using a very
similar pattern (wait list + rb_ensure) near line 2192 in
rb_autoload_load (on trunk).

Sorry for the delay, can you try r63210? Curious if somebody
else hit this and we failed to notice, since it's been a bug
since 2.3.0 in 2015.

(also at: https://80x24.org/spew/[e-mail]/raw )

[jmgarnier (Jean-Michel Garnier)]

• Status changed from Closed to Open
• ruby -v changed from ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-linux] to ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-linux]

I also encountered segfaults when upgrading from ruby 2.4 to 2.5.1
they happen in https://github.com/codegram/futuroscope gem which initalizes a pool of threads at startup. When passenger smart spawning forks the process, it segfaults.

I tested the same code with ruby 2.6 preview and no segfaults.

Any idea when naruse will backport to 2.5 branch please?

We are not in hurry, we can also wait for 2.6.

[tenderlovemaking (Aaron Patterson)]

Hi, we've been hitting this bug at work too. I tested these commits (backported them on to Ruby 2.5) and they seem to clear up the issue. Naruse, could we have these backported to the ruby_2_5 branch? I made backport commits here: https://github.com/github/ruby/pull/40

If there's anything I can do to help, please let me know.

Thanks!

[shan (Shannon Skipper)]

Hi, we've also been running into this at work. Thanks for the fix and backport! We look forward to a 2.5.2 release.

[nagachika (Tomoyuki Chikanaga)]

• Related to Bug #15383: Reproducible crash: crash.rb:6: [BUG] unexpected THREAD_KILLED added

[nagachika (Tomoyuki Chikanaga)]

• Status changed from Open to Closed

[nagachika (Tomoyuki Chikanaga)]

• Backport changed from 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: REQUIRED to 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: DONE

ruby_2_5 r66912 merged revision(s) 62934,63210,63215,63309.