Closed saulshanabrook closed 1 year ago
@saulshanabrook Thanks for reporting this, but can you simplify the reproduction steps down to just a Ruby/Rails application? The amount of dependencies and manual operations required to run it seems to be quite high:
/etc/hosts
I gave up on step 3 because I don't feel comfortable changing system configs (even harmless) for reproducing an issue that doesn't require it.
@saulshanabrook also is this a regression introduced by 5.8.0 (since that's the version in your issue) or does it also happen on older versions?
ok so what is happening is this super
is going back to the same patched request
for some reason, still don't know why.
https://github.com/getsentry/sentry-ruby/blob/a7bc13ed200756aea00a3ed8a3e0abe0715e6ab9/sentry-ruby/lib/sentry/net/http.rb#L35
@saulshanabrook can you print Net::HTTP.ancestors
after sticking a binding.pry/debugger
in your rake task?
@st0012 Yeah, that totally makes sense about the complicated reproduction steps.
I have tested this to reproduce the bug, which doesn't require messing with hosts, getting a sentry config, or having a domain:
$ git clone https://github.com/saulshanabrook/discourse-hosting
$ cd discourse-hosting
$ echo 'HOSTNAME=any-domain.com' > .env
$ docker compose run --rm upload_assets
Let me know if that doesn't work to reproduce it.
@sl0thentr0py I was just starting to use sentry with this project. I tried it with 5.7.0 a few weeks ago when that was the latest, was hitting the same error, upgraded to 5.8.0 to see if it would fix it but to no avail. Do you recommend I try downgrading to an earlier version?
@sl0thentr0py Sure, is this what you mean? I believe it's [Sentry::Net::HTTP]
$ docker compose run --rm upload_assets rdbg -c -- bundle exec rake --trace s3:upload_assets
WARN[0000] The "SEND_GRID_API_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "SECRET_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "DSN" variable is not set. Defaulting to a blank string.
WARN[0000] The "DSN" variable is not set. Defaulting to a blank string.
WARN[0000] The "EMAIL" variable is not set. Defaulting to a blank string.
WARN[0000] The "SECRET_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "SEND_GRID_API_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "DSN" variable is not set. Defaulting to a blank string.
WARN[0000] The "DSN" variable is not set. Defaulting to a blank string.
WARN[0000] The "SECRET_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "SEND_GRID_API_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "DSN" variable is not set. Defaulting to a blank string.
WARN[0000] The "SEND_GRID_API_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "SECRET_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "EMAIL" variable is not set. Defaulting to a blank string.
WARN[0000] The "SEND_GRID_API_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "EMAIL" variable is not set. Defaulting to a blank string.
WARN[0000] The "SEND_GRID_API_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "EMAIL" variable is not set. Defaulting to a blank string.
WARN[0000] The "SEND_GRID_API_KEY" variable is not set. Defaulting to a blank string.
WARN[0000] The "EMAIL" variable is not set. Defaulting to a blank string.
WARN[0000] The "SEND_GRID_API_KEY" variable is not set. Defaulting to a blank string.
[+] Running 4/0
⠿ Container discourse-hosting-minio-1 Running 0.0s
⠿ Container discourse-hosting-redis-1 Running 0.0s
⠿ Container discourse-hosting-db-1 Running 0.0s
⠿ Container discourse-hosting-glitchtip-web-1 Running 0.0s
[4, 13] in /usr/local/bin/rake
4| #
5| # The application 'rake' is installed as part of a gem, and
6| # this file is here to facilitate running it.
7| #
8|
=> 9| require 'rubygems'
10|
11| Gem.use_gemdeps
12|
13| version = ">= 0.a"
=>#0 <top (required)> at /usr/local/bin/rake:9
#1 [C] Kernel.load at /usr/local/bundle/gems/bundler-2.3.22/lib/bundler/cli/exec.rb:58
# and 14 frames (use `bt' command for all frames)
(rdbg) b /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb:35 # break command
#0 BP - Line (pending) /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb:35
(rdbg) c # continue command
** Invoke s3:upload_assets (first_time)
** Invoke environment (first_time)
** Execute environment
** Invoke s3:ensure_cors_rules (first_time)
** Invoke environment
** Execute s3:ensure_cors_rules
Installing CORS rules...
skipping
** Execute s3:upload_assets
[30, 39] in /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb
30| return super if from_sentry_sdk?
31|
32| Sentry.with_child_span(op: OP_NAME, start_timestamp: Sentry.utc_now.to_f) do |sentry_span|
33| set_sentry_trace_header(req, sentry_span)
34|
=> 35| super.tap do |res|
36| record_sentry_breadcrumb(req, res)
37|
38| if sentry_span
39| request_info = extract_request_info(req)
=>#0 block {|sentry_span=nil|} in request at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb:35
#1 Sentry::Hub#with_child_span(instrumenter=:sentry, attributes={:op=>"http.client", :start_timestamp=>16..., block=#<Proc:0x00007f9058c78a40 /usr/local/bund...) at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/hub.rb:100
# and 102 frames (use `bt' command for all frames)
Stop by #0 BP - Line /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb:35 (line)
(ruby) Net::HTTP.ancestors
[Sentry::Net::HTTP]
no i just wanted to know if this was a regression or not. In that case downgrading won't help, we'll need to find the problem in this setup and fix it.
I am also getting the same problem in the main server, I believe in a sidekiq worker process:
[Transport] Sending envelope with items [sessions] to Sentry
exception happened in background worker: stack level too deep
Discourse also captures some of the stacktrace:
Let me know if you have any ideas on ways to troubleshoot this!
ok some investigation, still not sure what the issue is.
discourse has the following in their gemfile (faraday with explicit net-http gem) https://github.com/discourse/discourse/blob/main/Gemfile#L269-L274
and then you're adding sentry manually in the Dockerfile with bundle add
https://github.com/saulshanabrook/discourse-hosting/blob/f880f8d714fc614535e96d0114203a67c529a854/Dockerfile#L50-L52
@st0012 do you see any problems with the patching in this scenario?
Normally the ancestors should look like this
[1] pry(main)> Net::HTTP.ancestors
=> [Sentry::Net::HTTP, Net::HTTP, Net::Protocol, Object, PP::ObjectMixin, JSON::Ext::Generator::GeneratorMethods::Object, Kernel, BasicObject]
while you have just Sentry::Net::HTTP
in there which is suspicious.
@sl0thentr0py I tried adding RUN bundle remove net-http
to the end of my Dockerfile, but that didn't change it FYI.
It's because discourse injects method_profiler, which uses alias_method
to patch the request
method. And because sentry-ruby
uses prepend
in Sentry::Net::HTTP
, the 2 conflicts and causes infinite loop.
We had several cases like this:
Given that more and more tools use prepend
now, I'd recommend them to use prepend
as well to avoid conflicts with other tools. But it could be a big change if all their patches are implemented with alias_method
.
Debugging note: As a major contributor of the debug
gem, I was surprised to see you use it in this report, which helped me quite a lot. Thank you 😄
I based my investigation on the command you provided:
bt 10
- list closest 10 frames=>#0 block {|sentry_span=nil|} in request at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb:35
#1 Sentry::Hub#with_child_span(instrumenter=:sentry, attributes={:op=>"http.client", :start_timestamp=>16..., block=#<Proc:0x0000ffff882e94c8 /usr/local/bund...) at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/hub.rb:100
#2 Sentry.with_child_span(attributes={:op=>"http.client", :start_timestamp=>16..., block=#<Proc:0x0000ffff882e9478 /usr/local/bund...) at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry-ruby.rb:446
#3 Sentry::Net::HTTP#request__mp_unpatched(req=#<Net::HTTP::Head HEAD>, body=nil, block=#<Proc:0x0000ffff89fac7e0 /usr/local/bund...) at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb:32
#4 Net::HTTP#request(args=[#<Net::HTTP::Head HEAD>, nil], blk=#<Proc:0x0000ffff89fac7e0 /usr/local/bund...) at (eval):5
#5 block {|sentry_span=nil|} in request at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb:35
#6 Sentry::Hub#with_child_span(instrumenter=:sentry, attributes={:op=>"http.client", :start_timestamp=>16..., block=#<Proc:0x0000ffff89fac718 /usr/local/bund...) at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/hub.rb:100
#7 Sentry.with_child_span(attributes={:op=>"http.client", :start_timestamp=>16..., block=#<Proc:0x0000ffff89fac6a0 /usr/local/bund...) at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry-ruby.rb:446
#8 Sentry::Net::HTTP#request(req=#<Net::HTTP::Head HEAD>, body=nil, block=#<Proc:0x0000ffff89fac7e0 /usr/local/bund...) at /usr/local/bundle/gems/sentry-ruby-5.8.0/lib/sentry/net/http.rb:32
#9 Seahorse::Client::NetHttp::ConnectionPool::ExtendedSession#request(args=[#<Net::HTTP::Head HEAD>], block=#<Proc:0x0000ffff89fac588 /usr/local/bund...) at /usr/local/bundle/gems/aws-sdk-core-3.130.2/lib/seahorse/client/net_http/connection_pool.rb:348
f 4
- because (eval):5
looks fishy and I want to see what that frame does.l
- to get the surrounding code:(rdbg) l # list command
1|
2|
3| unless defined?(request__mp_unpatched)
4| alias_method :request__mp_unpatched, :request
=> 5| def request(*args, &blk)
6| unless prof = Thread.current[:_method_profiler]
7| return request__mp_unpatched(*args, &blk)
8| end
9| return request__mp_unpatched(*args, &blk) if @mp_recurse_protect_request
10| @mp_recurse_protect_request = true
alias_method
, I knew it's the cause. So then I just googled that code piece by piece to find the source.
edit .
to open the file in editor right away.wow great debugging @st0012 !
@saulshanabrook does that answer your question? You'll need to patch discourse upstream to make it work with sentry, I don't think we can do much here. If it resolves your question, please close this issue.
Wow @st0012 that is excellent detective work! I had seen the (eval):5
as well but didn't realize that was a discourse block and not a sentry block....
Thank you for your work on the debug gem! I have actually never used ruby before trying to get Discourse up and running and the debugging experience was surprisingly pleasant :)
I posted a topic on the Discourse meta forum about this issue, so I will reply with your suggested fix (replacing use of alias_method
with prepend
) and use a workaround for now (probably just patching that piece to remove their method profiler).
Thank you all for helping me debug this, I really thought I would just have to give up on using Sentry for this project ❤️.
Issue Description
Hello!
I am coming across an error trying to use the sentry ruby bindings on with a rails app, during a rake task. The task uploads the precompiled assets to an S3 server. It exits cleanly without the sentry integration, but when I add it, it enters into an infinitely recursive loop with the patched HTTP module. I am not sure how to debug this further or what to do.
Thank you!
Reproduction Steps
edited with simpler steps:
Following the steps of https://github.com/saulshanabrook/discourse-hosting#local-development-with-docker-compose the error will be raised when running
docker compose run --rm upload_assets
:Expected Behavior
The command exits cleanly without an error
Actual Behavior
It raises a
SystemStackError
:Ruby Version
3.1
SDK Version
sentry-ruby-5.8.0
Integration and Its Version
No response
Sentry Config