Skip to content

allow unnesting JSON #17

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.

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

Merged
merged 5 commits into from
Apr 9, 2024
Merged
Show file tree
Hide file tree
Changes from 3 commits
Commits
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
4 changes: 1 addition & 3 deletions Project.toml
Original file line number Diff line number Diff line change
@@ -1,15 +1,13 @@
name = "LoggingFormats"
uuid = "98105f81-4425-4516-93fd-1664fb551ab6"
version = "1.3.0"
version = "1.4.0"

[deps]
JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1"
Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
StructTypes = "856f2bd8-1eba-4b0a-8007-ebc267875bd4"

[compat]
JSON3 = "1"
StructTypes = "1"
julia = "1"

[extras]
Expand Down
72 changes: 51 additions & 21 deletions src/LoggingFormats.jl
Original file line number Diff line number Diff line change
@@ -1,6 +1,8 @@
module LoggingFormats

import Logging, JSON3, StructTypes
import Logging, JSON3

const STANDARD_KEYS = (:level, :msg, :module, :file, :line, :group, :id)

###############
## Truncated ##
Expand Down Expand Up @@ -56,16 +58,6 @@ lvlstr(lvl::Logging.LogLevel) = lvl >= Logging.Error ? "error" :
lvl >= Logging.Info ? "info" :
"debug"

struct JSONLogMessage{T}
level::String
msg::String
_module::Union{String,Nothing}
file::Union{String,Nothing}
line::Union{Int,Nothing}
group::Union{String,Nothing}
id::Union{String,Nothing}
kwargs::Dict{String,T}
end

