Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ConsoleLogger for more fully featured log printing #25370

Merged
merged 2 commits into from
Jan 7, 2018
Merged

ConsoleLogger for more fully featured log printing #25370

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
af7cda9
ConsoleLogger for readable interactive logging
c42f Jan 2, 2018
63ecd06
Set the group of failed log events to logevent_error
c42f Jan 5, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion base/logging.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion base/sysimg.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down
119 changes: 119 additions & 0 deletions stdlib/Logging/src/ConsoleLogger.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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()))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we should do this --- there's no way to know whether the result of catch_backtrace corresponds to the given exception. This mechanism is already pretty fragile and can cause quite a bit of confusion, e.g. #19979

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One alternative is to have people pass it explicitly everywhere:

try
    # do stuff
catch ex
    @error "Extra information about something bad" exception=ex,catch_backtrace()
end

This might be an acceptable syntax burden?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

On further thought, to be completely safe from the problems of #19979 the pattern would have to look like

try
    # do stuff
catch ex
    bt = catch_backtrace()
    @error "Extra information about something bad" exception=ex,bt
end

Hmm. This breaks the general principle that log events should be lazily generated.


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)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For consistency with single line mode, locationstr could be printed at the last message/kwarg line if it fits.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That would be nice. It does complicate the implementation significantly.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think I'll punt on this for now. Getting right justification correct in general seems to involve removing ANSI escape sequences from the formatted values to determine the text width of the line prefix. It really seems somewhat messy.

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

5 changes: 4 additions & 1 deletion stdlib/Logging/src/Logging.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:
#
Expand Down
169 changes: 168 additions & 1 deletion stdlib/Logging/test/runtests.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
2 changes: 1 addition & 1 deletion test/logging.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down