Multiple reports per exception

[dmorneau]

Environment

• Elixir version (elixir -v): 1.10.3
• Erlang/OTP version (erl): 23.0.2
• Sentry version (mix deps): 7.2.4
• Operating system: Linux
• Is this an umbrella application?: No
• Release type (Distillery, mix release, Mix, etc.): mix release

Description

Every exception in a plug or controllers gets reported three times.

Expected Behavior

A single event per exception

Actual Behavior

There's three Sentry events per exception, with varying amounts of metadata:

• One report has the usual metadata, respecting header scrubber setting
• Another one looks similar, but includes sensitive headers (it's not scrubbed)
• The final one is missing almost all metadata

I believe these come from Sentry.Plug, Sentry.Phoenix.Endpoint, and Sentry.LoggerBackend respectively.

Steps to Reproduce

Setup a new Phoenix app with:

• Sentry.Plug
• Sentry.Phoenix.Endpoint
• Sentry.LoggerBackend

then add raise "boom" inside a controller and try to load the page.

I suspect the Phoenix and Cowboy versions are important. This is with Phoenix 1.5.3 and Cowboy 2.8.0. The LoggerHandler seems to check for Cowboy2Handler in the stack trace, which isn't present. Here'a sample :crash_reason as received by the logger backend:

[
   {MyAppWeb.TheController, :index, 2,
    [file: 'lib/myapp_web/controllers/the_controller.ex', line: 22]},
   {MyAppWeb.TheController, :action, 2,
    [file: 'lib/myapp_web/controllers/the_controller.ex', line: 1]},
   {MyAppWeb.TheController, :phoenix_controller_pipeline, 2,
    [file: 'lib/myapp_web/controllers/the_controller.ex', line: 1]},
   {Phoenix.Router, :__call__, 2, [file: 'lib/phoenix/router.ex', line: 352]},
   {MyAppWeb.Router, :call, 2, [file: 'lib/plug/error_handler.ex', line: 65]},
   {MyAppWeb.Endpoint, :plug_builder_call, 2,
    [file: 'lib/myapp_web/endpoint.ex', line: 1]},
   {MyAppWeb.Endpoint, :"call (overridable 3)", 2,
    [file: 'lib/plug/debugger.ex', line: 132]},
   {MyAppWeb.Endpoint, :call, 2,
    [file: 'lib/myapp_web/endpoint.ex', line: 1]}
 ]

This is similar to #374.

I'm not sure what causes the duplication between Sentry.Phoenix.Endpoint and Sentry.Plug.

[mitchellhenke]

@dmorneau thanks for opening an issue! 🙂

I was able to reproduce the duplicate Plug/Phoenix.Endpoint reporting, but I couldn't get the third Logger handler. Are you able to publish a small reproduction of the Logger duplication?

I tried to look into what may have changed to cause the Plug/Endpoint double report behavior, and tried going back to 1.4, and the same issue exists. Given that, I will see if I can resolve it, but will also beworking to find a more robust way to report errors in Phoenix/Plug outside of having to do use.

[dmorneau]

I think I see the problem with the logger. The Phoenix generators add this config in dev.exs:

# Set a higher stacktrace during development. Avoid configuring such
# in production as building large stacktraces may be expensive.
config :phoenix, :stacktrace_depth, 20

With this, if you raise inside a controller handler, the stack trace goes all the way to cowboy_handler:

    ** (RuntimeError) boom
        (sentry_397 0.1.0) lib/sentry_397_web/controllers/page_controller.ex:5: Sentry397Web.PageController.index/2
        (sentry_397 0.1.0) lib/sentry_397_web/controllers/page_controller.ex:1: Sentry397Web.PageController.action/2
        (sentry_397 0.1.0) lib/sentry_397_web/controllers/page_controller.ex:1: Sentry397Web.PageController.phoenix_controller_pipeline/2
        (phoenix 1.5.3) lib/phoenix/router.ex:352: Phoenix.Router.__call__/2
        (sentry_397 0.1.0) lib/plug/error_handler.ex:65: Sentry397Web.Router.call/2
        (sentry_397 0.1.0) lib/sentry_397_web/endpoint.ex:1: Sentry397Web.Endpoint.plug_builder_call/2
        (sentry_397 0.1.0) lib/plug/debugger.ex:132: Sentry397Web.Endpoint."call (overridable 3)"/2
        (sentry_397 0.1.0) lib/sentry_397_web/endpoint.ex:1: Sentry397Web.Endpoint.call/2
        (phoenix 1.5.3) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4
        (cowboy 2.8.0) sentry_397/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2
        (cowboy 2.8.0) sentry_397/deps/cowboy/src/cowboy_stream_h.erl:300: :cowboy_stream_h.execute/3
        (cowboy 2.8.0) sentry_397/deps/cowboy/src/cowboy_stream_h.erl:291: :cowboy_stream_h.request_process/3
        (stdlib 3.13) proc_lib.erl:226: :proc_lib.init_p_do_apply/3

But in production, the default stacktrace depth is 8, so the frames after Sentry397Web.Endpoint.call/2 get cut off and the pattern match inside the logger handler fails.

[princemaple]

Also having this issue, but double not triple, as @mitchellhenke described before.

It's because the error is re-raised by Plug.ErrorHandler after handle_errors is being called, and get caught again by Sentry.Phoenix.Endpoint, correct?

Is it possible to handle all errors in Endpoint?

  use Plug.ErrorHandler
  use Sentry.Plug

Can this be used in Endpoint, or does it have to be in Router?

[mitchellhenke]

@dmorneau ah, yeah. it's unfortunately a function of having to do heuristics to prevent the duplication.

And as @princemaple mentions, using Sentry.Phoenix.Endpoint should be sufficient on its own.

I'll be updating the docs and README accordingly.

[mitchellhenke]

Forgot to mention, but am hoping to have a solution that is entirely driven by Logger without the need for Plug/Endpoint interaction at all to avoid these types of issues.

[mitchellhenke]

@dmorneau I’ve released 8.0.0-rc.1 which should address this issue completely. If you’re able to give the release candidate a try and let me know how it goes, it’s be much appreciated!

[dmorneau]

@mitchellhenke The new version looks fantastic, thank you! I filed a couple minor things I noticed doing the upgrade: #408 #409

Duplicate events are gone and the scrubbing looks good 👍

[mitchellhenke]

@dmorneau greatly appreciate that, thank you!!