From af7cda9b8cd0d3ba5f86a63c1e16844a2b871ec9 Mon Sep 17 00:00:00 2001 From: Chris Foster Date: Tue, 2 Jan 2018 20:49:29 +1000 Subject: [PATCH 1/2] ConsoleLogger for readable interactive logging Start of a ConsoleLogger optimized for viewing log records in the REPL. This is the SimpleLogger code copied and modified to: * Provide configurable metadata formatting * Right justify some of the metadata * Use show() and showerror() for formatting values in ConsoleLogger key value pairs. * Set the :limit IOContext key to sensibly show approximations of large data structures Also make this the default logger type so that users can get interface improvements by upgrading the stdlib Logging library rather than being bound to Base. --- base/sysimg.jl | 2 +- stdlib/Logging/src/ConsoleLogger.jl | 119 ++++++++++++++++++++ stdlib/Logging/src/Logging.jl | 5 +- stdlib/Logging/test/runtests.jl | 169 +++++++++++++++++++++++++++- 4 files changed, 292 insertions(+), 3 deletions(-) create mode 100644 stdlib/Logging/src/ConsoleLogger.jl diff --git a/base/sysimg.jl b/base/sysimg.jl index ab6906a7bd905..e8b57aaa39a50 100644 --- a/base/sysimg.jl +++ b/base/sysimg.jl @@ -472,7 +472,7 @@ isdefined(Core, :Inference) && Docs.loaddocs(Core.Inference.CoreDocs.DOCS) function __init__() # Base library init reinit_stdio() - global_logger(SimpleLogger(STDERR)) + global_logger(root_module(:Logging).ConsoleLogger(STDERR)) Multimedia.reinit_displays() # since Multimedia.displays uses STDOUT as fallback early_init() init_load_path() diff --git a/stdlib/Logging/src/ConsoleLogger.jl b/stdlib/Logging/src/ConsoleLogger.jl new file mode 100644 index 0000000000000..53c2b48f57f4b --- /dev/null +++ b/stdlib/Logging/src/ConsoleLogger.jl @@ -0,0 +1,119 @@ +# This file is a part of Julia. License is MIT: https://julialang.org/license + +""" + ConsoleLogger(stream=STDERR, min_level=Info; meta_formatter=default_metafmt, show_limited=true) + +Logger with formatting optimized for readability in a text console, for example +interactive work with the Julia REPL. + +Log levels less than `min_level` are filtered out. + +Message formatting can be controlled by setting keyword arguments: + +* `meta_formatter` is a function which takes the log event metadata + `(level, _module, group, id, file, line)` and produces a prefix and suffix + for the log message. The default is to prefix with the log level and add a + suffix containing the module, file and line location. +* `show_limited` limits the printing of large data structures to something + which can fit on the screen by setting the `:limit` `IOContext` key during + formatting. +""" +struct ConsoleLogger <: AbstractLogger + stream::IO + min_level::LogLevel + meta_formatter + show_limited::Bool + message_limits::Dict{Any,Int} +end +function ConsoleLogger(stream::IO=STDERR, min_level=Info; + meta_formatter=default_metafmt, show_limited=true) + ConsoleLogger(stream, min_level, meta_formatter, + show_limited, Dict{Any,Int}()) +end + +shouldlog(logger::ConsoleLogger, level, _module, group, id) = + get(logger.message_limits, id, 1) > 0 + +min_enabled_level(logger::ConsoleLogger) = logger.min_level + +# Formatting of values in key value pairs +showvalue(io, msg) = show(io, "text/plain", msg) +function showvalue(io, e::Tuple{Exception,Any}) + ex,bt = e + showerror(io, ex, bt; backtrace = bt!=nothing) +end +showvalue(io, ex::Exception) = showvalue(io, (ex,catch_backtrace())) + +function default_metafmt(level, _module, group, id, file, line) + ((level == Warn ? "Warning" : string(level))*':', + "@ $_module $(basename(file)):$line") +end + +function handle_message(logger::ConsoleLogger, level, message, _module, group, id, + filepath, line; maxlog=nothing, kwargs...) + if maxlog != nothing && maxlog isa Integer + remaining = get!(logger.message_limits, id, maxlog) + logger.message_limits[id] = remaining - 1 + remaining > 0 || return + end + color = level < Info ? Base.debug_color() : + level < Warn ? Base.info_color() : + level < Error ? Base.warn_color() : + Base.error_color() + buf = IOBuffer() + iob = IOContext(buf, logger.stream) + if logger.show_limited + iob = IOContext(iob, :limit=>true) + end + msglines = split(chomp(string(message)), '\n') + dsize = displaysize(logger.stream) + width = dsize[2] + prefix,suffix = logger.meta_formatter(level, _module, group, id, filepath, line) + length(prefix) == 0 || (prefix = prefix*" ") + length(suffix) == 0 || (suffix = " "*suffix) + singlelinewidth = 2 + length(msglines[1]) + length(prefix) + length(suffix) + issingleline = length(msglines) + length(kwargs) == 1 && singlelinewidth <= width + print_with_color(color, iob, issingleline ? "[ " : "┌ ", bold=true) + if length(prefix) > 0 + print_with_color(color, iob, prefix, bold=true) + end + print(iob, msglines[1]) + if issingleline + npad = (width - singlelinewidth) + else + println(iob) + for i in 2:length(msglines) + print_with_color(color, iob, "│ ", bold=true) + println(iob, msglines[i]) + end + valbuf = IOBuffer() + rows_per_value = max(1, dsize[1]÷(length(kwargs)+1)) + valio = IOContext(IOContext(valbuf, iob), + :displaysize=>(rows_per_value,dsize[2]-5)) + for (key,val) in pairs(kwargs) + print_with_color(color, iob, "│ ", bold=true) + print(iob, " ", key, " =") + showvalue(valio, val) + vallines = split(String(take!(valbuf)), '\n') + if length(vallines) == 1 + println(iob, " ", vallines[1]) + else + println(iob) + for line in vallines + print_with_color(color, iob, "│ ", bold=true) + println(iob, line) + end + end + end + print_with_color(color, iob, "└ ", bold=true) + npad = width - 2 - length(suffix) + end + if length(suffix) > 0 + print(iob, " "^npad) + print_with_color(:light_black, iob, suffix, bold=false) + end + print(iob, "\n") + write(logger.stream, take!(buf)) + nothing +end + diff --git a/stdlib/Logging/src/Logging.jl b/stdlib/Logging/src/Logging.jl index 00aef043ece1a..8e38277bd513c 100644 --- a/stdlib/Logging/src/Logging.jl +++ b/stdlib/Logging/src/Logging.jl @@ -39,7 +39,10 @@ export current_logger, global_logger, disable_logging, - SimpleLogger + SimpleLogger, + ConsoleLogger + +include("ConsoleLogger.jl") # The following are also part of the public API, but not exported: # diff --git a/stdlib/Logging/test/runtests.jl b/stdlib/Logging/test/runtests.jl index 1cf40077a1476..f0b39e840889e 100644 --- a/stdlib/Logging/test/runtests.jl +++ b/stdlib/Logging/test/runtests.jl @@ -1 +1,168 @@ -# TODO: Move SimpleLogger in here +using Logging + +import Logging: min_enabled_level, shouldlog, handle_message + +@noinline func1() = backtrace() + +@testset "Logging" begin + +@testset "ConsoleLogger" begin + # First pass log limiting + @test min_enabled_level(ConsoleLogger(DevNull, Logging.Debug)) == Logging.Debug + @test min_enabled_level(ConsoleLogger(DevNull, Logging.Error)) == Logging.Error + + # Second pass log limiting + logger = ConsoleLogger(DevNull) + @test shouldlog(logger, Logging.Info, Base, :group, :asdf) === true + handle_message(logger, Logging.Info, "msg", Base, :group, :asdf, "somefile", 1, maxlog=2) + @test shouldlog(logger, Logging.Info, Base, :group, :asdf) === true + handle_message(logger, Logging.Info, "msg", Base, :group, :asdf, "somefile", 1, maxlog=2) + @test shouldlog(logger, Logging.Info, Base, :group, :asdf) === false + + # Log formatting + function genmsg(level, message, _module, filepath, line; color=false, + meta_formatter=Logging.default_metafmt, show_limited=true, kws...) + buf = IOBuffer() + io = IOContext(buf, :displaysize=>(30,75), :color=>color) + logger = ConsoleLogger(io, Logging.Debug, + meta_formatter=meta_formatter, + show_limited=show_limited) + Logging.handle_message(logger, level, message, _module, :a_group, :an_id, + filepath, line; kws...) + String(take!(buf)) + end + + # Single line formatting, default metadata + @test genmsg(Logging.Debug, "msg", Main, "some/path.jl", 101) == + """ + [ Debug: msg @ Main path.jl:101 + """ + @test genmsg(Logging.Info, "msg", Main, "some/path.jl", 101) == + """ + [ Info: msg @ Main path.jl:101 + """ + @test genmsg(Logging.Warn, "msg", Main, "some/path.jl", 101) == + """ + [ Warning: msg @ Main path.jl:101 + """ + @test genmsg(Logging.Error, "msg", Main, "some/path.jl", 101) == + """ + [ Error: msg @ Main path.jl:101 + """ + + # Configurable metadata formatting + @test genmsg(Logging.Debug, "msg", Main, "some/path.jl", 101, + meta_formatter=(level, _module, group, id, file, line)-> + ("Foo!", "$level $_module $group $id $file $line")) == + """ + [ Foo! msg Debug Main a_group an_id some/path.jl 101 + """ + + # Empty message string + @test genmsg(Logging.Error, "", Main, "some/path.jl", 101) == + """ + [ Error: @ Main path.jl:101 + """ + @test genmsg(Logging.Error, "", Main, "some/path.jl", 101, a=1) == + replace(""" + ┌ Error: EOL + │ a = 1 + └ @ Main path.jl:101 + """, "EOL"=>"") + + # Long message line + @test genmsg(Logging.Error, "msg msg msg msg msg msg msg msg msg msg msg msg msg", Main, "some/path.jl", 101) == + """ + ┌ Error: msg msg msg msg msg msg msg msg msg msg msg msg msg + └ @ Main path.jl:101 + """ + + # Multiline messages + @test genmsg(Logging.Warn, "line1\nline2", Main, "some/path.jl", 101) == + """ + ┌ Warning: line1 + │ line2 + └ @ Main path.jl:101 + """ + + # Keywords + @test genmsg(Logging.Error, "msg", Base, "other.jl", 101, a=1, b="asdf") == + """ + ┌ Error: msg + │ a = 1 + │ b = "asdf" + └ @ Base other.jl:101 + """ + # Exceptions use showerror + @test genmsg(Logging.Info, "msg", Base, "other.jl", 101, exception=DivideError()) == + """ + ┌ Info: msg + │ exception = DivideError: integer division error + └ @ Base other.jl:101 + """ + # Attaching backtraces + bt = func1() + @test startswith(genmsg(Logging.Info, "msg", Base, "other.jl", 101, + exception=(DivideError(),bt)), + """ + ┌ Info: msg + │ exception = + │ DivideError: integer division error + │ Stacktrace: + │ [1] func1() at""") + + + # Keywords - limiting the amount which is printed + @test genmsg(Logging.Info, "msg", Main, "some/path.jl", 101, + a=fill(1.00001, 100,100), b=fill(2.00002, 10,10)) == + replace(""" + ┌ Info: msg + │ a = + │ 100×100 Array{Float64,2}: + │ 1.00001 1.00001 1.00001 1.00001 … 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ ⋮ ⋱ EOL + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ b = + │ 10×10 Array{Float64,2}: + │ 2.00002 2.00002 2.00002 2.00002 … 2.00002 2.00002 2.00002 + │ 2.00002 2.00002 2.00002 2.00002 2.00002 2.00002 2.00002 + │ 2.00002 2.00002 2.00002 2.00002 2.00002 2.00002 2.00002 + │ ⋮ ⋱ EOL + │ 2.00002 2.00002 2.00002 2.00002 2.00002 2.00002 2.00002 + │ 2.00002 2.00002 2.00002 2.00002 2.00002 2.00002 2.00002 + └ @ Main path.jl:101 + """, "EOL"=>"") # EOL hack to work around git whitespace errors + # Limiting the amount which is printed + @test genmsg(Logging.Info, "msg", Main, "some/path.jl", 101, + a=fill(1.00001, 10,10), show_limited=false) == + """ + ┌ Info: msg + │ a = + │ 10×10 Array{Float64,2}: + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + │ 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 1.00001 + └ @ Main path.jl:101 + """ + + # Basic color test + @test genmsg(Logging.Info, "line1\nline2", Main, "some/path.jl", 101, color=true) == + """ + \e[1m\e[36m┌ \e[39m\e[22m\e[1m\e[36mInfo: \e[39m\e[22mline1 + \e[1m\e[36m│ \e[39m\e[22mline2 + \e[1m\e[36m└ \e[39m\e[22m \e[90m @ Main path.jl:101\e[39m + """ + +end + +end From 63ecd0646269bfa5dcbd0965c9b0fb3fe5d5cf70 Mon Sep 17 00:00:00 2001 From: Chris Foster Date: Sat, 6 Jan 2018 01:20:27 +1000 Subject: [PATCH 2/2] Set the group of failed log events to logevent_error This is to allow clean filtering of log event failures when these are automatically caught by the system. --- base/logging.jl | 2 +- test/logging.jl | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/base/logging.jl b/base/logging.jl index 9a8faebf9a797..715b43b5bff73 100644 --- a/base/logging.jl +++ b/base/logging.jl @@ -343,7 +343,7 @@ end # progressively less information. try msg = "Exception while generating log record in module $_module at $filepath:$line" - handle_message(logger, Error, msg, _module, group, id, filepath, line; exception=err) + handle_message(logger, Error, msg, _module, :logevent_error, id, filepath, line; exception=err) catch err2 try # Give up and write to STDERR, in three independent calls to diff --git a/test/logging.jl b/test/logging.jl index 6ff43052091a8..95d9919c3abd0 100644 --- a/test/logging.jl +++ b/test/logging.jl @@ -84,7 +84,7 @@ end @testset "Log message exception handling" begin # Exceptions in message creation are caught by default - @test_logs (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