Add try/catch around handle_message() to catch errors during logging. (…

…JuliaLang#57004)

Fixes JuliaLang#56889.

Before this PR, an exception thrown while constructing the objects to
log (the `msg`) would be caught and logged. However, an exception thrown
while _printing_ the msg to an IO would _not_ be caught, and can abort
the program. This breaks the promise that enabling verbose debug logging
shouldn't introduce new crashes.

After this PR, an exception thrown during handle_message is caught and
logged, just like an exception during `msg` construction:

```julia
julia> struct Foo end

julia> Base.show(::IO, ::Foo) = error("oh no")

julia> begin
           # Unexpectedly, the execption thrown while printing `Foo()` escapes
           @info Foo()
           # So we never reach this line! :'(
           println("~~~~~ ALL DONE ~~~~~~~~")
       end
┌ Error: Exception while generating log record in module Main at REPL[10]:3
│   exception =
│    oh no
│    Stacktrace:
│      [1] error(s::String)
│        @ Base ./error.jl:44
│      [2] show(::IOBuffer, ::Foo)
│        @ Main ./REPL[9]:1
...
│     [30] repl_main
│        @ ./client.jl:593 [inlined]
│     [31] _start()
│        @ Base ./client.jl:568
└ @ Main REPL[10]:3
~~~~~ ALL DONE ~~~~~~~~
```

This PR respects the change made in
JuliaLang#36600 to keep the codegen as
small as possible, by putting the new try/catch into a no-inlined
function, so that we don't have to introduce a new try/catch in the
macro-generated code body.

---------

Co-authored-by: Jameson Nash <[email protected]>

base/logging.jl

@@ -398,7 +398,7 @@ function logmsg_code(_module, file, line, level, message, exs...)
                         end
                         line = $(log_data._line)
                         local msg, kwargs
-                        $(logrecord) && invokelatest($handle_message,
+                        $(logrecord) && $handle_message_nothrow(
                             logger, level, msg, _module, group, id, file, line;
                             kwargs...)
                     end
@@ -409,6 +409,18 @@ function logmsg_code(_module, file, line, level, message, exs...)
     end
 end
 
+@noinline function handle_message_nothrow(logger, level, msg, _module, group, id, file, line; kwargs...)
+    @nospecialize
+    try
+        @invokelatest handle_message(
+            logger, level, msg, _module, group, id, file, line;
+            kwargs...)
+
+    catch err
+        @invokelatest logging_error(logger, level, _module, group, id, file, line, err, true)
+    end
+end
+
 function process_logmsg_exs(_orig_module, _file, _line, level, message, exs...)
     @nospecialize
     local _group, _id

test/corelogging.jl

@@ -114,6 +114,19 @@ end
         @test only(collect_test_logs(logmsg)[1]).kwargs[:x] === "the y"
     end
 end
+@testset "Log message handle_message exception handling" begin
+    # Exceptions in log handling (printing) of msg are caught by default.
+    struct Foo end
+    Base.show(::IO, ::Foo) = 1 ÷ 0
+
+    # We cannot use `@test_logs` here, since test_logs does not actually _print_ the message
+    # (i.e. it does not invoke handle_message). To test exception handling during printing,
+    # we have to use `@test_warn` to see what was printed.
+    @test_warn r"Error: Exception while generating log record in module .*DivideError: integer division error"s @info Foo()
+
+    # Exceptions in log handling (printing) of attributes are caught by default
+    @test_warn r"Error: Exception while generating log record in module .*DivideError: integer division error"s @info "foo" x=Foo()
+end
 
 @testset "Special keywords" begin
     logger = TestLogger()