newrelic-ruby-agent: `6.14.0` creates infinite recursion on "net request" with rack-mini-profiler present

^^ Provide a general summary of the issue in the title above. ^^

Description

We use fastimage to check the type of image behind the image URLs input by user before saving them. Example code would be something like:

FastImage.type(
  "https://duckduckgo.com/assets/logo_homepage.alt.v108.svg",
  timeout: 5,
).nil?

Expected Behavior

It should work without infinite recursion (SystemStackError: stack level too deep)

Troubleshooting or NR Diag results

Error Backtrace 
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:305:in `hash'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:305:in `lookup_unicode_composition'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:215:in `unicode_compose_pair'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:153:in `block in unicode_compose'
/usr/local/lib/ruby/gems/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/core_ext/range/each.rb:9:in `each'
/usr/local/lib/ruby/gems/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/core_ext/range/each.rb:9:in `each'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:149:in `unicode_compose'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:121:in `unicode_normalize_kc'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/uri.rb:566:in `normalize_component'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/uri.rb:1538:in `block in normalized_path'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/uri.rb:1537:in `map'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/uri.rb:1537:in `normalized_path'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/uri.rb:2171:in `normalize'
/usr/local/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/uri.rb:2184:in `normalize!'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/http_clients/uri_util.rb:35:in `parse_and_normalize_url'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/http_clients/net_http_wrappers.rb:65:in `uri'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/instrumentation/net_prepend.rb:45:in `request'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/patches/net_patches.rb:19:in `block in request_with_mini_profiler'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/mini_profiler/profiling_methods.rb:46:in `step'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/patches/net_patches.rb:18:in `request_with_mini_profiler'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/instrumentation/net_prepend.rb:57:in `block (2 levels) in request'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/tracer.rb:371:in `capture_segment_error'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/instrumentation/net_prepend.rb:56:in `block in request'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent.rb:506:in `disable_all_tracing'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/instrumentation/net_prepend.rb:55:in `request'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/patches/net_patches.rb:19:in `block in request_with_mini_profiler'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/mini_profiler/profiling_methods.rb:46:in `step'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/patches/net_patches.rb:18:in `request_with_mini_profiler'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/instrumentation/net_prepend.rb:57:in `block (2 levels) in request'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/tracer.rb:371:in `capture_segment_error'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/instrumentation/net_prepend.rb:56:in `block in request'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent.rb:506:in `disable_all_tracing'
/usr/local/lib/ruby/gems/2.7.0/gems/newrelic_rpm-6.14.0/lib/new_relic/agent/instrumentation/net_prepend.rb:55:in `request'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/patches/net_patches.rb:19:in `block in request_with_mini_profiler'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/mini_profiler/profiling_methods.rb:46:in `step'
/usr/local/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.2.0/lib/patches/net_patches.rb:18:in `request_with_mini_profiler'

Steps to Reproduce

begin
  parsed_uri = URI.parse("https://duckduckgo.com/assets/logo_homepage.alt.v108.svg")
  http = Net::HTTP.new(parsed_uri.host, parsed_uri.port)
  response = http.request_get(parsed_uri.request_uri, {'Accept-Encoding' => 'identity'})
  response.code
rescue SystemStackError => ex
  puts ex.backtrace
  raise
end

Your Environment

Include as many relevant details about your environment as possible including the running version of the Ruby agent, the Ruby version being used and any other relevant environment information

  • Docker with Ubuntu 18.04 LTS, same for Docker host
  • Ruby 2.7.2, Rails 6.0.3.4
  • rack-mini-profiler (2.2.0)
  • newrelic_rpm (6.14.0)

Additional context

newrelic_rpm (6.13.1) has no such issue This can only be reproduced on production like environment (This issue first affects production env & later reproduced on staging)

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Reactions: 5
  • Comments: 20 (6 by maintainers)

Most upvoted comments

@mwlang we’re having the issue with ruby 2.6.6 here is the stacktrace:

