Skylight and Sentry stacktrace issues #461
Comments
|
Hi @scouttyg , thanks for submitting the issue. Skylight's normalizers are basically just subscribers to (typically) existing events fired by ActiveSupport::Notifications, and wouldn't affect the stack trace. I'm afraid I don't understand what is garbled about the stacktrace in your screenshot; this is more or less what I expect to see in the middleware stack with or without Skylight. Are you able to post the stacktrace in plain text, and explain how it differs from what you expect to see? |
|
@zvkemp It's hard to paste everything here, but consider the cases below: 1. Before (with both skylight and sentry, and not what we want our traces to look like)Here, above OAuth::Unauthorized, we get only one frame, in the file that the error occurred, but not the parent class, or anything higher level than that. We also get about 300 frames of looping around lines like the following: This is not what we want, as the file we want loses all it's context (e.g. parent classes, etc), and there's a bunch of unrelated stack tracing that isn't really telling us anything:
2. After (with just sentry, and what we want our traces to look like)After removing skylight, above OAuth::Unauthorized, we get the frame of the file that caused the error, along with the parent class, that parent's class, etc. We also only get about 4-5 frames around the OAuth::Unauthorized section, which is much more clean. This is much more what we want, as it tells us only the relevant files to the trace at hand:
|
|
I believe what you are seeing is a result of the |
Could you expand on this more, and how the conflict between We're wanting more what #2 in my comment above is showing (e.g. a much shorter trace), but I'm unsure how Skylight hooking into the I also know |
|
It's not a conflict per-se. You can probably experiment with any notification subscriber to get the same stacktrace (the InstrumentationProxy was a relatively recent addition to Rails, so it's likely not as many things consume it), e.g. # config/initializers/subscriber_example.rb
ActiveSupport::Notifications.subscribe("process_middleware.action_dispatch") do |*args|
# contents of block not particularly important
endThe repeated frames in the trace are just from calling the same instrumentation methods from all of your middlewares. A brand new rails app has 29 things in the middleware stack, and by default they are all wrapped in InstrumentationProxy, so as long as anything subscribes to that event, the stack will have calls to instrumenter#instrument. Note that this is the ActiveSupport::Notifications instrumenter, (which is a general purpose event fanout) not Skylight's (which sends event data into a Skylight trace). I believe the question you should ask is what Sentry is doing to filter the stacktraces (in your second gif they are very aggressively limiting the information they show you by default), and why that filter doesn't seem to recognize the pattern in your more verbose example. As I previously said, this was a relatively recent addition for Rails (version 6 I believe?) so it's entirely possible they just don't expect this pattern yet. |
Hmm, potentially, but at the error line in question there's differences where things were filtered out vs kept in with the combination of the two that would imply other things at play. Here's a few other screenshots: 1) Before (Skylight + Sentry, missing parent classes, not what we want)In the below case, we have the line where the error happened, but then only one more frame through the 
2) After (Skylight + Sentry, missing parent classes, not what we want)Here, we not only have the line where the error happened, but the parent class, etc up all the way to the controller level. 
In case 1, it looks like the parent of the error at hand goes straight to |
|
As far as I am aware, there's no way to 'hijack' a callstack. Are you viewing the 'raw' stacktraces in their UI, or do you have the 'app only' selector active? |
|
@zvkemp There is indeed a way to view a "Full Stack Trace" vs a minimal one, but even with the full stack trace there is no reference to the parent classes that should have been there: 
The full stack trace of the sentry + skylight can't be seen in this picture, but here's a rough copy of it below: This is the similar "full stack trace" provided when only sentry is installed (which reduces down correctly) |
|
@zvkemp Interesting to note, the first mentioned "bad" trace above is 250 lines long, which makes me wonder if the If true, it could be discarding additional frames, which could be causing the issue at hand. Let me look more into this avenue as well, and thank you for your patience. |
|
I had similar issues with Sentry returning big backtraces with a lot of irrelevant traces, I've solved it by adding a backtrace_cleanup_callback to the Sentry config. Give it a try in your Sentry.init do |config|
# Add silencers for irrelevant notifications and sentry backtraces
config.backtrace_cleanup_callback = ->(backtrace) do
cleaner = ActiveSupport::BacktraceCleaner.new
cleaner.remove_silencers!
cleaner.add_silencer do |line|
line =~ %r{active_support/notifications|sentry/rails/tracing|action_dispatch/middleware/stack}
end
cleaner.clean(backtrace)
end
end |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
We use the following tech stack:
rails (7.0.5)skylight (5.3.4)sentry-rails (5.9.0)sentry-ruby (5.9.0)And unfortunately, we've been having some trouble with stack traces on Sentry getting super garbled. You can see the report on the sentry-ruby Github here: getsentry/sentry-ruby#1863
I explained a bit of what we were seeing in this comment here: getsentry/sentry-ruby#1863 (comment), but in a nutshell, stack traces look like the following:
Basically one good frame, and then a bunch of seemingly looping frames.
The lines I see regarding skylight and sentry in the garbled stack are:
skylight (5.3.4) lib/skylight/middleware.rb in call at line 99sentry-rails (5.9.0) lib/sentry/rails/tracing.rb in instrument at line 54skylight (5.3.4) lib/skylight/probes/action_dispatch/request_id.rb in call at line 8When I disable Skylight's
process_middleware.action_dispatchNormalizer (e.g. https://github.com/skylightio/skylight-ruby/blob/master/lib/skylight/normalizers/action_dispatch/process_middleware.rb) it looks like the logs calm down, but I couldn't trace any further than that. Something with what the instrumenter is doing.Just figured I'd submit this issue here as well, in case there was any insights that could be gleamed, although the issue seems to be the interaction of these two different libraries together.
The text was updated successfully, but these errors were encountered: