SystemStackError with rack-mini-profiler 3.0.0 and pg integration

victormartins commented 2 years ago

Current behaviour If we have these two gems together

gem "rack-mini-profiler", require: false
gem "ddtrace", "~> 1.5.1", require: "ddtrace/auto_instrument" # enables tracing for Datadog

And then when a Rails application loads we do: require "rack-mini-profiler"

When we boot the server with ./bin/rails s we get a SystemStackError

/Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.5.1/lib/datadog/tracing/contrib/registry.rb:36:in `[]': stack level too deep (SystemStackError)
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.5.1/lib/datadog/tracing/contrib/extensions.rb:179:in `fetch_integration'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.5.1/lib/datadog/tracing/contrib/extensions.rb:157:in `[]'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.5.1/lib/datadog/tracing/contrib/pg/instrumentation.rb:114:in `datadog_configuration'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.5.1/lib/datadog/tracing/contrib/pg/instrumentation.rb:77:in `trace'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.5.1/lib/datadog/tracing/contrib/pg/instrumentation.rb:39:in `async_exec'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/db/pg.rb:110:in `async_exec'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.5.1/lib/datadog/tracing/contrib/pg/instrumentation.rb:40:in `block in async_exec'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/ddtrace-1.5.1/lib/datadog/tracing/contrib/pg/instrumentation.rb:82:in `block in trace'
    ... 7948 levels...
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/railties-7.0.4/lib/rails/commands.rb:18:in `<main>'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.13.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
    from /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/bootsnap-1.13.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
    from ./bin/rails:4:in `<main>'

Expected behaviour The Rails app should boot normally.

Steps to reproduce Have these two gems together in the Gemfile

gem "rack-mini-profiler", require: false
gem "ddtrace", "~> 1.5.1", require: "ddtrace/auto_instrument" # enables tracing for Datadog

And then add this to config/initializers/rack_profiler.rb require "rack-mini-profiler"

Then run the Rails server:

./bin/rails s

How does ddtrace help you? We use ddtrace to ingest and monitor our application logs.

Environment

ddtrace version: 1.5.1

Configuration block (Datadog.configure ...): This is happening in our development environment so we only have these settings.

Datadog.configure do |config|
config.diagnostics.startup_logs.enabled = false
config.profiling.enabled = false
config.tracing.enabled = false
end

Ruby version: 3.1.2
Operating system: OSX 12.6
Relevant library versions:
```
rack-mini-profiler v3.0.0
pg v1.4.4
```

victormartins commented 2 years ago

It seems we can bypass this problem if we set DD_TRACE_PG_ENABLED=false when loading the rack-mini-profiler library.

TonyCTHsu commented 2 years ago

👋 @victormartins , thanks for reporting, we will be looking into it!

victormartins commented 2 years ago

Hello @TonyCTHsu 👋

Unfortunately PG was not the only integration causing a SystemStackError, today we got other stack trace, this time with timer_struct/request.rb We were able to bypass this one by setting DD_TRACE_HTTP_ENABLED=false

I wonder if there is a better ENV var we could set to completely disable ddtrace if rack-mini-profiler is loaded?