➜ rails s
=> Booting Puma
=> Rails 5.2.3 application starting in development
=> Run `rails server -h` for more startup options
Exiting
Traceback (most recent call last):
	10377: from bin/rails:13:in `<main>'
	10376: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/activesupport-5.2.3/lib/active_support/dependencies.rb:291:in `require'
	10375: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/activesupport-5.2.3/lib/active_support/dependencies.rb:257:in `load_dependency'
	10374: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/activesupport-5.2.3/lib/active_support/dependencies.rb:291:in `block in require'
	10373: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:29:in `require'
	10372: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:20:in `require_with_bootsnap_lfi'
	10371: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/loaded_features_index.rb:65:in `register'
	10370: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:21:in `block in require_with_bootsnap_lfi'
	 ... 10365 levels...
	    4: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/activesupport-5.2.3/lib/active_support/core_ext/range/each.rb:9:in `each'
	    3: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/activesupport-5.2.3/lib/active_support/core_ext/range/each.rb:9:in `each'
	    2: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:153:in `block in unicode_compose'
	    1: from /Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:215:in `unicode_compose_pair'
/Users/jeremy/.rvm/gems/ruby-2.6.6@appaloosa/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:305:in `lookup_unicode_composition': stack level too deep (SystemStackError)

Please don’t hesitate to let me know if you need more informations.

+3
jeremybdk on Dec 1, 2020

@angelatan2 - We just removed New Relic completely from our system. The fact that feature version bump causes such a major issue for us means we decided New Relic wasn’t worth the potentially damage. So I won’t be able share any more details other than below.

But basically we had an impossible to find where it occurred error, that ended up with

addressable-2.7.0/lib/addressable/idna/pure.rb:305:in `hash': stack level too deep (SystemStackError)

<190>1 2020-11-26T22:10:06.81121+00:00 app worker.1 - - /app/vendor/bundle/ruby/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:305:in `hash': stack level too deep (SystemStackError)
	from /app/vendor/bundle/ruby/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:305:in `lookup_unicode_composition'
	from /app/vendor/bundle/ruby/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:215:in `unicode_compose_pair'
	from /app/vendor/bundle/ruby/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:153:in `block in unicode_compose'
	from /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/core_ext/range/each.rb:9:in `each'
	from /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/core_ext/range/each.rb:9:in `each'
	from /app/vendor/bundle/ruby/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:149:in `unicode_compose'
	from /app/vendor/bundle/ruby/2.7.0/gems/addressable-2.7.0/lib/addressable/idna/pure.rb:121:in `unicode_normalize_kc'
	from /app/vendor/bundle/ruby/2.7.0/gems/addressable-2.7.0/lib/addressable/uri.rb:566:in `normalize_component

We are just a standard RoR app, and there was no reference to new relic. We just had to revert gems until we pinpointed the new relic agent.

We think it may have happened when we were sending off analytics and subscription data to third party services. As it seemed to have happened after our sign up form submission, but before the account was finished being created.

+3
ro-savage on Dec 1, 2020

@mwlang thanks for your help explaining and resolving the issue. We had the same problem using Skylight, because they are still using alias_method https://github.com/skylightio/skylight-ruby/issues/155. Maybe you want to add it to your fix.

+2
hector-able on Dec 5, 2020

This should be fixed by making the option prepend_net_instrumentation false by default And have a warning in doc for setting it to true

+2
PikachuEXE on Nov 30, 2020

@angelatan2 better than that! I spent some time, creating a new rails app, adding all my gems, reproducing the crash, and removing most of my gems to see which ones was making the app crash. The weird thing is that it’s not one gem that trigger the crash, it’s only when I have the gems left in this Gemfile. You can find a link to the app here: https://github.com/jeremybdk/crash_newrelic

I hope that will help you 😃

+1
jeremybdk on Dec 1, 2020

I had the same problem, the commit that introduced the regression was: https://github.com/newrelic/newrelic-ruby-agent/commit/cde7d105cb669f6a9b2afa93076c9b1dd88b1bd5

Setting prepend_net_instrumentation: false on config/newrelic.yml fixes the problem.

+1
tiagotex on Nov 27, 2020
Read more comments on GitHub
← newrelic-python-agent: Issue running starlette: TypeError: _run_asgi2() takes 2 positional arguments but 4 were given
newrelic-ruby-agent: Delayed job deadlocks in development →