From 52c4c4570fc0a9c028ab0e3cc316f09cba0737bc Mon Sep 17 00:00:00 2001
From: Chris Foster <chris42f@gmail.com>
Date: Wed, 10 Jan 2018 22:02:07 +1000
Subject: [PATCH] Improved formatting defaults for log metadata

The metadata suffix is now printed on its own line by default, and
disabled for `Info` level logging.  The printing can be made more
compact if desired by right justifying the metadata using the
`right_justify` setting.

Color is made customizable by requiring that it's returned from the
meta_formatter() function.
---
 stdlib/Logging/src/ConsoleLogger.jl | 141 +++++++++------
 stdlib/Logging/test/runtests.jl     | 265 +++++++++++++++++-----------
 2 files changed, 247 insertions(+), 159 deletions(-)

diff --git a/stdlib/Logging/src/ConsoleLogger.jl b/stdlib/Logging/src/ConsoleLogger.jl
index 53c2b48f57f4b..0cd6a6ce63370 100644
--- a/stdlib/Logging/src/ConsoleLogger.jl
+++ b/stdlib/Logging/src/ConsoleLogger.jl
@@ -1,7 +1,8 @@
 # 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)
+    ConsoleLogger(stream=STDERR, min_level=Info; meta_formatter=default_metafmt,
+                  show_limited=true, right_justify=0)
 
 Logger with formatting optimized for readability in a text console, for example
 interactive work with the Julia REPL.
