diff --git a/NEWS.md b/NEWS.md index f507c77a65e65..5df1b3af51ee9 100644 --- a/NEWS.md +++ b/NEWS.md @@ -109,6 +109,7 @@ Standard library changes * The `Pkg.BinaryPlatforms` module has been moved into `Base` as `Base.BinaryPlatforms` and heavily reworked. Applications that want to be compatible with the old API should continue to import `Pkg.BinaryPlatforms`, however new users should use `Base.BinaryPlatforms` directly. ([#37320]) +* Logging (such as `@warn`) no longer catches exceptions in the logger itself ([#36600]). * The `Pkg.Artifacts` module has been imported as a separate standard library. It is still available as `Pkg.Artifacts`, however starting from Julia v1.6+, packages may import simply `Artifacts` without importing all of `Pkg` alongside. ([#37320]) diff --git a/base/compiler/optimize.jl b/base/compiler/optimize.jl index d53b8193e639a..90324b9665175 100644 --- a/base/compiler/optimize.jl +++ b/base/compiler/optimize.jl @@ -258,7 +258,7 @@ function optimize(opt::OptimizationState, params::OptimizationParams, @nospecial # obey @inline declaration if a dispatch barrier would not help else bonus = 0 - if result ⊑ Tuple && !isbitstype(widenconst(result)) + if result ⊑ Tuple && !isconcretetype(widenconst(result)) bonus = params.inline_tupleret_bonus end if opt.src.inlineable diff --git a/base/compiler/tfuncs.jl b/base/compiler/tfuncs.jl index a938d86f953ae..b2b539c481b9b 100644 --- a/base/compiler/tfuncs.jl +++ b/base/compiler/tfuncs.jl @@ -592,7 +592,7 @@ function isa_tfunc(@nospecialize(v), @nospecialize(tt)) # TODO: handle non-leaftype(t) by testing against lower and upper bounds return Bool end -add_tfunc(isa, 2, 2, isa_tfunc, 0) +add_tfunc(isa, 2, 2, isa_tfunc, 1) function subtype_tfunc(@nospecialize(a), @nospecialize(b)) a, isexact_a = instanceof_tfunc(a) @@ -610,7 +610,7 @@ function subtype_tfunc(@nospecialize(a), @nospecialize(b)) end return Bool end -add_tfunc(<:, 2, 2, subtype_tfunc, 0) +add_tfunc(<:, 2, 2, subtype_tfunc, 10) is_dt_const_field(fld::Int) = ( fld == DATATYPE_NAME_FIELDINDEX || diff --git a/base/compiler/types.jl b/base/compiler/types.jl index 45a5bfcb12169..3ca6cff20ccd6 100644 --- a/base/compiler/types.jl +++ b/base/compiler/types.jl @@ -44,7 +44,7 @@ struct OptimizationParams inlining::Bool # whether inlining is enabled inline_cost_threshold::Int # number of CPU cycles beyond which it's not worth inlining inline_nonleaf_penalty::Int # penalty for dynamic dispatch - inline_tupleret_bonus::Int # extra willingness for non-isbits tuple return types + inline_tupleret_bonus::Int # extra inlining willingness for non-concrete tuple return types (in hopes of splitting it up) inline_error_path_cost::Int # cost of (un-optimized) calls in blocks that throw # Duplicating for now because optimizer inlining requires it. @@ -59,7 +59,7 @@ struct OptimizationParams inlining::Bool = inlining_enabled(), inline_cost_threshold::Int = 100, inline_nonleaf_penalty::Int = 1000, - inline_tupleret_bonus::Int = 400, + inline_tupleret_bonus::Int = 250, inline_error_path_cost::Int = 20, max_methods::Int = 3, tuple_splat::Int = 32, diff --git a/base/logging.jl b/base/logging.jl index 653ded32e443d..ec0921288852c 100644 --- a/base/logging.jl +++ b/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 === :(=) - k,v = ex.args + k, v = ex.args if !(k isa Symbol) k = Symbol(k) 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"), " ", diff --git a/stdlib/Logging/src/ConsoleLogger.jl b/stdlib/Logging/src/ConsoleLogger.jl index 4a73f10932dc7..8bc51c0d0b770 100644 --- a/stdlib/Logging/src/ConsoleLogger.jl +++ b/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,8 +97,11 @@ 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 @@ -105,29 +109,30 @@ function handle_message(logger::ConsoleLogger, level, message, _module, group, i # 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) ? "│ " : diff --git a/test/choosetests.jl b/test/choosetests.jl index 9ca97a543123c..887814c6bab0a 100644 --- a/test/choosetests.jl +++ b/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", "binaryplatforms", + "misc", "threads", "stress", "binaryplatforms", "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 = [] diff --git a/test/logging.jl b/test/corelogging.jl similarity index 91% rename from test/logging.jl rename to test/corelogging.jl index 0109664dff834..3e4523a322998 100644 --- a/test/logging.jl +++ b/test/corelogging.jl @@ -88,12 +88,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 @@ -390,7 +406,7 @@ end (record,), _ = collect_test_logs() do @info "test" end - @test record.group == :logging # name of this file + @test record.group == :corelogging # name of this file end end