Skip to content

Enhancement: lossless filtering of backtraces for fingerprinting #1076

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
ChrisBAshton opened this issue Oct 23, 2020 · 10 comments
Closed

Enhancement: lossless filtering of backtraces for fingerprinting #1076

ChrisBAshton opened this issue Oct 23, 2020 · 10 comments
Assignees

Comments

@ChrisBAshton
Copy link

Hello 👋 We're facing a situation similar to #957, whereby we have lots of errors that differ slightly in their stacktrace, meaning they are grouped differently when they are ostensibly the same error. Stacktrace differences typically occur in the 'framework traces', caused by slight variations in dependency versions over time. What we really care about for the purposes of fingerprinting are the 'application traces'.

The backtrace_cleanup_callback added in #1011 was a useful addition meaning that the application traces of our stacktraces no longer differ on dynamically generated template methods (such as app/views/welcome/view_error.html.erb in _app_views_welcome_view_error_html_erb__2807287320172182514_65600 at line 1). I understand that we could provide our own callback to this method and use the Rails::BacktraceCleaner to filter out framework traces and keep only our application traces, like so:

config.backtrace_cleanup_callback = lambda do |backtrace|
  Rails.backtrace_cleaner.clean(backtrace)
end

The problem with this approach is that it is lossy. We only want to filter the stacktrace for the purposes of fingerprinting, but we still want to be able to dig into the whole stack trace when we come to debug the error.

Proposal

