Attempt to improve plug call exception handling and logging #398

grzuy · 2024-09-16T13:48:09Z

Supersedes #396.

Telementry events
- Also emit span for throw
- Also emit span for exit
Logger
- Lets logger handlers know about the original crash reason when handling bandit errors
  - References:
    - Elixir Logger crash_reason: https://github.com/elixir-lang/elixir/blob/4bbddcc053498ca28ea5ebb5039de9b3a97ddf82/lib/logger/lib/logger.ex#L130-L135
    - Broadway passing crash_reason: https://github.com/dashbitco/broadway/blob/9eaf2140b6c1f36b25f990a7c74052bece26aadc/lib/broadway/acknowledger.ex#L104-L113
    - Plug.Cowboy passing crash_reason: https://github.com/elixir-plug/plug_cowboy/blob/746d848baca3436ca74fdab2750d14070b92002b/lib/plug/cowboy/translator.ex#L42-L46

- Telementry events - Also emit span for throw - Also emit span for exit - Logger - Lets logger handlers know about the original crash reason when handling bandit errors

mtrudel · 2024-09-16T20:41:41Z

lib/bandit/pipeline.ex

-      rescue
-        error -> handle_error(error, __STACKTRACE__, transport, span, opts)


I know it's redundant with the catch block below (raise being realized by try/catch internally), but I don't think it's part of official spec; can we leave this clause here to make it explicit? Alternately, if the language is authoritative on this, that's fine too.

Right.

Despite working like that doesn't seem to be actually documented in https://hexdocs.pm/elixir/try-catch-and-rescue.html that you can catch all (including :error) with just catch.

Re-instating the rescue clause just in case.

Good call. It sounds like it's an implementation detail then, so we're safer to be explicit in case they ever change it in the language.

mtrudel · 2024-09-16T20:43:53Z

lib/bandit/telemetry.ex

+      * `reason`: The exception, throw value or exit reason which caused this unexpected termination
+      * `stacktrace`: The stacktrace of the location which caused this unexpected termination
+
+  * `[:bandit, :request, :exception]` (DEPRECATED)


I realize that exception is (and always has been) the wrong term here, but I've deliberately been using it to mirror the naming conventions of :telemetry.span/3.

Gotcha.

I only introduced a new event name just to not break the shape of the actual one when supporting more kinds.

Updating back to only [:bandit, :request, :exception], with the correct kind and reason field, and maybe keeping the exception field in case is_exception(reason), so that this doesn't break peoples telemetry handlers listening and matching on that metadata field.

It will break anyone matching on kind: :exit and exception: exception at the same time. This will now be corrected to kind: :error and exception: exception.

That's fine

mtrudel · 2024-09-16T20:45:23Z

A couple of changes requested to keep things consistent and explicit; other than those changes the rest of this looks great!

grzuy · 2024-09-17T16:44:31Z

Fixed format.

Can't reproduce locally the protocol_test.exs failures happening here, though.

grzuy · 2024-09-17T18:05:31Z

@mtrudel Just realized that Bandit was originally taking the approach of re-raising plug call errors in 1.4 instead of just "logging or silence" with changes in 1.5 with https://github.com/mtrudel/bandit/pull/342/files#diff-68626306df11d3e10964941997c6cdafbf587a9ec7de087141840655a47a1855L65.

Curious about the reason not to continue re-raising?

Similar to what plug_cowboy does...

In case there's the possibility of introducing re-raise again, this pull request could be re-worked.

grzuy · 2024-09-17T18:14:15Z