[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] SystemStackError (stack level too deep):
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0]   
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
(...) many many more of these
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:174:in `adjust_depth'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/timer_struct/request.rb:100:in `move_child'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler_rails/railtie_methods.rb:26:in `block in render_notification_handler'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler_rails/railtie_methods.rb:26:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler_rails/railtie_methods.rb:26:in `render_notification_handler'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler_rails/railtie.rb:100:in `block in initialize!'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler_rails/railtie.rb:134:in `block in subscribe'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/fanout.rb:253:in `finish'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/fanout.rb:76:in `block in finish'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/fanout.rb:91:in `block in iterate_guarding_exceptions'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/fanout.rb:90:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/fanout.rb:90:in `iterate_guarding_exceptions'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/fanout.rb:76:in `finish'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/instrumenter.rb:49:in `finish_with_state'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/instrumenter.rb:30:in `ensure in instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/instrumenter.rb:30:in `instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications.rb:206:in `instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/renderer/template_renderer.rb:60:in `block in render_template'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/renderer/template_renderer.rb:75:in `block in render_with_layout'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications.rb:206:in `block in instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications.rb:206:in `instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/renderer/template_renderer.rb:74:in `render_with_layout'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/renderer/template_renderer.rb:59:in `render_template'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/renderer/template_renderer.rb:11:in `render'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/renderer/renderer.rb:61:in `render_template_to_object'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/renderer/renderer.rb:29:in `render_to_object'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/rendering.rb:117:in `block in _render_template'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/base.rb:270:in `in_rendering_context'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/rendering.rb:116:in `_render_template'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/streaming.rb:216:in `_render_template'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/rendering.rb:103:in `render_to_body'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/rendering.rb:46:in `render_to_body'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/renderers.rb:141:in `render_to_body'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/abstract_controller/rendering.rb:25:in `render'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/rendering.rb:30:in `render'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/instrumentation.rb:22:in `block (2 levels) in render'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] /Users/victormartins/.rbenv/versions/3.1.2/lib/ruby/3.1.0/benchmark.rb:311:in `realtime'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/core_ext/benchmark.rb:14:in `ms'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/instrumentation.rb:22:in `block in render'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/instrumentation.rb:91:in `cleanup_view_runtime'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activerecord (7.0.4) lib/active_record/railties/controller_runtime.rb:34:in `cleanup_view_runtime'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/instrumentation.rb:21:in `render'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] wicked_pdf (2.6.3) lib/wicked_pdf/pdf_helper.rb:18:in `render'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/implicit_render.rb:35:in `default_render'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/basic_implicit_render.rb:6:in `block in send_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] <internal:kernel>:90:in `tap'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/abstract_controller/base.rb:215:in `process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] ddtrace (1.5.1) lib/datadog/tracing/contrib/action_pack/action_controller/instrumentation.rb:129:in `process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/rendering.rb:53:in `process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/abstract_controller/callbacks.rb:234:in `block in process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/callbacks.rb:118:in `block in run_callbacks'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] react-rails (2.6.2) lib/react/rails/controller_lifecycle.rb:31:in `use_react_component_helper'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] ahoy_matey (4.1.0) lib/ahoy/controller.rb:45:in `set_ahoy_request_store'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actiontext (7.0.4) lib/action_text/rendering.rb:20:in `with_renderer'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actiontext (7.0.4) lib/action_text/engine.rb:69:in `block (4 levels) in <class:Engine>'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/callbacks.rb:127:in `instance_exec'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/callbacks.rb:138:in `run_callbacks'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/abstract_controller/callbacks.rb:233:in `process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/rescue.rb:22:in `process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications.rb:206:in `block in instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/notifications.rb:206:in `instrument'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/instrumentation.rb:66:in `process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activerecord (7.0.4) lib/active_record/railties/controller_runtime.rb:27:in `process_action'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/abstract_controller/base.rb:151:in `process'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionview (7.0.4) lib/action_view/rendering.rb:39:in `process'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal.rb:188:in `dispatch'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_controller/metal.rb:251:in `dispatch'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/routing/route_set.rb:32:in `serve'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/journey/router.rb:50:in `block in serve'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/journey/router.rb:32:in `each'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/journey/router.rb:32:in `serve'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/routing/route_set.rb:852:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/static.rb:23:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] bullet (7.0.3) lib/bullet/rack.rb:12:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-attack (6.6.1) lib/rack/attack.rb:127:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-contrib (2.3.0) lib/rack/contrib/locale.rb:18:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] clearance (2.6.1) lib/clearance/rack_session.rb:23:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/tempfile_reaper.rb:15:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/etag.rb:27:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/conditional_get.rb:27:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/head.rb:12:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/http/permissions_policy.rb:38:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/http/content_security_policy.rb:36:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/session/abstract/id.rb:266:in `context'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/session/abstract/id.rb:260:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/cookies.rb:696:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activerecord (7.0.4) lib/active_record/migration.rb:603:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/callbacks.rb:99:in `run_callbacks'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/executor.rb:14:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] bugsnag (6.24.2) lib/bugsnag/integrations/rack.rb:51:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] ddtrace (1.5.1) lib/datadog/tracing/contrib/rails/middlewares.rb:19:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] web-console (4.2.0) lib/web_console/middleware.rb:132:in `call_app'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] web-console (4.2.0) lib/web_console/middleware.rb:28:in `block in call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] web-console (4.2.0) lib/web_console/middleware.rb:17:in `catch'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] web-console (4.2.0) lib/web_console/middleware.rb:17:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/show_exceptions.rb:26:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] railties (7.0.4) lib/rails/rack/logger.rb:40:in `call_app'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] railties (7.0.4) lib/rails/rack/logger.rb:25:in `block in call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/tagged_logging.rb:99:in `block in tagged'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/tagged_logging.rb:37:in `tagged'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/tagged_logging.rb:99:in `tagged'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] railties (7.0.4) lib/rails/rack/logger.rb:25:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] ahoy_matey (4.1.0) lib/ahoy/engine.rb:22:in `call_with_quiet_ahoy'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] sprockets-rails (3.4.2) lib/sprockets/rails/quiet_assets.rb:13:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/remote_ip.rb:93:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] request_store (1.5.1) lib/request_store/middleware.rb:19:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/request_id.rb:26:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/method_override.rb:24:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/runtime.rb:22:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rails-autoscale-core (1.1.0) lib/rails_autoscale/request_middleware.rb:41:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] activesupport (7.0.4) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/server_timing.rb:61:in `block in call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/server_timing.rb:26:in `collect_events'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/server_timing.rb:60:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/executor.rb:14:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/static.rb:23:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack (2.2.4) lib/rack/sendfile.rb:110:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] actionpack (7.0.4) lib/action_dispatch/middleware/host_authorization.rb:137:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-utf8_sanitizer (1.7.0) lib/rack/utf8_sanitizer.rb:22:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-cors (1.1.1) lib/rack/cors.rb:100:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] ddtrace (1.5.1) lib/datadog/tracing/contrib/rack/middlewares.rb:85:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] rack-mini-profiler (3.0.0) lib/mini_profiler/profiler.rb:393:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] railties (7.0.4) lib/rails/engine.rb:530:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] puma (5.6.5) lib/puma/configuration.rb:252:in `call'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] puma (5.6.5) lib/puma/request.rb:77:in `block in handle_request'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] puma (5.6.5) lib/puma/thread_pool.rb:340:in `with_force_shutdown'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] puma (5.6.5) lib/puma/request.rb:76:in `handle_request'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] puma (5.6.5) lib/puma/server.rb:443:in `process_client'
[dd.service=easol dd.trace_id=38196853596244446 dd.span_id=0] puma (5.6.5) lib/puma/thread_pool.rb:147:in `block in spawn_thread'

TonyCTHsu commented 2 years ago

@victormartins 👋

I can reproduce this with only the

gem "ddtrace", "~> 1.5.1", require: "ddtrace/auto_instrument"

and require "rack-mini-profiler" in the initializer

It is caused by our writer trying to send traces through net/http, which rack-mini-profiler also patched.

Traceback (most recent call last):
    9362: from /vendor/dd-trace-rb/lib/datadog/tracing/workers.rb:73:in `block (2 levels) in start'
    9361: from /vendor/dd-trace-rb/lib/datadog/tracing/workers.rb:112:in `perform'
    9360: from /vendor/dd-trace-rb/lib/datadog/tracing/workers.rb:112:in `loop'
    9359: from /vendor/dd-trace-rb/lib/datadog/tracing/workers.rb:113:in `block in perform'
    9358: from /vendor/dd-trace-rb/lib/datadog/tracing/workers.rb:55:in `callback_traces'
    9357: from /vendor/dd-trace-rb/lib/datadog/tracing/writer.rb:74:in `block in start_worker'
    9356: from /vendor/dd-trace-rb/lib/datadog/tracing/writer.rb:114:in `send_spans'
    9355: from /vendor/dd-trace-rb/lib/ddtrace/transport/traces.rb:153:in `send_traces'
     ... 9350 levels...
       4: from /vendor/dd-trace-rb/lib/datadog/tracing/contrib/http/instrumentation.rb:37:in `request'
       3: from /vendor/dd-trace-rb/lib/datadog/tracing/contrib/http/instrumentation.rb:123:in `datadog_configuration'
       2: from /vendor/dd-trace-rb/lib/datadog/tracing/contrib/extensions.rb:157:in `[]'
       1: from /vendor/dd-trace-rb/lib/datadog/tracing/contrib/extensions.rb:179:in `fetch_integration'
/vendor/dd-trace-rb/lib/datadog/tracing/contrib/registry.rb:36:in `[]': stack level too deep (SystemStackError)

