Rails/Rack recording exceptions twice

[mattrobenolt]

Repository to test: https://github.com/mattrobenolt/sentry_test

When an exception occurs, we get two exceptions, one for the page itself, then one for the corresponding /500 route.

As noted by a user:

So it looks like that even new Rails app is affected. We think that it’s caused by catching exception in a raven rails integration first and then the second exception is caught by raven rack integration. It can be avoided by skipping rack integration entirely but we don’t want to do that. So I think that there should be some kind of mechanism to catch the exception only once and by only by one integration.

Refs: https://sentry.zendesk.com/agent/tickets/1054

[dcramer]

It's unclear what the right solution to this is. Would appreciate anyone familiar w/ Rack/Rails ecosystem's opinion.

[mattrobenolt]

Hey @martinhladil, just following up here.

I clone this repository, and was unable to reproduce. I was running with just rails server. Is there something I should be doing differently?

Could this be something with running behind Unicorn?

[martinhladil]

We can reproduce this on the new Rails app in it's default state without any modifications etc. so the test repository is actually not needed.

It's not Unicorn related as this happens on Webrick and Passenger.

We think that the reason of the duplication is quite simple. Exception is catched and reported twice. Once for Rails integration and once for Rack integration. We can solve it by manually including Rails integration only and skipping Rack integration but this is not acceptable as we would miss Rack only errors.

[mattrobenolt]

Yeah, I understand. I just haven't been able to see this myself in testing to be able to begin to fix.

I've tested against a brand new Rails app, as well as your repository without success. :(

[martinhladil]

Hmm, I would really like to help you, but I don't have a clue we are doing different. We know for sure that it's not related to a webserver, ruby or Rails version. We are not using any custom Raven configuration. DSN is set as an ENV variable.

[mattrobenolt]

If you're familiar with Docker, I've been doing this inside a container, and I forked and updated your project to include a Dockerfile.

You should be able to simply:

git clone https://github.com/mattrobenolt/sentry_test.git
cd sentry_test
docker build --rm -t sentry-test .
docker run --rm --name sentry-test -e SENTRY_DSN=<dsn> -p 3000:3000 -v $PWD:/usr/src/app -it sentry-test

[mattrobenolt]

Also for context, this is the change: mattrobenolt/sentry_test@4d7b98a

[mjdavies]

"We can solve it by manually including Rails integration only and skipping Rack integration but this is not acceptable as we would miss Rack only errors."

This may sound a bit daft, but can you show me the differences in the code in those two options you've outlined above? The codebase when it does this twice, and the codebase when it doesn't?

[mjdavies]

Thinking out loud, maybe there are 2 errors happening. Depending on how your catching the errors could determine whether or not you actually catch and report the second one. If you show me the diffs mentioned above we can probably rule this out.

[robertcigan]

What the problem I think is as described: The problem is the default Rails app inject does add things into ActionDispatch::ShowExceptions to catch exceptions and report them and also adds extra Raven::Rack middleware(which should be really used for only non - Rails apps). If you look here at the middleware trace (my app) for default gem "sentry-raven" and it's default inject for Rails (integrations/rails and then integrations/rack) you get

use Raven::Rack
use Rack::Sendfile
use ActionDispatch::Static
use Rack::Lock
use #ActiveSupport::Cache::Strategy::LocalCache::Middleware:0x007ff3d539fed8
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use WebConsole::Middleware
use ActionDispatch::DebugExceptions
use ActionDispatch::RemoteIp
use ActionDispatch::Reloader
use ActionDispatch::Callbacks
use ActiveRecord::Migration::CheckPending
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use ActionDispatch::ParamsParser
use Rack::Head
use Rack::ConditionalGet
use Rack::ETag
use Warden::Manager
use MyApp::Application.routes

Errors are already reported in use ActionDispatch::ShowExceptions but then when this middlware does it's job and also modifies headers etc. it's being propagated further to Raven::Rack and reported again.

We don't need to report errors from middlewares of ActionDispatch::ShowExceptions and above (all the things like sessions, cookies, params etc. are catched by ActionDispatch::ShowExceptions.

Do not add Raven::Rack middleware for Rails apps and we're fine. This can now be achieved per wiki (Integrations)

gem "sentry-raven", require: false

and in initializers/raven.rb

require "raven/base"
require "raven/integrations/rails"

[chadwtaylor]

+1 Am having this issue too; and don't have the Rack expertise here to help out :(

[EricCarlstrom]

+1, watching/subscribed to this issue, hoping for a resolution. Thanks much!

[neilvcarvalho]

+1 So am I. I have the exact same problem.

[kkumler]

@mattrobenolt If you set the rails environment to production, you should be able to replicate the issue. Add -e RAILS_ENV=production to the docker run command above (note, by default the logs won't be output to stdout with this, so separately tail -f log/production.log)
With this we can see two separate events being sent to Sentry:

I, [2015-12-10T19:29:44.957534 #1]  INFO -- : Started GET "/?foo=bar" for 192.168.99.1 at 2015-12-10 19:29:44 +0000
I, [2015-12-10T19:29:44.964303 #1]  INFO -- : Processing by SentryController#index as HTML
I, [2015-12-10T19:29:44.964491 #1]  INFO -- :   Parameters: {"foo"=>"bar"}
I, [2015-12-10T19:29:44.965058 #1]  INFO -- : Completed 500 Internal Server Error in 0ms (ActiveRecord: 0.0ms)
D, [2015-12-10T19:29:44.989773 #1] DEBUG -- : ** [Raven] Sending event 1edbc5131b8b9997c76c646386ec1807 to Sentry
D, [2015-12-10T19:29:45.094375 #1] DEBUG -- : ** [Raven] Raven HTTP Transport connecting to https://app.getsentry.com
F, [2015-12-10T19:29:45.577222 #1] FATAL -- :
RuntimeError (TEST ERROR):
  app/controllers/sentry_controller.rb:3:in `index'


D, [2015-12-10T19:29:45.586827 #1] DEBUG -- : ** [Raven] Sending event 73bd3e2f35ce8000364fc711604f9aa6 to Sentry

One is for the initial / path and the other is for the /500 path. This would not happen with the Sentry-documented setting of config.action_dispatch.show_exceptions = false. However, no one will want to set that because then all 500 errors are bubbled up to be handled by the web server directly.