@@ -11,24 +12,29 @@ 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.
+  `(level, _module, group, id, file, line)` and returns a color (as would be
+  passed to print_with_color), prefix and suffix for the log message.  The
+  default is to prefix with the log level and 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.
+* `right_justify` is the integer column which log metadata is right justified
+  at. The default is zero (metadata goes on its own line).
 """
 struct ConsoleLogger <: AbstractLogger
     stream::IO
     min_level::LogLevel
     meta_formatter
     show_limited::Bool
+    right_justify::Int
     message_limits::Dict{Any,Int}
 end
 function ConsoleLogger(stream::IO=STDERR, min_level=Info;
-                       meta_formatter=default_metafmt, show_limited=true)
+                       meta_formatter=default_metafmt, show_limited=true,
+                       right_justify=0)
     ConsoleLogger(stream, min_level, meta_formatter,
-                  show_limited, Dict{Any,Int}())
+                  show_limited, right_justify, Dict{Any,Int}())
 end
 
 shouldlog(logger::ConsoleLogger, level, _module, group, id) =
@@ -44,9 +50,39 @@ function showvalue(io, e::Tuple{Exception,Any})
 end
 showvalue(io, ex::Exception) = showvalue(io, (ex,catch_backtrace()))
 
+function default_logcolor(level)
+    level < Info  ? Base.debug_color() :
+    level < Warn  ? Base.info_color()  :
+    level < Error ? Base.warn_color()  :
+                    Base.error_color()
+end
+
 function default_metafmt(level, _module, group, id, file, line)
-    ((level == Warn ? "Warning" : string(level))*':',
-     "@ $_module $(basename(file)):$line")
+    color = default_logcolor(level)
+    prefix = (level == Warn ? "Warning" : string(level))*':'
+    suffix = (Info <= level < Warn) ? "" : "@ $_module $(basename(file)):$line"
+    color,prefix,suffix
+end
+
+# Length of a string as it will appear in the terminal (after ANSI color codes
+# are removed)
+function termlength(str)
+    N = 0
+    in_esc = false
+    for c in str
+        if in_esc
+            if c == 'm'
+                in_esc = false
+            end
+        else
+            if c == '\e'
+                in_esc = true
+            else
+                N += 1
+            end
+        end
+    end
+    return N
 end
 
 function handle_message(logger::ConsoleLogger, level, message, _module, group, id,
@@ -56,63 +92,64 @@ function handle_message(logger::ConsoleLogger, level, message, _module, group, i
         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')
+
+    # 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')]
     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
+    if !isempty(kwargs)
         valbuf = IOBuffer()
         rows_per_value = max(1, dsize[1]÷(length(kwargs)+1))
-        valio = IOContext(IOContext(valbuf, iob),
+        valio = IOContext(IOContext(valbuf, logger.stream),
                           :displaysize=>(rows_per_value,dsize[2]-5))
+        if logger.show_limited
+            valio = IOContext(valio, :limit=>true)
+        end
         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])
+                push!(msglines, (indent=2,msg=SubString("$key = $(vallines[1])")))
             else
-                println(iob)
-                for line in vallines
-                    print_with_color(color, iob, "│    ", bold=true)
-                    println(iob, line)
-                end
+                push!(msglines, (indent=2,msg=SubString("$key =")))
+                append!(msglines, ((indent=3,msg=line) for line in vallines))
             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)
+
+    # 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)
+    minsuffixpad = 2
+    buf = IOBuffer()
+    iob = IOContext(buf, logger.stream)
+    nonpadwidth = 2 + (isempty(prefix) || length(msglines) > 1 ? 0 : length(prefix)+1) +
+                  msglines[end].indent + termlength(msglines[end].msg) +
+                  (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("")))
+        minsuffixpad = 0
+        nonpadwidth = 2 + length(suffix)
+    end
+    for (i,(indent,msg)) in enumerate(msglines)
+        boxstr = length(msglines) == 1 ? "[ " :
+                 i == 1                ? "┌ " :
+                 i < length(msglines)  ? "│ " :
+                                         "└ "
+        print_with_color(color, iob, boxstr, bold=true)
+        if i == 1 && !isempty(prefix)
+            print_with_color(color, iob, prefix, " ", bold=true)
+        end
+        print(iob, " "^indent, msg)
+        if i == length(msglines) && !isempty(suffix)
+            npad = max(0, justify_width - nonpadwidth) + minsuffixpad
+            print(iob, " "^npad)
+            print_with_color(:light_black, iob, suffix)
+        end
+        println(iob)
     end
-    print(iob, "\n")
+
     write(logger.stream, take!(buf))
     nothing
 end
diff --git a/stdlib/Logging/test/runtests.jl b/stdlib/Logging/test/runtests.jl
index 74701a5c302d7..8419527be6c53 100644
--- a/stdlib/Logging/test/runtests.jl
+++ b/stdlib/Logging/test/runtests.jl
@@ -19,148 +19,199 @@ import Logging: min_enabled_level, shouldlog, handle_message
     handle_message(logger, Logging.Info, "msg", Base, :group, :asdf, "somefile", 1, maxlog=2)
     @test shouldlog(logger, Logging.Info, Base, :group, :asdf) === false
 
+    @testset "Default metadata formatting" begin
+        @test Logging.default_metafmt(Logging.Debug, Base, :g, :i, "path/to/somefile.jl", 42) ==
+            (:blue,      "Debug:",   "@ Base somefile.jl:42")
+        @test Logging.default_metafmt(Logging.Info,  Main, :g, :i, "a.jl", 1) ==
+            (:cyan,      "Info:",    "")
+        @test Logging.default_metafmt(Logging.Warn,  Main, :g, :i, "b.jl", 2) ==
+            (:yellow,    "Warning:", "@ Main b.jl:2")
+        @test Logging.default_metafmt(Logging.Error, Main, :g, :i, "", 0) ==
+            (:light_red, "Error:",   "@ Main :0")
+    end
+
+    function dummy_metafmt(level, _module, group, id, file, line)
+        :cyan,"PREFIX","SUFFIX"
+    end
+
     # Log formatting
-    function genmsg(level, message, _module, filepath, line; color=false,
-                    meta_formatter=Logging.default_metafmt, show_limited=true, kws...)
+    function genmsg(message; level=Logging.Info, _module=Main,
+                    file="some/path.jl", line=101, color=false, width=75,
+                    meta_formatter=dummy_metafmt, show_limited=true,
+                    right_justify=0, kws...)
         buf = IOBuffer()
-        io = IOContext(buf, :displaysize=>(30,75), :color=>color)
+        io = IOContext(buf, :displaysize=>(30,width), :color=>color)
         logger = ConsoleLogger(io, Logging.Debug,
                                meta_formatter=meta_formatter,
-                               show_limited=show_limited)
+                               show_limited=show_limited,
+                               right_justify=right_justify)
         Logging.handle_message(logger, level, message, _module, :a_group, :an_id,
-                               filepath, line; kws...)
+                               file, 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) ==
+    # Basic tests for the default setup
+    @test genmsg("msg", level=Logging.Info, meta_formatter=Logging.default_metafmt) ==
     """