I realized this is a known issue from rack-mini-profiler, for details, see the references below:

https://github.com/DataDog/dd-trace-rb/blob/master/docs/GettingStarted.md#stack-level-too-deep https://github.com/MiniProfiler/rack-mini-profiler#nethttp-stack-level-too-deep-errors

victormartins commented 2 years ago

hey @TonyCTHsu, thank you for the information above.

After reading the docs above we see that if we add the following in the Gemfile it does prevent the SystemStackError during HTTP requests, so we no longer have to set DD_TRACE_HTTP_ENABLED=false but it does not prevent the errors with the Postgres gem pg so we still have to set DD_TRACE_PG_ENABLED=false.

  gem 'rack-mini-profiler', require: ['prepend_net_http_patch']

I was wondering if there is like a global switch to turn ddtrace off when rack-mini-profiler is loaded? We tried these but they didn't work:

DD_TRACE_ENABLED=false
DD_TRACE_RACK_ENABLED=false
DD_TRACE_RAILS_ENABLED=false

TonyCTHsu commented 2 years ago

I think currently there is no way we could remove a patch when auto instrumented.

However, I was able to run an auto instrumented Rails app successfully, without the initializer and environment variables.

gem 'rack-mini-profiler', require: ['prepend_net_http_patch', 'rack-mini-profiler']
gem "ddtrace", require: "ddtrace/auto_instrument"

