Skip to content

Commit

Permalink
Merge pull request #25370 from JuliaLang/cjf/ConsoleLogger
Browse files Browse the repository at this point in the history 
ConsoleLogger for more fully featured log printing
  • Loading branch information
@c42f
c42f authored Jan 7, 2018
2 parents b96097b + 63ecd06 commit abb2061
Show file tree
Hide file tree
Showing 6 changed files with 294 additions and 5 deletions.
2 changes: 1 addition & 1 deletion base/logging.jl
View file
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
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
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()))

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

5 changes: 4 additions & 1 deletion stdlib/Logging/src/Logging.jl
View file
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
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
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

0 comments on commit abb2061

Please sign in to comment.