Support exceptions better in logfmt (#14)

Author: ericphanson

Project.toml

@@ -1,6 +1,6 @@
 name = "LoggingFormats"
 uuid = "98105f81-4425-4516-93fd-1664fb551ab6"
-version = "1.2.0"
+version = "1.3.0"
 
 [deps]
 JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1"

README.md

@@ -66,11 +66,13 @@ level=info msg="hello, world" module=Main file="REPL[2]" line=2 group="REPL[2]"
 level=error msg="something is wrong" module=Main file="REPL[2]" line=3 group="REPL[2]" id=Main_2289c7f8
 ```
 
+Similarly to the JSON logger, `LogFmt` handles the key `exception` specially, by printing errors and stacktraces using `Base.showerror`.
+
 ## `Truncated`: Truncate long variables and messages
 
 `LoggingFormats.Truncated(max_var_len=5_000)` is a function which formats data in similar manner as `ConsoleLogger`,
 but with truncation of string representation when it exceeds `max_var_len`.
-This format truncates the length of message itself, and truncates string representation of 
+This format truncates the length of message itself, and truncates string representation of
 individual variables, but does not truncate the size of whole printed text.
 
 See the examples:

src/LoggingFormats.jl

@@ -70,15 +70,20 @@ end
 transform(::Type{String}, v) = string(v)
 transform(::Type{Any}, v) = v
 
-# Use key information, then lower to 2-arg transform
-function transform(::Type{T}, key, v) where {T}
-    key == :exception || return transform(T, v)
+function maybe_stringify_exceptions(key, v)
+    key == :exception || return v
     if v isa Tuple && length(v) == 2 && v[1] isa Exception
         e, bt = v
         msg = sprint(Base.display_error, e, bt)
-        return transform(T, msg)
+        return msg
     end
-    return transform(T, sprint(showerror, v))
+    return sprint(showerror, v)
+end
+
+# Use key information, then lower to 2-arg transform
+function transform(::Type{T}, key, v) where {T}
+    v = maybe_stringify_exceptions(key, v)
+    return transform(T, v)
 end
 
 function JSONLogMessage{T}(args) where {T}
@@ -147,6 +152,7 @@ function (::LogFmt)(io, args)
     )
     for (k, v) in args.kwargs
         print(io, " ", k, "=\"")
+        v = maybe_stringify_exceptions(k, v)
         escape_string(io, sprint(print, something(v, "nothing")), '"')
         print(io, "\"")
     end

test/runtests.jl

@@ -4,6 +4,10 @@ using LoggingExtras: FormatLogger
 using LoggingFormats: LoggingFormats, Truncated, JSON, LogFmt
 import JSON3
 
+function my_throwing_function()
+    throw(ArgumentError("no"))
+end
+
 @testset "Truncating" begin
     @test LoggingFormats.shorten_str("αβγαβγ", 3) == "αβ…"
     @test LoggingFormats.shorten_str("αβγαβγ", 4) == "αβγ…"
@@ -167,6 +171,7 @@ end
         @warn "msg with \"quotes\""
         @error "error msg with nothings" _module=nothing _file=nothing __line=nothing
         @error :notstring x = [1, 2, 3] y = "hello\" \"world"
+        @error "hi" exception=ErrorException("bad")
     end
     strs = collect(eachline(seekstart(io)))
     @test occursin("level=debug msg=\"debug msg\" module=Main", strs[1])
@@ -183,4 +188,37 @@ end
     @test occursin("line=\"nothing\"", strs[4])
     @test occursin("level=error msg=\"notstring\" module=Main", strs[5])
     @test occursin("x=\"[1, 2, 3]\" y=\"hello\\\" \\\"world\"", strs[5])
+    @test occursin("exception=\"bad\"", strs[6])
+
+    # Now let's try exceptions with backtraces
+    io = IOBuffer()
+    with_logger(FormatLogger(LogFmt(), io)) do
+        try
+            my_throwing_function()
+        catch e
+            @error "Oh no" exception = (e, catch_backtrace())
+        end
+    end
+    str = String(take!(io))
+    @test occursin("level=error msg=\"Oh no\" module=Main", str)
+    @test occursin("file=\"", str)
+    @test occursin("group=\"", str)
+    @test occursin("exception=\"ERROR: ArgumentError: no\\nStacktrace:", str)
+    # no new lines (except at the end of the line)
+    @test !occursin('\n', chomp(str))
+    # no Ptr's showing up in the backtrace
+    @test !occursin("Ptr", str)
+    # Test we are getting at least some stacktrace, e.g., the function we called:
+    @test occursin("my_throwing_function()", str)
+
+    # Can test by converting to JSON with the node `logfmt` package:
+    # first install it with `npm i -g logfmt`
+    # Then:
+    # in = Base.PipeEndpoint()
+    # out = Base.PipeEndpoint()
+    # p = run(pipeline(`logfmt`; stdin=in, stdout=out); wait=false)
+    # write(in, str)
+    # close(in)
+    # wait(p)
+    # output = JSON3.read(read(out))
 end