Have you try this?

victormartins commented 2 years ago

hey @TonyCTHsu

Just went back to basics to pinpoint the issue. Created a new Rails App from scratch and just adding the gems normally will make it work.

This is the breaking change, where we load rack-mini-profiler conditionally in an initializer.

if ENV["ENABLE_PROFILER"]
  require "rack-mini-profiler"
  Rack::MiniProfilerRails.initialize!(Rails.application)
end

With that change in place we have this:

This will work and we can render the root page since we don't load rack-mini-profiler
./bin/rails s

This will cause a SystemStackError when we reload root page
ENABLE_PROFILER=1 ./bin/rails s

This will work again because we disable the PG integration
DD_TRACE_PG_ENABLED=false ENABLE_PROFILER=1 ./bin/rails s

So I guess that the issue is that when we load the profiler it's already late?

marcotc commented 2 years ago

👋 @victormartins, we've recently introduced pg instrumentation, thus this is a rather new issue.

The root cause is the same as the SystemStackError that's fixed by setting prepend_net_http_patch, but this one is pg related, not http related.

I noticed that the rack-mini-profiler has a workaround for both Net::HTTP and mysql2, but not for pg: https://cs.github.com/MiniProfiler/rack-mini-profiler?q=path%3Aprepend

At this moment, your only option is to not load both rack-mini-profiler and ddtrace's pg integration at the same time.

I'm thinking we can prevent loading pg if we know rack-mini-profiler is loaded.

@victormartins, can you add this to your application, in the initialization process before Bundler.require(*Rails.groups) in your config/application.rb:

module Datadog
  module Tracing
    module Contrib
      module Pg
        class Integration
          class << self
            prepend(Module.new do
              def compatible?
                super && ENV['ENABLE_PROFILER'] != '1'
              end
            end)
          end
        end
      end
    end
  end
end

I played around with a couple different approaches, but they both have issues:

# Doesn't not prevent user from loading `Rack::MiniProfiler` later
defined?(::Rack::MiniProfiler)

# Disables `pg` integration just by having `rack-mini-profiler` in the Gemfile.
# This means you can't disable `rack-mini-profiler` easily to reenable the `pg` integration.
Gem.loaded_specs['rack-mini-profiler']

Gem.loaded_specs['rack-mini-profiler'] might actually be reasonable, given the critically of having a SystemStackError is pretty severe.

victormartins commented 2 years ago

hey @marcotc thank you for getting back to us 🙏

From our side fell free to close this issue, since we now know what is going on and have a work around for it 👍 or you may want to keep it open for any further internal development.

Thank you for the help guys 🍻

marcotc commented 2 years ago

👍 @victormartins, I've updated the title so it's easier for us to track. I'll leave it as a way to track future work for us.

The solution is to add support for prepend style patching for pg in the rack-mini-profiler gem.

DataDog / dd-trace-rb

SystemStackError with rack-mini-profiler 3.0.0 and pg integration #2348