Segfault from EM.run after EM::Connection#unbind raises exception #765

SpComb · 2017-02-01T10:23:24Z

I experienced a segfault similar to #758 and #761 when trying to write rspecs for a faye/websocket client, using an EM.run { ... } pattern similar to tests/test_unbind_reason.rb.

The following minimal repro crashes with a segfault when run with CRASH_EM=1:

#!/usr/bin/env ruby

require 'eventmachine'

class Subject < EM::Connection
  def self.connect(host, port)
    STDERR.puts "EM.connect..."

    EM.connect '127.0.0.1', 1337, self
  end

  def unbind(reason = nil)
    STDERR.puts "EM::Connection.unbind: #{reason}"

    fail 'crash EventMachine' if ENV['CRASH_EM']

    EM.stop
  rescue => exc
    STDERR.puts "raise #{exc}:\n#{exc.backtrace.join "\n"}\n\n"
    raise
  end
end

STDERR.puts "EM.run..."
EM.run {
  STDERR.puts "EM.run &block start"
  conn = Subject.connect('127.0.0.1', 1337)
  STDERR.puts "EM.run &block end"
}
STDERR.puts "EM.run returned"

`ruby bin/em-test`

EM.run...
EM.run &block start
EM.connect...
EM.run &block end
EM::Connection.unbind: Errno::ECONNREFUSED
EM.run returned

`CRASH_EM=1 ruby bin/em-test`

