Dd-trace-rb: Segmentation fault on exit while tracing mongodb

[cjford]

Hello, we've been encountering segmentation faults that seem related to ddtrace and were hoping you could help with debugging.

Here is a minimal reproduction app: https://github.com/cjford/ddtrace-repro
It assumes mongodb reachable at mongodb://0.0.0.0:27017/development and datadog-agent running with default configuration. You can run it with bundle exec ruby app.rb

On Catalina 10.15.6, I get the following output (no backtrace or crash reports present):

[2020-11-04T18:56:00.134787 #43967]  INFO -- ddtrace: [ddtrace] DATADOG TRACER CONFIGURATION - {"date":"2020-11-04T18:56:00-07:00","os_name":"x86_64-apple-darwin19.2.0","version":"0.41.0","lang":"ruby","lang_version":"2.6.5","enabled":true,"agent_url":"http://127.0.0.1:8126?timeout=1","debug":false,"analytics_enabled":false,"runtime_metrics_enabled":false,"integrations_loaded":"[email protected]","vm":"ruby-2.6.5","partial_flushing_enabled":false,"priority_sampling_enabled":false,"health_metrics_enabled":false,"integration_mongo_analytics_enabled":"false","integration_mongo_analytics_sample_rate":"1.0","integration_mongo_enabled":"true","integration_mongo_service_name":"mongo","integration_mongo_quantize":"{:show=\u003e[:collection, :database, :operation]}"}
[BUG] Segmentation fault at 0x0000000000000040
ruby 2.6.5p114 (2019-10-01 revision 67812) [x86_64-darwin19]

-- Crash Report log information --------------------------------------------
   See Crash Report log file under the one of following:
     * ~/Library/Logs/DiagnosticReports
     * /Library/Logs/DiagnosticReports
   for more details.
Don't forget to include the above Crash Report log file in bug reports.

-- Machine register context ------------------------------------------------
 rax: 0x0000000000000000 rbx: 0x00007fba4a240003 rcx: 0x0000000000000000
 rdx: 0x000000010d7f60f0 rdi: 0x00007fba4a240003 rsi: 0x0000000000000000
 rbp: 0x000070000955cd20 rsp: 0x000070000955cd20  r8: 0x0000000000000000
  r9: 0x00007fba51ef6578 r10: 0x00007fba51ef6570 r11: 0x00007fba51ef6574
 r12: 0x00007fba51ef8cb0 r13: 0x000070000955cf28 r14: 0x000070000955cd30
 r15: 0x00007fba4e3f4000 rip: 0x000000010d5dec38 rfl: 0x0000000000010206

-- C level backtrace information -------------------------------------------

We've also observed this in live environments, here's a log that includes a stack trace (Debian 9, kernel v4.19.132-1):

PROD-read_only [37] pry(main)> exit
/bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:149: [BUG] Segmentation fault at 0x0000000000000bb0
ruby 2.6.5p114 (2019-10-01 revision 67812) [x86_64-linux]

-- Control frame information -----------------------------------------------
c:0021 p:0010 s:0109 e:000105 METHOD /bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:149
c:0020 p:0033 s:0101 e:000100 METHOD /bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:98
c:0019 p:0025 s:0092 e:000091 METHOD /bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:669
c:0018 p:0290 s:0087 e:000086 METHOD /bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:664
c:0017 p:0048 s:0076 e:000075 METHOD /bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:395
c:0016 p:0076 s:0069 e:000068 METHOD /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/metrics.rb:93
c:0015 p:0009 s:0060 e:000059 BLOCK  /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:57 [FINISH]
c:0014 p:---- s:0055 e:000054 CFUNC  :each
c:0013 p:0021 s:0051 e:000050 BLOCK  /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:57
c:0012 p:0002 s:0048 e:000047 METHOD /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:69
c:0011 p:0027 s:0043 e:000042 METHOD /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:57
c:0010 p:0007 s:0039 e:000038 METHOD /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/runtime_metrics.rb:33
c:0009 p:0010 s:0035 e:000034 BLOCK  /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:17
c:0008 p:0009 s:0032 e:000031 BLOCK  /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:83 [FINISH]
c:0007 p:---- s:0029 e:000028 CFUNC  :loop
c:0006 p:0010 s:0025 e:000024 METHOD /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:80
c:0005 p:0005 s:0021 e:000020 METHOD /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:17
c:0004 p:0012 s:0016 e:000013 BLOCK  /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/async.rb:21
c:0003 p:0003 s:0011 e:000010 BLOCK  /bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/async.rb:128
c:0002 p:0041 s:0007 e:000006 BLOCK  /bundle/ruby/2.6.0/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474 [FINISH]
c:0001 p:---- s:0003 e:000002 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------
/bundle/ruby/2.6.0/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/async.rb:128:in `block in start_worker'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/async.rb:21:in `block in perform'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:17:in `perform'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:80:in `perform_loop'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:80:in `loop'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:83:in `block in perform_loop'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/loop.rb:17:in `block in perform'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/workers/runtime_metrics.rb:33:in `perform'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:57:in `flush'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:69:in `try_flush'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:57:in `block in flush'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:57:in `each'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/runtime/metrics.rb:57:in `block (2 levels) in flush'
/bundle/ruby/2.6.0/gems/ddtrace-0.41.0/lib/ddtrace/metrics.rb:93:in `gauge'
/bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:395:in `gauge'
/bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:664:in `send_stats'
/bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:669:in `send_stat'
/bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:98:in `write'
/bundle/ruby/2.6.0/gems/dogstatsd-ruby-4.6.0/lib/datadog/statsd.rb:149:in `send_message'

-- Machine register context ------------------------------------------------
 RIP: 0x00007f75a840ad81 RBP: 0x00007f75a052d9c0 RSP: 0x00007f75a052d9b8
 RAX: 0x0000000000000bb0 RBX: 0x0000000000000ba1 RCX: 0x00000000000000ba
 RDX: 0x00007f75a052d9c0 RDI: 0x00007f75820a5500 RSI: 0x00000000000000ba
  R8: 0x00000000000003ff  R9: 0x0000000000000010 R10: 0x0000000000000000
 R11: 0x00007f7590e21eb0 R12: 0x00000feeb1c1802e R13: 0x00007f758e0c5c78
 R14: 0x00007f75a052da18 R15: 0x00007f758e0a6710 EFL: 0x0000000000010202

-- C level backtrace information -------------------------------------------

The above examples are both triggered when calling exit from a ruby repl, after making a mongo query with dd tracing enabled. We've also observed it from our web server processes when they are shutting down. In these cases the backtrace points to puma, but I suspect it's the same root cause since the application code also traces mongo queries and triggers an exit. I'll leave out that log to reduce clutter, but let me know if you think it would be helpful.

We've isolated the cause of the error to version 0.38.0 of ddtrace, specifically this code change: https://github.com/DataDog/dd-trace-rb/pull/1091. By starting with 0.41.0 and manually reverting only the above diff, we can no longer produce the error.

Thanks for reading, let me know if you have any ideas on causes/fixes or need any other info.

[ericmustin]

@cjford Thanks for the report here and reproduction. We're looking into this, we'll try to update the issue here when we've determined a fix, I would say for now you'll want to disable the mongo instrumentation.

[marcotc]

Setup

First, I tried to reproduce it on a Linux environment (debian:bullseye), to allow me to use tools like gdb to debug the issue, but the program runs without error.

On Catalina 10.15.7 it reliably crashes or aborts, as originally reported.

I was able to capture the moment the application crashes using a debugger (lldb) to a Ruby 2.6.5 VM built with debug symbols, this brought a little more clarity to the crashes.

Investigation

The application consistently crashes due to iseq objects having a corrupted or null iseq->body. It crashes most commonly on this line, when trying to access location.pathobj: https://github.com/ruby/ruby/blob/v2_6_5/iseq.c#L946

The abort error timeout.rb:97: [BUG] sleeper must not be more than vm_living_thread_num(vm) happens when call Net::HTTP#start with open_timeout greater than zero. This causes Timeout.timeout[https://github.com/ruby/ruby/blob/v2_6_5/lib/timeout.rb#L76-L97] be executed, which creates a thread that eventually aborts the app on Thread#join.

Setting open_timeout in ddtrace makes the [BUG] sleeper must not be more than vm_living_thread_num(vm) abort stop, but bring us back to a segfault. The segfault happens in a variety of lines, but they all still crash for the same reason: corrupted or null iseq->body.

Running with newer versions of Ruby (up to 2.7.2) yield the same errors.

Takeaways

I wasn't able to find a definitive source causing the issue. The only gem with native code in our gemset is bson, and I wasn't able to find any crashes similar to this one.
There are also no similar Ruby VM bugs that were reported or fixed.

On the bright side I did find a way around these issues: use Ruby 3.0 :)
The crashes and abort don't happen when running with Ruby 3.0.0-preview1.
They also don't seem to be reproducible on Linux, only Mac.

Overall, there is still work to investigate the internals of mongoid/mongo/bson gems if we want to pinpoint where that intersects with ddtrace.

[oriahu]

Hello 👋 . Here is a patch file to be applied to @cjford original minimal reproduction app repo.Hopefully a way to reproduce within a linux docker container. Hopefully this works for you.

Was also playing around with it to see if i could reproduce a related exception that appears to happen when our pods / containers are shutdown gracefully. Appeared to happen also when making mongo queries, but through puma -> rack -> mongo.

FYI: Just notice that the ruby version in this patch is 2.6.6, and that puma is version 4.3.6. Though I did try upgrading puma to 5+ too. I tried adding a sleep of 3 seconds to the endpoint for /mongo_create_and_save, though I think it makes no difference...

Hopefully this helps in some way!

0001-Repro-in-docker-container.patch.zip

• to be applied to the ddtrace-repro repo

root@docker-desktop:/app# uname -a
Linux docker-desktop 5.4.39-linuxkit #1 SMP Fri May 8 23:03:06 UTC 2020 x86_64 GNU/Linux

UPDATE: Pull Request on @cjford's repro app repo https://github.com/cjford/ddtrace-repro/pull/1

[oriahu]

We noticed this recent fix, thanks for taking a look into this!

We were wondering roughly when 0.43.0 will be released?

[marcotc]

@oriahu Thank you for the info! We are planning on releasing it as soon as we have confirmation that the PR addresses the underlying issue. We are working with a partner to test this PR at this moment.

If you are experiencing this same issue in your application, it would be invaluable if you were able to deploy our prerelease version containing https://github.com/DataDog/dd-trace-rb/pull/1248 and report if it fixes the issue:

source 'http://gems.datadoghq.com/prerelease' do
  gem 'ddtrace', '0.42.0.fix.shutdown.writer.96817'
end

The prerelease based on 0.42.0, so keep this in mind if you currently have an older version installed.

[keiko713]

We've been seeing segmentation faults, as well as memory bloat / memory leak issue starting with 0.38.0 too. We just tried #1248 version and it has fixed both issues with our application! Thanks for the fix!

[marcotc]

👋 @cjford and @keiko713! We've shipped a fix for this issue in 0.43.0.

Please let us now if you still have any feedback on it.

[cjford]

@marcotc Thank you for the quick fix! We deployed the update and can confirm it's solved the errors for the case of exiting a console.

We do still see some seg faults during Puma shutdown. I think at this point we can assume that is an unrelated issue, but will keep working on a better repro case and report back if it looks like that's not the case.