Unable to catch exception caught by logger

[hunterboerner]

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
}

[hunterboerner]

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.

[whatyouhide]

@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?

[mtrudel]

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

[whatyouhide]

@hunterboerner could you give the newly-releases Sentry 10.6.2 + Bandit >= 1.5.5 a try? I think they should fix this up.