transform(::Type{String}, v) = string(v)
transform(::Type{Any}, v) = v
Expand All @@ -74,39 +66,77 @@ maybe_stringify_exceptions((e, bt)::Tuple{Exception,Any}) = sprint(Base.display_
maybe_stringify_exceptions(e::Exception) = sprint(showerror, e)
maybe_stringify_exceptions(v) = v

function JSONLogMessage{T}(args) where {T}
JSONLogMessage{T}(
unclash_key(k) = k in STANDARD_KEYS ? Symbol("_", k) : k

function to_namedtuple(::Type{T}, args; nest_kwargs) where {T}
kw = (k => transform(T, maybe_stringify_exceptions(v)) for (k, v) in args.kwargs)
if nest_kwargs
kw = (:kwargs => Dict{String, T}(string(k) => transform(T, maybe_stringify_exceptions(v)) for (k, v) in args.kwargs),)
else
kw = (unclash_key(k) => transform(T, maybe_stringify_exceptions(v)) for (k, v) in args.kwargs)
end
standard_message = NamedTuple{STANDARD_KEYS}(
lvlstr(args.level),
args.message isa AbstractString ? args.message : string(args.message),
args._module === nothing ? nothing : string(args._module),
args.file,
args.line,
args.group === nothing ? nothing : string(args.group),
args.id === nothing ? nothing : string(args.id),
Dict{String,T}(string(k) => transform(T, maybe_stringify_exceptions(v)) for (k, v) in args.kwargs)
)
return merge(standard_message, kw)
)
end
StructTypes.StructType(::Type{<:JSONLogMessage}) = StructTypes.OrderedStruct()
StructTypes.names(::Type{<:JSONLogMessage}) = ((:_module, :module), )

"""
JSON(; recursive=false, nest_kwargs=true)

Creates a `JSON` format logger. If `recursive=true`, any custom arguments will be recursively serialized as JSON; otherwise, the values will be treated as strings. If `nest_kwargs` is true (the default), all custom keyword arguments will be under the `kwargs` key. Otherwise, they will be inlined into the top-level JSON object. In the latter case, if the key name clashes with one of the standard keys (`$STANDARD_KEYS`), it will be renamed by prefixing it with a `_`.

## Examples

```julia
julia> using LoggingFormats, LoggingExtras

julia> with_logger(FormatLogger(LoggingFormats.JSON(; recursive=false), stderr)) do
@info "hello, world" key=Dict("hello" => true)
end
{"level":"info","msg":"hello, world","module":"Main","file":"REPL[3]","line":2,"group":"REPL[3]","id":"Main_ffce16b4","kwargs":{"key":"Dict{String, Bool}(\"hello\" => 1)"}}

julia> with_logger(FormatLogger(LoggingFormats.JSON(; recursive=true), stderr)) do
@info "hello, world" key=Dict("hello" => true)
end
{"level":"info","msg":"hello, world","module":"Main","file":"REPL[4]","line":2,"group":"REPL[4]","id":"Main_ffce16b5","kwargs":{"key":{"hello":true}}}

julia> with_logger(FormatLogger(LoggingFormats.JSON(; recursive=true, nest_kwargs=false), stderr)) do
@info "hello, world" key=Dict("hello" => true)
end
{"level":"info","msg":"hello, world","module":"Main","file":"REPL[5]","line":2,"group":"REPL[5]","id":"Main_ffce16b6","key":{"hello":true}}
```
"""
struct JSON <: Function
recursive::Bool
nest_kwargs::Bool
end

JSON(; recursive=false) = JSON(recursive)
JSON(; recursive=false, nest_kwargs=true) = JSON(recursive, nest_kwargs)

function (j::JSON)(io, args)
if j.recursive
logmsg = JSONLogMessage{Any}(args)
logmsg = to_namedtuple(Any, args; nest_kwargs=j.nest_kwargs)
try
JSON3.write(io, logmsg)
catch e
fallback_msg = JSONLogMessage{String}(args)
fallback_msg.kwargs["LoggingFormats.FormatError"] = sprint(showerror, e)
if j.nest_kwargs
fallback_msg = to_namedtuple(String, args; nest_kwargs=true)
fallback_msg.kwargs["LoggingFormats.FormatError"] = sprint(showerror, e)
else
fallback_msg = (; to_namedtuple(String, args; nest_kwargs=false)..., Symbol("LoggingFormats.FormatError") => sprint(showerror, e))
end
JSON3.write(io, fallback_msg)
end
else
logmsg = JSONLogMessage{String}(args)
logmsg = to_namedtuple(String, args; nest_kwargs=j.nest_kwargs)
JSON3.write(io, logmsg)
end
println(io)
Expand Down
82 changes: 60 additions & 22 deletions test/runtests.jl
Original file line number Diff line number Diff line change
Expand Up @@ -98,60 +98,98 @@ end
@test json.kwargs.x == "[1, 2, 3]"
@test json.kwargs.y == "(1, 2)"

# `recursive=true`

# nest_kwargs=false
io = IOBuffer()
with_logger(FormatLogger(JSON(; recursive=true), io)) do
with_logger(FormatLogger(JSON(; nest_kwargs=false), io)) do
y = (1, 2)
@info "info msg" x = [1, 2, 3] y = Dict("hi" => Dict("hi2" => [1,2]))
@info "info msg" x = [1, 2, 3] y
end
json = JSON3.read(seekstart(io))
@test json.level == "info"
@test json.msg == "info msg"
@test json.module == "Main"
@test json.line isa Int
@test json.kwargs.x == [1, 2, 3]
@test json.kwargs.y == Dict(:hi => Dict(:hi2 => [1,2]))
# not tucked under `kwargs`
@test json.x == "[1, 2, 3]"
@test json.y == "(1, 2)"

# Fallback to strings

# With clash
io = IOBuffer()
with_logger(FormatLogger(JSON(; nest_kwargs=false), io)) do
@info "info msg" line = [1, 2, 3]
end
json = JSON3.read(seekstart(io))
@test json.level == "info"
@test json.msg == "info msg"
@test json.module == "Main"
@test json.line isa Int
# key was renamed to prevent clash:
@test json._line == "[1, 2, 3]"

# `recursive=true`
io = IOBuffer()
with_logger(FormatLogger(JSON(; recursive=true), io)) do
y = (1, 2)
@info "info msg" x = [1, 2, 3] y = Dict("hi" => NaN)
@info "info msg" x = [1, 2, 3] y = Dict("hi" => Dict("hi2" => [1,2]))
end
json = JSON3.read(seekstart(io))
@test json.level == "info"
@test json.msg == "info msg"
@test json.module == "Main"
@test json.line isa Int
@test json.kwargs.x == "[1, 2, 3]"
y = json.kwargs.y
must_have = ("Dict", "\"hi\"", "=>", "NaN")
@test all(h -> occursin(h, y), must_have) # avoid issues with printing changing with versions
@test json.kwargs[Symbol("LoggingFormats.FormatError")] == "NaN not allowed to be written in JSON spec"
@test json.kwargs.x == [1, 2, 3]
@test json.kwargs.y == Dict(:hi => Dict(:hi2 => [1,2]))

# Fallback to strings
for nest_kwargs in (true, false)
io = IOBuffer()
with_logger(FormatLogger(JSON(; recursive=true, nest_kwargs=nest_kwargs), io)) do
@info "info msg" x = [1, 2, 3] y = Dict("hi" => NaN)
end
json = JSON3.read(seekstart(io))
@test json.level == "info"
@test json.msg == "info msg"
@test json.module == "Main"
@test json.line isa Int
if nest_kwargs
@test json.kwargs.x == "[1, 2, 3]"
@test json.kwargs[Symbol("LoggingFormats.FormatError")] == "NaN not allowed to be written in JSON spec"
y = json.kwargs.y
else
@test json.x == "[1, 2, 3]"
@test json[Symbol("LoggingFormats.FormatError")] == "NaN not allowed to be written in JSON spec"
y = json.y
end
must_have = ("Dict", "\"hi\"", "=>", "NaN")
@test all(h -> occursin(h, y), must_have) # avoid issues with printing changing with versions
end

# Test logging exceptions
for recursive in (false, true)
for recursive in (false, true), nest_kwargs in (true, false)
# no stacktrace
io = IOBuffer()
with_logger(FormatLogger(JSON(; recursive=recursive), io)) do
with_logger(FormatLogger(JSON(; recursive=recursive, nest_kwargs=nest_kwargs), io)) do
@error "Oh no" exception = ArgumentError("no")
end
logs = JSON3.read(seekstart(io))
@test logs["msg"] == "Oh no"
@test logs["kwargs"]["exception"] == "ArgumentError: no"
ex = nest_kwargs ? logs["kwargs"]["exception"] : logs["exception"]
@test ex == "ArgumentError: no"

# non-standard exception key
io = IOBuffer()
with_logger(FormatLogger(JSON(; recursive=recursive), io)) do
with_logger(FormatLogger(JSON(; recursive=recursive, nest_kwargs=nest_kwargs), io)) do
@error "Oh no" ex = ArgumentError("no")
end
logs = JSON3.read(seekstart(io))
@test logs["msg"] == "Oh no"
@test logs["kwargs"]["ex"] == "ArgumentError: no"
ex = nest_kwargs ? logs["kwargs"]["ex"] : logs["ex"]
@test ex == "ArgumentError: no"

# stacktrace
io = IOBuffer()
with_logger(FormatLogger(JSON(; recursive=recursive), io)) do
with_logger(FormatLogger(JSON(; recursive=recursive, nest_kwargs=nest_kwargs), io)) do
try
throw(ArgumentError("no"))
catch e
Expand All @@ -161,10 +199,10 @@ end
logs = JSON3.read(seekstart(io))
@test logs["msg"] == "Oh no"

@test occursin("ArgumentError: no", logs["kwargs"]["exception"])
ex = nest_kwargs ? logs["kwargs"]["exception"] : logs["exception"]
@test occursin("ArgumentError: no", ex)
# Make sure we get a stacktrace out:
@test occursin(r"ArgumentError: no\nStacktrace:\s* \[1\]",
logs["kwargs"]["exception"])
@test occursin(r"ArgumentError: no\nStacktrace:\s* \[1\]", ex)
end
end

Expand Down