Reading this thread (https://groups.google.com/g/elixir-lang-core/c/pWz-uTVMEVM/m/QGXncxD1AQAJ) also got me thinking about it.

mtrudel · 2024-09-17T18:17:52Z

Similar to what plug_cowboy does...

Interesting! It seems like they're using exactly the 'catch :error types' convention I raised above, such that exceptions are in fact re-raising. I think when I'd read the plug_cowboy implementation originally I saw the catch and assumed that handling was only for idiomatic throw/catch usage (which the current Bandit implementation handles).

The main purpose of that PR was to ensure that logging of errors takes into consideration the accompanying result code (ie: only log errors that get raised with a 500..599 response code). This generally means that we do the logging ourselves (as we do in that PR) instead of reraising and letting the runtime log it

All of which is to say that I think we're doing the right thing by not re-raising?

grzuy · 2024-09-18T15:45:13Z

Mmm... not sure to he honest.

I'm exploring the "re-raising approach" in a separate branch to compare.

I'll let you know how it goes.

grzuy · 2024-09-18T19:50:48Z

I'm exploring the "re-raising approach" in a separate branch to compare.

Opening draft with what I got from playing with that alternative approach: #400.

grzuy · 2024-10-23T17:51:54Z

lib/bandit/pipeline.ex

+        error -> handle_error(:error, error, __STACKTRACE__, transport, span, opts)
+      catch
+        kind, reason ->
+          handle_error(kind, reason, __STACKTRACE__, transport, span, opts)


This is not right.
It will catch and handle "normal" exists as errors.

grzuy · 2024-10-23T18:19:57Z

Closing in favor smaller and more focused #411 for now.
Will revisit and build on top of #411 if that one accepted and merged.

grzuy · 2024-11-01T13:11:04Z

lib/bandit/pipeline.ex

+      Logger.error(
+        Exception.format(kind, reason, stacktrace),
+        domain: [:bandit],
+        crash_reason: crash_reason(kind, reason, stacktrace)


For the record, reported separate issue for "missing crash_reason" so it can be tackled separately: #413.

More complete exception handling and logging

1d6e26f

- Telementry events - Also emit span for throw - Also emit span for exit - Logger - Lets logger handlers know about the original crash reason when handling bandit errors

grzuy changed the title ~~More complete exception handling and logging~~ Attempt to improve exception handling and logging Sep 16, 2024

don't break existing [:bandit, :request, :exception] telemetry handlers

a4205ba

grzuy mentioned this pull request Sep 16, 2024

Handle throwing plug call #396

Closed

mtrudel reviewed Sep 16, 2024

View reviewed changes

grzuy added 3 commits September 17, 2024 09:32

re-add rescue

2935e31

keep only improved exception telemetry event

49d0aad

keep exception metadata field for backwards compatibility

c6347e1

grzuy force-pushed the error-handling branch from 7765728 to c6347e1 Compare September 17, 2024 13:16

mtrudel force-pushed the main branch 2 times, most recently from 12d7cc5 to 8dc344f Compare September 17, 2024 15:01

grzuy added 2 commits September 17, 2024 13:01

Merge branch 'main' into error-handling

6fe26bf

mix format

34e0a1a

grzuy changed the title ~~Attempt to improve exception handling and logging~~ Attempt to improve plug call exception handling and logging Sep 17, 2024

grzuy mentioned this pull request Sep 18, 2024

Error handling and logging improvements via re-raising #400

Closed

Merge branch 'main' into error-handling

fc612cd

grzuy commented Oct 23, 2024

View reviewed changes

grzuy mentioned this pull request Oct 23, 2024

fix: throwing plug properly handled and returns 500 #411

Merged

grzuy closed this Oct 23, 2024

grzuy commented Nov 1, 2024

View reviewed changes

grzuy deleted the error-handling branch November 1, 2024 13:11

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Attempt to improve plug call exception handling and logging #398

Attempt to improve plug call exception handling and logging #398

grzuy commented Sep 16, 2024

mtrudel Sep 16, 2024

grzuy Sep 17, 2024

mtrudel Sep 17, 2024

mtrudel Sep 16, 2024

grzuy Sep 17, 2024 •

edited

Loading

mtrudel Sep 17, 2024

mtrudel commented Sep 16, 2024

grzuy commented Sep 17, 2024 •

edited

Loading

grzuy commented Sep 17, 2024 •

edited

Loading

grzuy commented Sep 17, 2024 •

edited

Loading

mtrudel commented Sep 17, 2024

grzuy commented Sep 18, 2024

grzuy commented Sep 18, 2024

grzuy Oct 23, 2024

grzuy commented Oct 23, 2024

grzuy Nov 1, 2024

		rescue
		error -> handle_error(error, __STACKTRACE__, transport, span, opts)

Attempt to improve plug call exception handling and logging #398

Attempt to improve plug call exception handling and logging #398

Conversation

grzuy commented Sep 16, 2024

mtrudel Sep 16, 2024

Choose a reason for hiding this comment

grzuy Sep 17, 2024

Choose a reason for hiding this comment

mtrudel Sep 17, 2024

Choose a reason for hiding this comment

mtrudel Sep 16, 2024

Choose a reason for hiding this comment

grzuy Sep 17, 2024 • edited Loading

Choose a reason for hiding this comment

mtrudel Sep 17, 2024

Choose a reason for hiding this comment

mtrudel commented Sep 16, 2024

grzuy commented Sep 17, 2024 • edited Loading

grzuy commented Sep 17, 2024 • edited Loading

grzuy commented Sep 17, 2024 • edited Loading

mtrudel commented Sep 17, 2024

grzuy commented Sep 18, 2024

grzuy commented Sep 18, 2024

grzuy Oct 23, 2024

Choose a reason for hiding this comment

grzuy commented Oct 23, 2024

grzuy Nov 1, 2024

Choose a reason for hiding this comment

grzuy Sep 17, 2024 •

edited

Loading

grzuy commented Sep 17, 2024 •

edited

Loading

grzuy commented Sep 17, 2024 •

edited

Loading

grzuy commented Sep 17, 2024 •

edited

Loading