Skip to content

Commit

Permalink
ConsoleLogger for readable interactive logging
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@c42f
c42f committed Jan 5, 2018
1 parent 5953286 commit af7cda9
Show file tree
Hide file tree
Showing 4 changed files with 292 additions and 3 deletions.
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

0 comments on commit af7cda9

Please sign in to comment.