logging: avoid try/catch when the message is a simple

This should avoid the try/catch in some cases, where the message is
simply a constant value or simple variable. It also tries to slightly
reduce required specialization in some other cases too.

Author: vtjnash

NEWS.md

@@ -88,6 +88,7 @@ Standard library changes
 * `RegexMatch` objects can now be probed for whether a named capture group exists within it through `haskey()` ([#36717]).
 * For consistency `haskey(r::RegexMatch, i::Integer)` has also been added and returns if the capture group for `i` exists ([#37300]).
 * A new standard library `TOML` has been added for parsing and printing [TOML files](https://toml.io) ([#37034]).
+* Logging (such as `@warn`) no longer catches exceptions in the logger itself ([#36600]).
 
 #### LinearAlgebra
 * New method `LinearAlgebra.issuccess(::CholeskyPivoted)` for checking whether pivoted Cholesky factorization was successful ([#36002]).

base/logging.jl

@@ -254,6 +254,7 @@ _log_record_ids = Set{Symbol}()
 # across versions of the originating module, provided the log generating
 # statement itself doesn't change.
 function log_record_id(_module, level, message, log_kws)
+    @nospecialize
     modname = _module === nothing ?  "" : join(fullname(_module), "_")
     # Use an arbitrarily chosen eight hex digits here. TODO: Figure out how to
     # make the id exactly the same on 32 and 64 bit systems.
@@ -274,48 +275,112 @@ end
 
 default_group(file) = Symbol(splitext(basename(file))[1])
 
+function issimple(@nospecialize val)
+    val isa String && return true
+    val isa Symbol && return true
+    val isa QuoteNode && return true
+    val isa Number && return true
+    val isa Char && return true
+    if val isa Expr
+        val.head === :quote && issimple(val[1]) && return true
+        val.head === :inert && return true
+    end
+    return false
+end
+function issimplekw(@nospecialize val)
+    if val isa Expr
+        if val.head === :kw
+            val = val.args[2]
+            if val isa Expr && val.head === :escape
+                issimple(val.args[1]) && return true
+            end
+        end
+    end
+    return false
+end
+
 # Generate code for logging macros
 function logmsg_code(_module, file, line, level, message, exs...)
+    @nospecialize
     log_data = process_logmsg_exs(_module, file, line, level, message, exs...)
-    quote
-    let
-        level = $level
-        std_level = convert(LogLevel, level)
-        if std_level >= getindex(_min_enabled_level)
-            group = $(log_data._group)
-            _module = $(log_data._module)
-            logger = current_logger_for_env(std_level, group, _module)
-            if !(logger === nothing)
-                id = $(log_data._id)
-                # Second chance at an early bail-out (before computing the message),
-                # based on arbitrary logger-specific logic.
-                if _invoked_shouldlog(logger, level, _module, group, id)
-                    file = $(log_data._file)
-                    line = $(log_data._line)
-                    try
-                        msg = $(esc(message))
-                        handle_message(
+    if !isa(message, Symbol) && issimple(message) && isempty(log_data.kwargs)
+        logrecord = quote
+            msg = $(message)
+            kwargs = (;)
+            true
+        end
+    elseif issimple(message) && all(issimplekw, log_data.kwargs)
+        # if message and kwargs are just values and variables, we can avoid try/catch
+        # complexity by adding the code for testing the UndefVarError by hand
+        checkerrors = nothing
+        for kwarg in reverse(log_data.kwargs)
+            if isa(kwarg.args[2].args[1], Symbol)
+                checkerrors = Expr(:if, Expr(:isdefined, kwarg.args[2]), checkerrors, Expr(:call, Expr(:core, :UndefVarError), QuoteNode(kwarg.args[2].args[1])))
+            end
+        end
+        if isa(message, Symbol)
+            message = esc(message)
+            checkerrors = Expr(:if, Expr(:isdefined, message), checkerrors, Expr(:call, Expr(:core, :UndefVarError), QuoteNode(message.args[1])))
+        end
+        logrecord = quote
+            let err = $checkerrors
+                if err === nothing
+                    msg = $(message)
+                    kwargs = (;$(log_data.kwargs...))
+                    true
+                else
+                    logging_error(logger, level, _module, group, id, file, line, err, false)
+                    false
+                end
+            end
+        end
+    else
+        logrecord = quote
+            try
+                msg = $(esc(message))
+                kwargs = (;$(log_data.kwargs...))
+                true
+            catch err
+                logging_error(logger, level, _module, group, id, file, line, err, true)
+                false
+            end
+        end
+    end
+    return quote
+        let
+            level = $level
+            std_level = convert(LogLevel, level)
+            if std_level >= getindex(_min_enabled_level)
+                group = $(log_data._group)
+                _module = $(log_data._module)
+                logger = current_logger_for_env(std_level, group, _module)
+                if !(logger === nothing)
+                    id = $(log_data._id)
+                    # Second chance at an early bail-out (before computing the message),
+                    # based on arbitrary logger-specific logic.
+                    if _invoked_shouldlog(logger, level, _module, group, id)
+                        file = $(log_data._file)
+                        line = $(log_data._line)
+                        local msg, kwargs
+                        $(logrecord) && handle_message(
                             logger, level, msg, _module, group, id, file, line;
-                            $(log_data.kwargs...)
-                        )
-                    catch err
-                        logging_error(logger, level, _module, group, id, file, line, err)
+                            kwargs...)
                     end
                 end
             end
+            nothing
         end
-        nothing
-    end
     end
 end
 
 function process_logmsg_exs(_orig_module, _file, _line, level, message, exs...)
+    @nospecialize
     local _group, _id
     _module = _orig_module
     kwargs = Any[]
     for ex in exs
         if ex isa Expr && ex.head === :(=) && ex.args[1] isa Symbol
-            k,v = ex.args
+            k, v = ex.args
             if !(k isa Symbol)
                 throw(ArgumentError("Expected symbol for key in key value pair `$ex`"))
             end
@@ -352,6 +417,7 @@ function process_logmsg_exs(_orig_module, _file, _line, level, message, exs...)
 end
 
 function default_group_code(file)
+    @nospecialize
     if file isa String && isdefined(Base, :basename)
         QuoteNode(default_group(file))  # precompute if we can
     else
@@ -361,39 +427,34 @@ function default_group_code(file)
 end
 
 
-# Report an error in log message creation (or in the logger itself).
+# Report an error in log message creation
 @noinline function logging_error(logger, level, _module, group, id,
-                                 filepath, line, @nospecialize(err))
+                                 filepath, line, @nospecialize(err), real::Bool)
+    @nospecialize
     if !_invoked_catch_exceptions(logger)
-        rethrow(err)
-    end
-    try
-        msg = "Exception while generating log record in module $_module at $filepath:$line"
-        handle_message(
-            logger, Error, msg, _module, :logevent_error, id, filepath, line;
-            exception=(err,catch_backtrace())
-        )
-    catch err2
-        try
-            # Give up and write to stderr, in three independent calls to
-            # increase the odds of it getting through.
-            print(stderr, "Exception handling log message: ")
-            println(stderr, err)
-            println(stderr, "  module=$_module  file=$filepath  line=$line")
-            println(stderr, "  Second exception: ", err2)
-        catch
-        end
+        real ? rethrow(err) : throw(err)
     end
+    msg = try
+              "Exception while generating log record in module $_module at $filepath:$line"
+          catch ex
+              "Exception handling log message: $ex"
+          end
+    bt = real ? catch_backtrace() : backtrace()
+    handle_message(
+        logger, Error, msg, _module, :logevent_error, id, filepath, line;
+        exception=(err,bt))
     nothing
 end
 
 # Log a message. Called from the julia C code; kwargs is in the format
 # Any[key1,val1, ...] for simplicity in construction on the C side.
 function logmsg_shim(level, message, _module, group, id, file, line, kwargs)
-    real_kws = Any[(kwargs[i],kwargs[i+1]) for i in 1:2:length(kwargs)]
+    @nospecialize
+    real_kws = Any[(kwargs[i], kwargs[i+1]) for i in 1:2:length(kwargs)]
     @logmsg(convert(LogLevel, level), message,
             _module=_module, _id=id, _group=group,
             _file=String(file), _line=line, real_kws...)
+    nothing
 end
 
 # Global log limiting mechanism for super fast but inflexible global log limiting.
@@ -574,8 +635,10 @@ min_enabled_level(logger::SimpleLogger) = logger.min_level
 catch_exceptions(logger::SimpleLogger) = false
 
 function handle_message(logger::SimpleLogger, level, message, _module, group, id,
-                        filepath, line; maxlog=nothing, kwargs...)
-    if maxlog !== nothing && maxlog isa Integer
+                        filepath, line; kwargs...)
+    @nospecialize
+    maxlog = get(kwargs, :maxlog, nothing)
+    if maxlog isa Integer
         remaining = get!(logger.message_limits, id, maxlog)
         logger.message_limits[id] = remaining - 1
         remaining > 0 || return
@@ -589,6 +652,7 @@ function handle_message(logger::SimpleLogger, level, message, _module, group, id
         println(iob, "│ ", msglines[i])
     end
     for (key, val) in kwargs
+        key === :maxlog && continue
         println(iob, "│   ", key, " = ", val)
     end
     println(iob, "└ @ ", something(_module, "nothing"), " ",

stdlib/Logging/src/ConsoleLogger.jl

@@ -58,6 +58,7 @@ function default_logcolor(level)
 end
 
 function default_metafmt(level, _module, group, id, file, line)
+    @nospecialize
     color = default_logcolor(level)
     prefix = (level == Warn ? "Warning" : string(level))*':'
     suffix = ""
@@ -96,38 +97,42 @@ function termlength(str)
 end
 
 function handle_message(logger::ConsoleLogger, level, message, _module, group, id,
-                        filepath, line; maxlog=nothing, kwargs...)
-    if maxlog !== nothing && maxlog isa Integer
+                        filepath, line; kwargs...)
+    @nospecialize
+    hasmaxlog = haskey(kwargs, :maxlog) ? 1 : 0
+    maxlog = get(kwargs, :maxlog, nothing)
+    if maxlog isa Integer
         remaining = get!(logger.message_limits, id, maxlog)
         logger.message_limits[id] = remaining - 1
         remaining > 0 || return
     end
 
     # Generate a text representation of the message and all key value pairs,
     # split into lines.
-    msglines = [(indent=0,msg=l) for l in split(chomp(string(message)), '\n')]
+    msglines = [(indent=0, msg=l) for l in split(chomp(string(message)), '\n')]
     dsize = displaysize(logger.stream)::Tuple{Int,Int}
-    if !isempty(kwargs)
+    if length(kwargs) > hasmaxlog
         valbuf = IOBuffer()
-        rows_per_value = max(1, dsize[1]÷(length(kwargs)+1))
+        rows_per_value = max(1, dsize[1] ÷ (length(kwargs) + 1 - hasmaxlog))
         valio = IOContext(IOContext(valbuf, logger.stream),
-                          :displaysize => (rows_per_value,dsize[2]-5),
+                          :displaysize => (rows_per_value, dsize[2] - 5),
                           :limit => logger.show_limited)
-        for (key,val) in pairs(kwargs)
+        for (key, val) in kwargs
+            key === :maxlog && continue
             showvalue(valio, val)
             vallines = split(String(take!(valbuf)), '\n')
             if length(vallines) == 1
-                push!(msglines, (indent=2,msg=SubString("$key = $(vallines[1])")))
+                push!(msglines, (indent=2, msg=SubString("$key = $(vallines[1])")))
             else
-                push!(msglines, (indent=2,msg=SubString("$key =")))
-                append!(msglines, ((indent=3,msg=line) for line in vallines))
+                push!(msglines, (indent=2, msg=SubString("$key =")))
+                append!(msglines, ((indent=3, msg=line) for line in vallines))
             end
         end
     end
 
     # Format lines as text with appropriate indentation and with a box
     # decoration on the left.
-    color,prefix,suffix = logger.meta_formatter(level, _module, group, id, filepath, line)::Tuple{Union{Symbol,Int},String,String}
+    color, prefix, suffix = logger.meta_formatter(level, _module, group, id, filepath, line)::Tuple{Union{Symbol,Int},String,String}
     minsuffixpad = 2
     buf = IOBuffer()
     iob = IOContext(buf, logger.stream)
@@ -136,11 +141,11 @@ function handle_message(logger::ConsoleLogger, level, message, _module, group, i
                   (isempty(suffix) ? 0 : length(suffix)+minsuffixpad)
     justify_width = min(logger.right_justify, dsize[2])
     if nonpadwidth > justify_width && !isempty(suffix)
-        push!(msglines, (indent=0,msg=SubString("")))
+        push!(msglines, (indent=0, msg=SubString("")))
         minsuffixpad = 0
         nonpadwidth = 2 + length(suffix)
     end
-    for (i,(indent,msg)) in enumerate(msglines)
+    for (i, (indent, msg)) in enumerate(msglines)
         boxstr = length(msglines) == 1 ? "[ " :
                  i == 1                ? "┌ " :
                  i < length(msglines)  ? "│ " :

test/choosetests.jl

@@ -49,12 +49,12 @@ function choosetests(choices = [])
         "euler", "show", "client",
         "errorshow", "sets", "goto", "llvmcall", "llvmcall2", "ryu",
         "some", "meta", "stacktraces", "docs",
-        "misc", "threads", "stress",
+        "misc", "threads", "stress", "atexit",
         "enums", "cmdlineargs", "int", "interpreter",
         "checked", "bitset", "floatfuncs", "precompile",
         "boundscheck", "error", "ambiguous", "cartesian", "osutils",
         "channels", "iostream", "secretbuffer", "specificity",
-        "reinterpretarray", "syntax", "logging", "missing", "asyncmap", "atexit"
+        "reinterpretarray", "syntax", "corelogging", "missing", "asyncmap"
     ]
 
     tests = []

test/logging.jl renamed to test/corelogging.jl

@@ -87,12 +87,28 @@ end
 
 @testset "Log message exception handling" begin
     # Exceptions in message creation are caught by default
-    @test_logs (Error,Test.Ignored(),Test.Ignored(),:logevent_error) catch_exceptions=true  @info "foo $(1÷0)"
+    @test_logs (Error, Test.Ignored(), Test.Ignored(), :logevent_error) catch_exceptions=true @info "foo $(1÷0)"
     # Exceptions propagate if explicitly disabled for the logger (by default
     # for the test logger)
     @test_throws DivideError collect_test_logs() do
         @info  "foo $(1÷0)"
     end
+    # trivial expressions create the errors explicitly instead of throwing them (to avoid try/catch)
+    for i in 1:2
+        local msg, x, y
+        logmsg = (function() @info msg x=y end,
+                  function() @info msg x=y z=1+1 end)[i]
+        @test_logs (Error, Test.Ignored(), Test.Ignored(), :logevent_error) catch_exceptions=true logmsg()
+        @test_throws UndefVarError(:msg) collect_test_logs(logmsg)
+        @test (only(collect_test_logs(logmsg, catch_exceptions=true)[1]).kwargs[:exception]::Tuple{UndefVarError, Vector})[1] === UndefVarError(:msg)
+        msg = "the msg"
+        @test_logs (Error, Test.Ignored(), Test.Ignored(), :logevent_error) catch_exceptions=true logmsg()
+        @test_throws UndefVarError(:y) collect_test_logs(logmsg)
+        @test (only(collect_test_logs(logmsg, catch_exceptions=true)[1]).kwargs[:exception]::Tuple{UndefVarError, Vector})[1] === UndefVarError(:y)
+        y = "the y"
+        @test_logs (Info,"the msg") logmsg()
+        @test only(collect_test_logs(logmsg)[1]).kwargs[:x] === "the y"
+    end
 end
 
 @testset "Special keywords" begin