-    ┌ Error: msg msg msg msg msg msg msg msg msg msg msg msg msg
-    └                                                        @ Main path.jl:101
+    [ Info: msg
     """
-
-    # Multiline messages
-    @test genmsg(Logging.Warn, "line1\nline2", Main, "some/path.jl", 101) ==
+    @test genmsg("line1\nline2", level=Logging.Warn, _module=Base,
+                 file="other.jl", line=42, meta_formatter=Logging.default_metafmt) ==
     """
     ┌ Warning: line1
     │ line2
-    └                                                        @ Main path.jl:101
+    └ @ Base other.jl:42
     """
+    # Full metadata formatting
+    @test genmsg("msg", level=Logging.Debug,
+                 meta_formatter=(level, _module, group, id, file, line)->
+                                (:white,"Foo!", "$level $_module $group $id $file $line")) ==
+    """
+    ┌ Foo! msg
+    └ Debug Main a_group an_id some/path.jl 101
+    """
+
+    @testset "Prefix and suffix layout" begin
+        @test genmsg("") ==
+        replace("""
+        ┌ PREFIX EOL
+        └ SUFFIX
+        """, "EOL"=>"")
+        @test genmsg("msg") ==
+        """
+        ┌ PREFIX msg
+        └ SUFFIX
+        """
+        # Behavior with empty prefix / suffix
+        @test genmsg("msg", meta_formatter=(args...)->(:white, "PREFIX", "")) ==
+        """
+        [ PREFIX msg
+        """
+        @test genmsg("msg", meta_formatter=(args...)->(:white, "", "SUFFIX")) ==
+        """
+        ┌ msg
+        └ SUFFIX
+        """
+    end
+
+    @testset "Metadata suffix, right justification" begin
+        @test genmsg("xxx", width=20, right_justify=200) ==
+        """
+        [ PREFIX xxx  SUFFIX
+        """
+        @test genmsg("xxx\nxxx", width=20, right_justify=200) ==
+        """
+        ┌ PREFIX xxx
+        └ xxx         SUFFIX
+        """
+        # When adding the suffix would overflow the display width, add it on
+        # the next line:
+        @test genmsg("xxxx", width=20, right_justify=200) ==
+        """
+        ┌ PREFIX xxxx
+        └             SUFFIX
+        """
+        # Same for multiline messages
+        @test genmsg("""xxx
+                        xxxxxxxxxx""", width=20, right_justify=200) ==
+        """
+        ┌ PREFIX xxx
+        └ xxxxxxxxxx  SUFFIX
+        """
+        @test genmsg("""xxx
+                        xxxxxxxxxxx""", width=20, right_justify=200) ==
+        """
+        ┌ PREFIX xxx
+        │ xxxxxxxxxxx
+        └             SUFFIX
+        """
+        # min(right_justify,width) is used
+        @test genmsg("xxx", width=200, right_justify=20) ==
+        """
+        [ PREFIX xxx  SUFFIX
+        """
+        @test genmsg("xxxx", width=200, right_justify=20) ==
+        """
+        ┌ PREFIX xxxx
+        └             SUFFIX
+        """
+    end
 
     # Keywords
-    @test genmsg(Logging.Error, "msg", Base, "other.jl", 101, a=1, b="asdf") ==
+    @test genmsg("msg", a=1, b="asdf") ==
     """
-    ┌ Error: msg
+    ┌ PREFIX msg
     │   a = 1
     │   b = "asdf"
-    └                                                       @ Base other.jl:101
+    └ SUFFIX
     """
-    # Exceptions use showerror
-    @test genmsg(Logging.Info, "msg", Base, "other.jl", 101, exception=DivideError()) ==
+    # Exceptions shown with showerror
+    @test genmsg("msg", exception=DivideError()) ==
     """
-    ┌ Info: msg
+    ┌ PREFIX msg
     │   exception = DivideError: integer division error
-    └                                                       @ Base other.jl:101
+    └ SUFFIX
     """
+
     # Attaching backtraces
     bt = func1()
-    @test startswith(genmsg(Logging.Info, "msg", Base, "other.jl", 101,
-                            exception=(DivideError(),bt)),
+    @test startswith(genmsg("msg", exception=(DivideError(),bt)),
     """
-    ┌ Info: msg
+    ┌ PREFIX 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
-    """
+    @testset "Limiting large data structures" begin
+        @test genmsg("msg", a=fill(1.00001, 100,100), b=fill(2.00002, 10,10)) ==
+        replace("""
+        ┌ PREFIX 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
+        └ SUFFIX
+        """, "EOL"=>"") # EOL hack to work around git whitespace errors
+        # Limiting the amount which is printed
+        @test genmsg("msg", a=fill(1.00001, 10,10), show_limited=false) ==
+        """
+        ┌ PREFIX 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
+        └ SUFFIX
+        """
+    end
 
-    # Basic color test
-    @test genmsg(Logging.Info, "line1\nline2", Main, "some/path.jl", 101, color=true) ==
+    # Basic colorization test
+    @test genmsg("line1\nline2", color=true) ==
     """
-    \e[36m\e[1m┌ \e[22m\e[39m\e[36m\e[1mInfo: \e[22m\e[39mline1
+    \e[36m\e[1m┌ \e[22m\e[39m\e[36m\e[1mPREFIX \e[22m\e[39mline1
     \e[36m\e[1m│ \e[22m\e[39mline2
-    \e[36m\e[1m└ \e[22m\e[39m                                                      \e[90m @ Main path.jl:101\e[39m
+    \e[36m\e[1m└ \e[22m\e[39m\e[90mSUFFIX\e[39m
     """
 
 end