I propose that the implementation of backtrace_cleanup_callback be changed slightly (as it's still new and presumably has limited adoption so far), so that it doesn't alter the original stack trace. It would have exactly the same API (i.e. a lambda) but would just store a filtered version in memory for the purposes of fingerprinting.

If changing the current property is not an option, a new config option could be provided (perhaps filter_backtrace_for_fingerprinting).

Or, if I've completely misunderstood how this works and it isn't lossy, could the documentation make this explicit?

Other approaches considered

I've toyed with the idea of manipulating the fingerprint itself using before_send, though there is no documentation on this and I'm not sure if it's supported:

config.before_send = lambda { |event, hint|
  event.fingerprint =CustomFingerprint.sample(event)
  event
}

What stopped me from investigating this further was that it felt like using a sledgehammer to crack a nut. The default Sentry grouping algorithm is great, most of the time, and I'd rather not reimplement it - I just want to tweak it to be a little more forgiving of environmental differences in stack trace.

I did also consider server-side fingerprinting to filter out framework traces, but we have a lot of applications to manage and a strong version control mantra, whereby manually editing this kind of thing in the Sentry UI really isn't ideal.

Thanks in advance for your time!

@st0012
Copy link
Collaborator

st0012 commented Oct 23, 2020

hi @ChrisBAshton, thanks for clearing explaining the issue! I'm sorry that backtrace_cleanup_callback is causing problems for you. but as we're actively working on the 4.0 version, we don't have time to address this issue in the near future. atm, I suggest you use config.backtrace_cleanup_callback = nil to fall back to the old behavior to avoid such issues.

with that being said, I will introduce something like fingerprint_cleanup_callback in the new SDK as a better solution to similar issues. but again, that's not likely to happen very soon.

@ChrisBAshton
Copy link
Author

Hi @st0012, thanks for the quick response! backtrace_cleanup_callback isn't causing us issues, but it doesn't quite solve our problem either. A fingerprint_cleanup_callback sounds great, when you have time. Thanks.

@st0012 st0012 added this to the 4.1.0 milestone Oct 31, 2020
@st0012 st0012 modified the milestones: 4.1.0, 4.2.0 Dec 15, 2020
@st0012 st0012 modified the milestones: 4.2.0, 4.3.0 Jan 30, 2021
@st0012 st0012 removed this from the 4.3.0 milestone Mar 2, 2021
@ChrisBAshton
Copy link
Author

Hi @st0012, I was wondering if you had a rough timeline for this now that v4 has been released? Thanks in advance.

@st0012
Copy link
Collaborator

st0012 commented Jun 12, 2021

@ChrisBAshton hey sorry for the delay. I've started working on this again. I'm still thinking if I should treat backtrace_cleanup_callback's current behavior as a bug and fix it. I have to admit that I didn't think about different scenarios clearly when I designed it. atm, I think it's suppose to preserve the backtrace for view exceptions and just modify the fingerprint. but I'm not sure how changing backtrace_cleanup_callback's behavior will affect other cases 🤔

@st0012
Copy link
Collaborator

st0012 commented Jun 12, 2021

@ChrisBAshton can you screenshot the backtrace information you find missing because of backtrace_cleanup_callback?
I think the backtrace display has also been modified on Sentry's server side changes. so I want to learn more about what you expect now and make sure we're on the same page before committing to any change. thanks.

@ChrisBAshton
Copy link
Author

ChrisBAshton commented Jul 22, 2021

Hi @st0012, sorry for the slow response. Here are the stack traces taken from clicking "RAW" next to the Stack Trace section in the Sentry UI.

I've tried three approaches:

  1. No backtrace cleaning (i.e. don't call backtrace_cleanup_callback)
  2. 'Default' backtrace cleaning (i.e. call Rails.backtrace_cleaner.clean(backtrace)
  3. Backtrace cleaning with custom rules

With no backtrace cleaning

StandardError: Custom exception from Chris
  from app/controllers/trigger_error_controller.rb:3:in `now'
  from action_controller/metal/basic_implicit_render.rb:6:in `send_action'
  from abstract_controller/base.rb:228:in `process_action'
  from action_controller/metal/rendering.rb:30:in `process_action'
  from abstract_controller/callbacks.rb:42:in `block in process_action'
  from active_support/callbacks.rb:106:in `run_callbacks'
  from abstract_controller/callbacks.rb:41:in `process_action'
  from action_controller/metal/rescue.rb:22:in `process_action'
  from logstasher/rails_ext/action_controller/metal/instrumentation.rb:40:in `block in process_action'
  from active_support/notifications.rb:203:in `block in instrument'
  from active_support/notifications/instrumenter.rb:24:in `instrument'
  from active_support/notifications.rb:203:in `instrument'
  from logstasher/rails_ext/action_controller/metal/instrumentation.rb:27:in `process_action'
  from action_controller/metal/params_wrapper.rb:249:in `process_action'
  from active_record/railties/controller_runtime.rb:27:in `process_action'
  from abstract_controller/base.rb:165:in `process'
  from action_view/rendering.rb:39:in `process'
  from action_controller/metal.rb:190:in `dispatch'
  from action_controller/metal.rb:254:in `dispatch'
  from action_dispatch/routing/route_set.rb:50:in `dispatch'
  from action_dispatch/routing/route_set.rb:33:in `serve'
  from action_dispatch/journey/router.rb:50:in `block in serve'
  from action_dispatch/journey/router.rb:32:in `each'
  from action_dispatch/journey/router.rb:32:in `serve'
  from action_dispatch/routing/route_set.rb:842:in `call'
  from sentry/rails/rescued_exception_interceptor.rb:12:in `call'
  from gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from warden/manager.rb:36:in `block in call'
  from warden/manager.rb:34:in `catch'
  from warden/manager.rb:34:in `call'
  from omniauth/strategy.rb:202:in `call!'
  from omniauth/strategy.rb:169:in `call'
  from omniauth/builder.rb:45:in `call'
  from rack/tempfile_reaper.rb:15:in `call'
  from rack/etag.rb:27:in `call'
  from rack/conditional_get.rb:27:in `call'
  from rack/head.rb:12:in `call'
  from action_dispatch/http/permissions_policy.rb:22:in `call'
  from action_dispatch/http/content_security_policy.rb:18:in `call'
  from rack/session/abstract/id.rb:266:in `context'
  from rack/session/abstract/id.rb:260:in `call'
  from action_dispatch/middleware/cookies.rb:689:in `call'
  from action_dispatch/middleware/callbacks.rb:27:in `block in call'
  from active_support/callbacks.rb:98:in `run_callbacks'
  from action_dispatch/middleware/callbacks.rb:26:in `call'
  from action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
  from action_dispatch/middleware/debug_exceptions.rb:29:in `call'
  from action_dispatch/middleware/show_exceptions.rb:33:in `call'
  from logstasher/rails_ext/rack/logger.rb:16:in `call_app'
  from rails/rack/logger.rb:26:in `block in call'
  from active_support/tagged_logging.rb:99:in `block in tagged'
  from active_support/tagged_logging.rb:37:in `tagged'
  from active_support/tagged_logging.rb:99:in `tagged'
  from rails/rack/logger.rb:26:in `call'
  from action_dispatch/middleware/remote_ip.rb:81:in `call'
  from request_store/middleware.rb:19:in `call'
  from action_dispatch/middleware/request_id.rb:26:in `call'
  from rack/method_override.rb:24:in `call'
  from rack/runtime.rb:22:in `call'
  from active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
  from sentry/rack/capture_exceptions.rb:23:in `block in call'
  from sentry/hub.rb:56:in `with_scope'
  from sentry-ruby.rb:168:in `with_scope'
  from sentry/rack/capture_exceptions.rb:14:in `call'
  from action_dispatch/middleware/executor.rb:14:in `call'
  from rack/sendfile.rb:110:in `call'
  from action_dispatch/middleware/host_authorization.rb:92:in `call'
  from rails/engine.rb:539:in `call'
  from unicorn/http_server.rb:634:in `process_client'
  from unicorn/http_server.rb:732:in `worker_loop'
  from unicorn/http_server.rb:548:in `spawn_missing_workers'
  from unicorn/http_server.rb:144:in `start'
  from /data/vhost/collections-publisher/shared/bundle/ruby/2.7.0/gems/unicorn-5.8.0/bin/unicorn:128:in `<top (required)>'
  from /data/apps/collections-publisher/shared/bundle/ruby/2.7.0/bin/unicorn:23:in `load'
  from /data/apps/collections-publisher/shared/bundle/ruby/2.7.0/bin/unicorn:23:in `<main>'

With backtrace cleaning

i.e. by supplying this config:

config.backtrace_cleanup_callback = lambda do |backtrace|
  Rails.backtrace_cleaner.clean(backtrace)
end

We can see that the formatting is different, but no frames are lost:

StandardError: Custom exception from Chris - with backtrace cleaned
  from app/controllers/trigger_error_controller.rb:3:in `now'
  from actionpack (6.1.4) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
  from actionpack (6.1.4) lib/abstract_controller/base.rb:228:in `process_action'
  from actionpack (6.1.4) lib/action_controller/metal/rendering.rb:30:in `process_action'
  from actionpack (6.1.4) lib/abstract_controller/callbacks.rb:42:in `block in process_action'
  from activesupport (6.1.4) lib/active_support/callbacks.rb:106:in `run_callbacks'
  from actionpack (6.1.4) lib/abstract_controller/callbacks.rb:41:in `process_action'
  from actionpack (6.1.4) lib/action_controller/metal/rescue.rb:22:in `process_action'
  from logstasher (2.1.5) lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb:40:in `block in process_action'
  from activesupport (6.1.4) lib/active_support/notifications.rb:203:in `block in instrument'
  from activesupport (6.1.4) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
  from activesupport (6.1.4) lib/active_support/notifications.rb:203:in `instrument'
  from logstasher (2.1.5) lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb:27:in `process_action'
  from actionpack (6.1.4) lib/action_controller/metal/params_wrapper.rb:249:in `process_action'
  from activerecord (6.1.4) lib/active_record/railties/controller_runtime.rb:27:in `process_action'
  from actionpack (6.1.4) lib/abstract_controller/base.rb:165:in `process'
  from actionview (6.1.4) lib/action_view/rendering.rb:39:in `process'
  from actionpack (6.1.4) lib/action_controller/metal.rb:190:in `dispatch'
  from actionpack (6.1.4) lib/action_controller/metal.rb:254:in `dispatch'
  from actionpack (6.1.4) lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
  from actionpack (6.1.4) lib/action_dispatch/routing/route_set.rb:33:in `serve'
  from actionpack (6.1.4) lib/action_dispatch/journey/router.rb:50:in `block in serve'
  from actionpack (6.1.4) lib/action_dispatch/journey/router.rb:32:in `each'
  from actionpack (6.1.4) lib/action_dispatch/journey/router.rb:32:in `serve'
  from actionpack (6.1.4) lib/action_dispatch/routing/route_set.rb:842:in `call'
  from sentry-rails (4.5.2) lib/sentry/rails/rescued_exception_interceptor.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from warden (1.2.9) lib/warden/manager.rb:36:in `block in call'
  from warden (1.2.9) lib/warden/manager.rb:34:in `catch'
  from warden (1.2.9) lib/warden/manager.rb:34:in `call'
  from omniauth (2.0.4) lib/omniauth/strategy.rb:202:in `call!'
  from omniauth (2.0.4) lib/omniauth/strategy.rb:169:in `call'
  from omniauth (2.0.4) lib/omniauth/builder.rb:45:in `call'
  from rack (2.2.3) lib/rack/tempfile_reaper.rb:15:in `call'
  from rack (2.2.3) lib/rack/etag.rb:27:in `call'
  from rack (2.2.3) lib/rack/conditional_get.rb:27:in `call'
  from rack (2.2.3) lib/rack/head.rb:12:in `call'
  from actionpack (6.1.4) lib/action_dispatch/http/permissions_policy.rb:22:in `call'
  from actionpack (6.1.4) lib/action_dispatch/http/content_security_policy.rb:18:in `call'
  from rack (2.2.3) lib/rack/session/abstract/id.rb:266:in `context'
  from rack (2.2.3) lib/rack/session/abstract/id.rb:260:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/cookies.rb:689:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
  from activesupport (6.1.4) lib/active_support/callbacks.rb:98:in `run_callbacks'
  from actionpack (6.1.4) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
  from logstasher (2.1.5) lib/logstasher/rails_ext/rack/logger.rb:16:in `call_app'
  from railties (6.1.4) lib/rails/rack/logger.rb:26:in `block in call'
  from activesupport (6.1.4) lib/active_support/tagged_logging.rb:99:in `block in tagged'
  from activesupport (6.1.4) lib/active_support/tagged_logging.rb:37:in `tagged'
  from activesupport (6.1.4) lib/active_support/tagged_logging.rb:99:in `tagged'
  from railties (6.1.4) lib/rails/rack/logger.rb:26:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
  from request_store (1.5.0) lib/request_store/middleware.rb:19:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/request_id.rb:26:in `call'
  from rack (2.2.3) lib/rack/method_override.rb:24:in `call'
  from rack (2.2.3) lib/rack/runtime.rb:22:in `call'
  from activesupport (6.1.4) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
  from sentry-ruby-core (4.5.2) lib/sentry/rack/capture_exceptions.rb:23:in `block in call'
  from sentry-ruby-core (4.5.2) lib/sentry/hub.rb:56:in `with_scope'
  from sentry-ruby-core (4.5.2) lib/sentry-ruby.rb:168:in `with_scope'
  from sentry-ruby-core (4.5.2) lib/sentry/rack/capture_exceptions.rb:14:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/executor.rb:14:in `call'
  from rack (2.2.3) lib/rack/sendfile.rb:110:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/host_authorization.rb:92:in `call'
  from railties (6.1.4) lib/rails/engine.rb:539:in `call'
  from unicorn (5.8.0) lib/unicorn/http_server.rb:634:in `process_client'
  from unicorn (5.8.0) lib/unicorn/http_server.rb:732:in `worker_loop'
  from unicorn (5.8.0) lib/unicorn/http_server.rb:548:in `spawn_missing_workers'
  from unicorn (5.8.0) lib/unicorn/http_server.rb:144:in `start'
  from unicorn (5.8.0) bin/unicorn:128:in `<top (required)>'
  from /data/apps/collections-publisher/shared/bundle/ruby/2.7.0/bin/unicorn:23:in `load'
  from /data/apps/collections-publisher/shared/bundle/ruby/2.7.0/bin/unicorn:23:in `<main>'

With backtrace cleaning and custom silencers

config.backtrace_cleanup_callback = lambda do |backtrace|
  Rails.backtrace_cleaner.add_silencer { |line| /action_dispatch/.match?(line) }
  Rails.backtrace_cleaner.clean(backtrace)
end

We can see that, again, no frames are lost - action_dispatch frames are still present in the stack trace:

StandardError: Custom exception from Chris - with backtrace cleaned & custom silencer
  from app/controllers/trigger_error_controller.rb:3:in `now'
  from actionpack (6.1.4) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
  from actionpack (6.1.4) lib/abstract_controller/base.rb:228:in `process_action'
  from actionpack (6.1.4) lib/action_controller/metal/rendering.rb:30:in `process_action'
  from actionpack (6.1.4) lib/abstract_controller/callbacks.rb:42:in `block in process_action'
  from activesupport (6.1.4) lib/active_support/callbacks.rb:106:in `run_callbacks'
  from actionpack (6.1.4) lib/abstract_controller/callbacks.rb:41:in `process_action'
  from actionpack (6.1.4) lib/action_controller/metal/rescue.rb:22:in `process_action'
  from logstasher (2.1.5) lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb:40:in `block in process_action'
  from activesupport (6.1.4) lib/active_support/notifications.rb:203:in `block in instrument'
  from activesupport (6.1.4) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
  from activesupport (6.1.4) lib/active_support/notifications.rb:203:in `instrument'
  from logstasher (2.1.5) lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb:27:in `process_action'
  from actionpack (6.1.4) lib/action_controller/metal/params_wrapper.rb:249:in `process_action'
  from activerecord (6.1.4) lib/active_record/railties/controller_runtime.rb:27:in `process_action'
  from actionpack (6.1.4) lib/abstract_controller/base.rb:165:in `process'
  from actionview (6.1.4) lib/action_view/rendering.rb:39:in `process'
  from actionpack (6.1.4) lib/action_controller/metal.rb:190:in `dispatch'
  from actionpack (6.1.4) lib/action_controller/metal.rb:254:in `dispatch'
  from actionpack (6.1.4) lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
  from actionpack (6.1.4) lib/action_dispatch/routing/route_set.rb:33:in `serve'
  from actionpack (6.1.4) lib/action_dispatch/journey/router.rb:50:in `block in serve'
  from actionpack (6.1.4) lib/action_dispatch/journey/router.rb:32:in `each'
  from actionpack (6.1.4) lib/action_dispatch/journey/router.rb:32:in `serve'
  from actionpack (6.1.4) lib/action_dispatch/routing/route_set.rb:842:in `call'
  from sentry-rails (4.5.2) lib/sentry/rails/rescued_exception_interceptor.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from gds-api-adapters (72.0.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'
  from warden (1.2.9) lib/warden/manager.rb:36:in `block in call'
  from warden (1.2.9) lib/warden/manager.rb:34:in `catch'
  from warden (1.2.9) lib/warden/manager.rb:34:in `call'
  from omniauth (2.0.4) lib/omniauth/strategy.rb:202:in `call!'
  from omniauth (2.0.4) lib/omniauth/strategy.rb:169:in `call'
  from omniauth (2.0.4) lib/omniauth/builder.rb:45:in `call'
  from rack (2.2.3) lib/rack/tempfile_reaper.rb:15:in `call'
  from rack (2.2.3) lib/rack/etag.rb:27:in `call'
  from rack (2.2.3) lib/rack/conditional_get.rb:27:in `call'
  from rack (2.2.3) lib/rack/head.rb:12:in `call'
  from actionpack (6.1.4) lib/action_dispatch/http/permissions_policy.rb:22:in `call'
  from actionpack (6.1.4) lib/action_dispatch/http/content_security_policy.rb:18:in `call'
  from rack (2.2.3) lib/rack/session/abstract/id.rb:266:in `context'
  from rack (2.2.3) lib/rack/session/abstract/id.rb:260:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/cookies.rb:689:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
  from activesupport (6.1.4) lib/active_support/callbacks.rb:98:in `run_callbacks'
  from actionpack (6.1.4) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
  from logstasher (2.1.5) lib/logstasher/rails_ext/rack/logger.rb:16:in `call_app'
  from railties (6.1.4) lib/rails/rack/logger.rb:26:in `block in call'
  from activesupport (6.1.4) lib/active_support/tagged_logging.rb:99:in `block in tagged'
  from activesupport (6.1.4) lib/active_support/tagged_logging.rb:37:in `tagged'
  from activesupport (6.1.4) lib/active_support/tagged_logging.rb:99:in `tagged'
  from railties (6.1.4) lib/rails/rack/logger.rb:26:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
  from request_store (1.5.0) lib/request_store/middleware.rb:19:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/request_id.rb:26:in `call'
  from rack (2.2.3) lib/rack/method_override.rb:24:in `call'
  from rack (2.2.3) lib/rack/runtime.rb:22:in `call'
  from activesupport (6.1.4) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
  from sentry-ruby-core (4.5.2) lib/sentry/rack/capture_exceptions.rb:23:in `block in call'
  from sentry-ruby-core (4.5.2) lib/sentry/hub.rb:56:in `with_scope'
  from sentry-ruby-core (4.5.2) lib/sentry-ruby.rb:168:in `with_scope'
  from sentry-ruby-core (4.5.2) lib/sentry/rack/capture_exceptions.rb:14:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/executor.rb:14:in `call'
  from rack (2.2.3) lib/rack/sendfile.rb:110:in `call'
  from actionpack (6.1.4) lib/action_dispatch/middleware/host_authorization.rb:92:in `call'
  from railties (6.1.4) lib/rails/engine.rb:539:in `call'
  from unicorn (5.8.0) lib/unicorn/http_server.rb:634:in `process_client'
  from unicorn (5.8.0) lib/unicorn/http_server.rb:732:in `worker_loop'
  from unicorn (5.8.0) lib/unicorn/http_server.rb:548:in `spawn_missing_workers'
  from unicorn (5.8.0) lib/unicorn/http_server.rb:144:in `start'
  from unicorn (5.8.0) bin/unicorn:128:in `<top (required)>'
  from /data/apps/collections-publisher/shared/bundle/ruby/2.7.0/bin/unicorn:23:in `load'
  from /data/apps/collections-publisher/shared/bundle/ruby/2.7.0/bin/unicorn:23:in `<main>'

Further investigation

I must admit, I was surprised that 2) retained every frame trace (albeit looking different), and even more surprised when 3) retained all the frame traces too. So I tried an experiment:

config.backtrace_cleanup_callback = lambda do |backtrace|
  Rails.backtrace_cleaner.add_silencer { |line| true }
  Rails.backtrace_cleaner.clean(backtrace)
end

The add_silencer { |line| true } should in theory silence EVERY LINE, meaning if different exception types are raised, they're grouped under one Issue, assuming they're grouped by stack trace.

I added this to my routes.rb:

  get "/trigger-error" => "trigger_error#now"
  get "/trigger-another-error" => "trigger_error#then"

...and this in the TriggerErrorController:

  def now
    raise StandardError.new("Custom exception from Chris #1")
  end

  def then
    raise StandardError.new("Custom exception from Chris #2")
  end

However, when I triggered the two error types, they did not appear in Sentry as one issue as I expected. They appeared as two separate issues, and when I scrolled to the bottom, I could see that they were each grouped "By Exception Stack-trace", and that the stack traces appeared in full.

This makes me think that the Sentry backtrace cleaner isn't actually doing what we think it is.

For the record, I also tried out the Rails backtrace cleaner in a REPL, and it does seem to work how I've documented above:

$ Rails.backtrace_cleaner.remove_silencers!
=> []
$ Rails.backtrace_cleaner.clean(["/puma/"])
=> ["/puma/"] # doesn't clean it, as we haven't told it to
$ Rails.backtrace_cleaner.add_silencer { |line| /puma/.match?(line) }
=> [#<Proc:0x0000560f7ee4eb50 (irb):6>]
$ Rails.backtrace_cleaner.clean(["/puma/"])
=> [] # cleans it, because we've told it to
$ Rails.backtrace_cleaner.clean(["/foo/"])
=> ["/foo/"] # doesn't clean it, because it doesn't match "puma"
$ Rails.backtrace_cleaner.add_silencer { |line| true }
=> [#<Proc:0x0000560f7ee4eb50 (irb):6>, #<Proc:0x0000560f7eac2748 (irb):9>]
$> Rails.backtrace_cleaner.clean(["/foo/", "/bar/"])
=> [] # cleans all lines, because we've just hardcoded `true` above

Summary

The backtrace_cleanup_callback doesn't appear "lossy" in the way that I expected. However, Sentry appears not to use the cleaned up backtrace for grouping purposes - which is the feature I'm requesting here. I'm not entirely sure what Sentry is doing with the cleaned up backtrace.

@st0012
Copy link
Collaborator

st0012 commented Jul 22, 2021

@ChrisBAshton thanks for the detailed investigation 🙏 I found the result weird too so I did an investigation myself and here's what I found:

st0012 added a commit that referenced this issue Jul 22, 2021
`sentry-rails` should check the presence `backtrace_cleanup_callback`
before assigning the default one.

The problem was spotted in #1076 (comment).
st0012 added a commit that referenced this issue Jul 23, 2021
* Remove perform_basic_setup test helper to avoid misuse

* Don't override backtrace_cleanup_callback set by the user

`sentry-rails` should check the presence `backtrace_cleanup_callback`
before assigning the default one.

The problem was spotted in #1076 (comment).

* Update changelog
@github-actions
Copy link

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!


"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

@ChrisBAshton
Copy link
Author

Thanks, bot, for reminding me about this!

I believe next steps are for me to try out my experiment again, but with the latest version of sentry-ruby.

@sl0thentr0py
Copy link
Member

@ChrisBAshton I believe this should no longer be a problem, so closing. Please reopen if necessary!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants