getsentry
Unable to catch exception caught by logger
Hi,
Bandit is throwing exceptions for me from some malformed requests that are probing my site. I can easily filter out that exception with a before_send callback:
def filter_non_500(%Sentry.Event{original_exception: exception} = event) do
cond do
match?(%{message: "Timeout waiting for space in the send_window"}, exception) ->
false
true -> event
end
end
but it appears the error is also getting captured by the log handler which has original_exception set to nil. What do I do in this situation?
%Sentry.Event{
event_id: "59d88cdc444f4ae6a10e08eeccd16d92",
timestamp: "2024-06-09T19:04:48.273951",
breadcrumbs: [
%Sentry.Interfaces.Breadcrumb{
type: nil,
category: "web.live_view.mount",
message: "Mounted live view",
data: %{},
level: nil,
timestamp: 1717959888
}
],
contexts: %{
runtime: %{name: "elixir", version: "1.16.2 (compiled with Erlang/OTP 26)"},
os: %{name: "darwin", version: "23.3.0"}
},
dist: nil,
environment: "dev",
exception: [],
extra: %{
domain: [:elixir],
logger_level: :error,
logger_metadata: %{line: 225, file: "lib/bandit/pipeline.ex"},
user_agent: "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0",
socket_id: "phx-F9drao1fyRZrWQGC"
},
fingerprint: ["{{ default }}"],
level: :error,
logger: nil,
message: %Sentry.Interfaces.Message{
message: nil,
params: nil,
formatted: "** (RuntimeError) Timeout waiting for space in the send_window\n (visual_garden 0.1.0) lib/visual_garden_web/live/home_live/show.ex:15: VisualGardenWeb.HomeLive.Show.mount/3\n (phoenix_live_view 0.20.14) lib/phoenix_live_view/utils.ex:354: anonymous fn/6 in Phoenix.LiveView.Utils.maybe_call_live_view_mount!/5\n (telemetry 1.2.1) /Users/theron/code/visual_garden/deps/telemetry/src/telemetry.erl:321: :telemetry.span/3\n (phoenix_live_view 0.20.14) lib/phoenix_live_view/static.ex:281: Phoenix.LiveView.Static.call_mount_and_handle_params!/5\n (phoenix_live_view 0.20.14) lib/phoenix_live_view/static.ex:116: Phoenix.LiveView.Static.render/3\n (phoenix_live_view 0.20.14) lib/phoenix_live_view/controller.ex:39: Phoenix.LiveView.Controller.live_render/3\n (phoenix 1.7.12) lib/phoenix/router.ex:484: Phoenix.Router.__call__/5\n (visual_garden 0.1.0) lib/visual_garden_web/endpoint.ex:1: VisualGardenWeb.Endpoint.plug_builder_call/2\n (visual_garden 0.1.0) lib/visual_garden_web/endpoint.ex:1: VisualGardenWeb.Endpoint.\"call (overridable 3)\"/2\n (visual_garden 0.1.0) deps/plug/lib/plug/debugger.ex:136: VisualGardenWeb.Endpoint.\"call (overridable 4)\"/2\n (visual_garden 0.1.0) lib/visual_garden_web/endpoint.ex:1: VisualGardenWeb.Endpoint.call/2\n (phoenix 1.7.12) lib/phoenix/endpoint/sync_code_reload_plug.ex:22: Phoenix.Endpoint.SyncCodeReloadPlug.do_call/4\n (bandit 1.5.2) lib/bandit/pipeline.ex:124: Bandit.Pipeline.call_plug!/2\n (bandit 1.5.2) lib/bandit/pipeline.ex:36: Bandit.Pipeline.run/4\n (bandit 1.5.2) lib/bandit/http1/handler.ex:12: Bandit.HTTP1.Handler.handle_data/3\n (bandit 1.5.2) lib/bandit/delegating_handler.ex:18: Bandit.DelegatingHandler.handle_data/3\n (bandit 1.5.2) /Users/theron/code/visual_garden/deps/thousand_island/lib/thousand_island/handler.ex:379: Bandit.DelegatingHandler.handle_info/2\n (stdlib 5.0.2) gen_server.erl:1077: :gen_server.try_handle_info/3\n (stdlib 5.0.2) gen_server.erl:1165: :gen_server.handle_msg/6\n (stdlib 5.0.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3\n"
},
modules: %{
"site_encrypt" => "0.6.0",
"certifi" => "2.12.0",
"telemetry" => "1.2.1",
"asn1" => "5.1",
"comeonin" => "5.4.0",
"parent" => "0.12.1",
"expo" => "0.5.2",
"phoenix_html" => "4.1.1",
"ecto_sql" => "3.11.1",
"plug" => "1.16.0",
"iex" => "1.16.2",
"jose" => "1.11.10",
"kernel" => "9.0.2",
"x509" => "0.8.8",
"phoenix" => "1.7.12",
"runtime_tools" => "2.0",
"unicode_util_compat" => "0.7.0",
"esbuild" => "0.8.1",
"mix" => "1.16.2",
"phoenix_live_reload" => "1.5.2",
"castore" => "1.0.7",
"phx_component_helpers" => "1.4.1",
"timex" => "3.7.11",
"hpax" => "0.1.2",
"tailwind" => "0.2.2",
"logger" => "1.16.2",
"nimble_options" => "1.1.0",
"ssl" => "11.0.2",
"inets" => "9.0.1",
"compiler" => "8.3.2",
"makeup_elixir" => "0.16.2",
"finch" => "0.18.0",
"mime" => "2.0.5",
"makeup" => "1.1.1",
"decimal" => "2.1.1",
"telemetry_poller" => "1.0.0",
"crypto" => "5.2",
...
},
platform: :elixir,
release: nil,
request: %Sentry.Interfaces.Request{
method: "GET",
url: "http://localhost:4000/home/?",
query_string: "",
data: %{},
cookies: %{},
headers: %{
"accept" => "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8",
"accept-encoding" => "gzip, deflate, br, zstd",
"accept-language" => "en-US,en;q=0.5",
"connection" => "keep-alive",
"host" => "localhost:4000",
"priority" => "u=1",
"referer" => "http://localhost:4000/users/log_in",
"sec-fetch-dest" => "document",
"sec-fetch-mode" => "navigate",
"sec-fetch-site" => "same-origin",
"upgrade-insecure-requests" => "1",
"user-agent" => "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0"
},
env: %{
"REMOTE_ADDR" => "127.0.0.1",
"REMOTE_PORT" => nil,
"REQUEST_ID" => "F9draorliQYSa1kAAAFi",
"SERVER_NAME" => "localhost",
"SERVER_PORT" => 4000
}
},
sdk: %Sentry.Interfaces.SDK{name: "sentry-elixir", version: "10.5.0"},
server_name: "Therons-Air.hsd1.fl.comcast.net",
tags: %{},
transaction: nil,
threads: nil,
user: %{user_id: 1},
culprit: nil,
attachments: [],
source: :logger,
original_exception: nil
}
Also, does this mean that all of my errors are being double-caught? Once as the error itself and then secondly as part of the logger? That doesn't seem like the desired behavior.
@hunterboerner this might be a problem with the :domain setting (see https://github.com/getsentry/sentry-elixir/commit/c4b2facee4b7c2235fd132b8513c0c9f97a947ac), but I see that it's just [:elixir] above. @mtrudel any idea what's going on here, if it's something Bandit-related?
We only added :bandit as the logging domain in 1.5.5, released on 19 Jun. If you're running a version older than that I think you should expect to the see the behaviour you're seeing
@hunterboerner could you give the newly-releases Sentry 10.6.2 + Bandit >= 1.5.5 a try? I think they should fix this up.
Haven't heard back on this so assuming that this has been fixed. Please feel free to comment and we'll reopen if this is still an issue 🙃