Skip to content

Commit

Permalink
allow unnesting JSON (#17)
Browse files Browse the repository at this point in the history
* allow unnesting JSON

* bump version

* Apply suggestions from code review

Co-authored-by: Glenn Moynihan <glennmoy@gmail.com>

* Update src/LoggingFormats.jl

* Apply suggestions from code review

---------

Co-authored-by: Glenn Moynihan <glennmoy@gmail.com>
  • Loading branch information
ericphanson and glennmoy authored Apr 9, 2024
1 parent 9367c8b commit 4fa07f0
Show file tree
Hide file tree
Showing 3 changed files with 112 additions and 47 deletions.
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
73 changes: 51 additions & 22 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,76 @@ 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

2 comments on commit 4fa07f0

@ericphanson
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@JuliaRegistrator
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Registration pull request created: JuliaRegistries/General/104592

Tip: Release Notes

Did you know you can add release notes too? Just add markdown formatted text underneath the comment after the text
"Release notes:" and it will be added to the registry PR, and if TagBot is installed it will also be added to the
release that TagBot creates. i.e.

@JuliaRegistrator register

Release notes:

## Breaking changes

- blah

To add them here just re-invoke and the PR will be updated.

Tagging

After the above pull request is merged, it is recommended that a tag is created on this repository for the registered package version.

This will be done automatically if the Julia TagBot GitHub Action is installed, or can be done manually through the github interface, or via:

git tag -a v1.4.0 -m "<description of version>" 4fa07f0c2cc02797450d3f0c465e99e20e3cd703
git push origin v1.4.0

Please sign in to comment.