EM.run...
EM.run &block start
EM.connect...
EM.run &block end
EM::Connection.unbind: Errno::ECONNREFUSED
raise crash EventMachine:
bin/em-test:15:in `unbind'
/home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:1481:in `event_callback'
/home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:194:in `run_machine'
/home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:194:in `run'
bin/em-test:25:in `<main>'

/home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:202: [BUG] Segmentation fault at 0x00000000000000
ruby 2.3.1p112 (2016-04-26) [x86_64-linux-gnu]

-- Control frame information -----------------------------------------------
c:0005 p:---- s:0017 e:000016 CFUNC  :release_machine
c:0004 p:0036 s:0014 e:000013 RESCUE /home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:202
c:0003 p:0385 s:0011 e:000010 METHOD /home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:205
c:0002 p:0055 s:0004 E:0002a0 EVAL   bin/em-test:25 [FINISH]
c:0001 p:0000 s:0002 E:0005a0 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------
bin/em-test:25:in `<main>'
/home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:205:in `run'
/home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:202:in `ensure in run'
/home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.2/lib/eventmachine.rb:202:in `release_machine'

The text was updated successfully, but these errors were encountered:

sodabrew · 2017-02-06T10:11:19Z

Thank you! I've got your repro script and PR #766 and now I'm cooking on a fix!

SpComb · 2017-02-20T06:52:13Z

I assume this will be fixed in the 1.2.3 release?

sodabrew · 2017-02-23T05:56:49Z

Please try the new EventMachine 1.2.3 release, it should resolve this crash!

SpComb · 2017-04-12T11:13:46Z

The original repro case still segfaults in eventmachine 1.2.3. It seems to be 100% reproable, re-open or new issue?

`CRASH_EM=1 bundle exec bin/em-test`

EM.run...
EM.run &block start
EM.connect...
EM.run &block end
EM::Connection.unbind: Errno::ECONNREFUSED
raise crash EventMachine:
bin/em-test:15:in `unbind'
/home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:1481:in `event_callback'
/home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:194:in `run_machine'
/home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:194:in `run'
bin/em-test:25:in `<top (required)>'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli/exec.rb:74:in `load'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli/exec.rb:74:in `kernel_load'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli/exec.rb:27:in `run'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:332:in `exec'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor.rb:359:in `dispatch'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:20:in `dispatch'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/base.rb:440:in `start'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:11:in `start'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/exe/bundle:34:in `block in <top (required)>'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/friendly_errors.rb:100:in `with_friendly_errors'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/exe/bundle:26:in `<top (required)>'
/home/kontena/.local/bin/bundle:23:in `load'
/home/kontena/.local/bin/bundle:23:in `<main>'

/home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:202: [BUG] Segmentation fault at 0x00000000000000
ruby 2.3.1p112 (2016-04-26) [x86_64-linux-gnu]

-- Control frame information -----------------------------------------------
c:0020 p:---- s:0098 e:000097 CFUNC  :release_machine
c:0019 p:0036 s:0095 e:000094 RESCUE /home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:202
c:0018 p:0385 s:0092 e:000091 METHOD /home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:205
c:0017 p:0055 s:0085 E:000e10 TOP    bin/em-test:25 [FINISH]
c:0016 p:---- s:0083 e:000082 CFUNC  :load
c:0015 p:0170 s:0079 e:000078 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli/exec.rb:74
c:0014 p:0089 s:0070 e:000069 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli/exec.rb:27
c:0013 p:0032 s:0066 e:000065 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:332
c:0012 p:0078 s:0062 e:000061 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/command.rb:27
c:0011 p:0058 s:0055 e:000054 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/invocation.rb:126
c:0010 p:0291 s:0049 e:000048 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor.rb:359
c:0009 p:0012 s:0037 e:000036 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:20
c:0008 p:0070 s:0033 e:000032 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/base.rb:440
c:0007 p:0012 s:0027 e:000026 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:11
c:0006 p:0090 s:0022 e:000021 BLOCK  /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/exe/bundle:34
c:0005 p:0006 s:0017 e:000016 METHOD /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/friendly_errors.rb:100
c:0004 p:0172 s:0013 E:001af8 TOP    /home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/exe/bundle:26 [FINISH]
c:0003 p:---- s:0010 e:000009 CFUNC  :load
c:0002 p:0147 s:0006 E:001440 EVAL   /home/kontena/.local/bin/bundle:23 [FINISH]
c:0001 p:0000 s:0002 E:001810 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------
/home/kontena/.local/bin/bundle:23:in `<main>'
/home/kontena/.local/bin/bundle:23:in `load'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/exe/bundle:26:in `<top (required)>'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/friendly_errors.rb:100:in `with_friendly_errors'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/exe/bundle:34:in `block in <top (required)>'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:11:in `start'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/base.rb:440:in `start'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:20:in `dispatch'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor.rb:359:in `dispatch'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli.rb:332:in `exec'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli/exec.rb:27:in `run'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli/exec.rb:74:in `kernel_load'
/home/kontena/.gem/ruby/2.3.0/gems/bundler-1.13.5/lib/bundler/cli/exec.rb:74:in `load'
bin/em-test:25:in `<top (required)>'
/home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:205:in `run'
/home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:202:in `ensure in run'
/home/kontena/kontena/kontena/agent/vendor/bundle/ruby/2.3.0/gems/eventmachine-1.2.3/lib/eventmachine.rb:202:in `release_machine'

-- Machine register context ------------------------------------------------
 RIP: 0x0000000000000000 RBP: 0x0000000000000000 RSP: 0x00007ffe4ad502a8
 RAX: 0x00007f4ee4ee3c98 RBX: 0x00000000020594f0 RCX: 0x0000000001e24f08
 RDX: 0x0000000001e24f00 RDI: 0x0000000002065cc0 RSI: 0x00000000018fa3d0
  R8: 0x0000000000000000  R9: 0x0000000000000000 R10: 0x00007ffe4ad50510
 R11: 0x00000000018fa3d0 R12: 0x00000000018fa3d0 R13: 0x0000000000000000
 R14: 0x00007f4ee9b22b50 R15: 0x0000000001f29950 EFL: 0x0000000000010206

-- C level backtrace information -------------------------------------------
/usr/lib/x86_64-linux-gnu/libruby-2.3.so.2.3 [0x7f4ee9657ca5]
/usr/lib/x86_64-linux-gnu/libruby-2.3.so.2.3 [0x7f4ee9657edc]
/usr/lib/x86_64-linux-gnu/libruby-2.3.so.2.3 [0x7f4ee9531944]
/usr/lib/x86_64-linux-gnu/libruby-2.3.so.2.3 [0x7f4ee95e3c3e]
/lib/x86_64-linux-gnu/libc.so.6 [0x7f4ee91394b0]

-- Other runtime information -----------------------------------------------

<snip>

sodabrew · 2017-04-13T17:30:06Z

Yes, sadly the 1.2.3 release just moved the same crash to a different line. I am working on a followup fix.

franzliedke · 2017-08-29T08:54:04Z

@sodabrew Thanks for your work on this! Any progress with the followup?

franzliedke · 2017-08-30T11:38:34Z

We are experiencing the same segfault. It happens often, but not always. If I understood the discussion here correctly, this has to do with an exception being raised at a time when eventmachine does not correctly deal with it.

As it would help me with debugging the issue on our side: Is there a way to find out what exception is being raised that then triggers the problem in eventmachine? While we wait for a fix in this gem, maybe that will help us work around the issue on our side...

SpComb · 2017-08-30T11:50:25Z

As it would help me with debugging the issue on our side: Is there a way to find out what exception is being raised that then triggers the problem in eventmachine? While we wait for a fix in this gem, maybe that will help us work around the issue on our side...

I don't know if this issue is specific to exceptions raised from unbind handlers, you might try adding rescue => exc; logger.error exc statements to all of your unbind handlers?

Or use ruby -d / $DEBUG = true to have ruby log all raised exceptions... might get verbose :)

For the PoC case, removing the rescue logging, the $DEBUG output looks like this:

Exception `RuntimeError' at ./em-test:17 - crash EventMachine
Exception `RuntimeError' at /home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.5/lib/eventmachine.rb:1498 - crash EventMachine
/home/kontena/.gem/ruby/2.3.0/gems/eventmachine-1.2.5/lib/eventmachine.rb:202: [BUG] Segmentation fault at 0x00000000000000

The eventmachine-1.2.5/lib/eventmachine.rb:1498 line is probably the interesting one here, that's re-raising any exceptions from unbind.

franzliedke · 2017-08-30T14:54:39Z

@SpComb Thanks for the tip!

However, nothing of value was printed out right before the crash (some other warnings and exceptions earlier in the code, but not related to the crash).

SpComb mentioned this issue Feb 1, 2017

Agent: Upgrade to faye-websocket 0.10.7 with connection error reasons, close timeouts kontena/kontena#1757

Merged

arthurdandrea mentioned this issue Feb 1, 2017

Fix segfault when an Exception is raised from unbind callback #766

Merged

sodabrew closed this as completed Feb 23, 2017

SpComb mentioned this issue Apr 12, 2017

Server WebsocketBackend EventMachine watchdog kontena/kontena#2139

Merged

SpComb mentioned this issue Apr 12, 2017

Server EventMachine can segfault on ruby exceptions or watchdog aborts kontena/kontena#2148

Open

sodabrew reopened this Apr 13, 2017

sodabrew added this to the v1.2.4 milestone Apr 13, 2017

sodabrew modified the milestones: v1.2.4, v1.3.0 Jul 27, 2017

sodabrew mentioned this issue Apr 28, 2018

Fix unbind exceptions #835

Merged

sodabrew closed this as completed Apr 28, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Segfault from EM.run after EM::Connection#unbind raises exception #765

Segfault from EM.run after EM::Connection#unbind raises exception #765

SpComb commented Feb 1, 2017

sodabrew commented Feb 6, 2017

SpComb commented Feb 20, 2017

sodabrew commented Feb 23, 2017

SpComb commented Apr 12, 2017 •

edited

Loading

sodabrew commented Apr 13, 2017

franzliedke commented Aug 29, 2017

franzliedke commented Aug 30, 2017

SpComb commented Aug 30, 2017 •

edited

Loading

franzliedke commented Aug 30, 2017

Segfault from EM.run after EM::Connection#unbind raises exception #765

Segfault from EM.run after EM::Connection#unbind raises exception #765

Comments

SpComb commented Feb 1, 2017

ruby bin/em-test

CRASH_EM=1 ruby bin/em-test

sodabrew commented Feb 6, 2017

SpComb commented Feb 20, 2017

sodabrew commented Feb 23, 2017

SpComb commented Apr 12, 2017 • edited Loading

CRASH_EM=1 bundle exec bin/em-test

sodabrew commented Apr 13, 2017

franzliedke commented Aug 29, 2017

franzliedke commented Aug 30, 2017

SpComb commented Aug 30, 2017 • edited Loading

franzliedke commented Aug 30, 2017

`ruby bin/em-test`

`CRASH_EM=1 ruby bin/em-test`

SpComb commented Apr 12, 2017 •

edited

Loading

`CRASH_EM=1 bundle exec bin/em-test`

SpComb commented Aug 30, 2017 •

edited

Loading