Skip to content

Commit

Permalink
Merge pull request #37 from Arkoniak/21-json-logger
Browse files Browse the repository at this point in the history
add: initial implementation json logger (#21)
  • Loading branch information
Arkoniak authored Feb 14, 2023
2 parents b4208fe + f04b63b commit 6b4c0d7
Show file tree
Hide file tree
Showing 9 changed files with 415 additions and 113 deletions.
2 changes: 1 addition & 1 deletion .github/workflows/CI.yml
Original file line number Diff line number Diff line change
Expand Up @@ -50,7 +50,7 @@ jobs:
- uses: actions/checkout@v2
- uses: julia-actions/setup-julia@v1
with:
version: '1.3'
version: '1.8'
- run: |
julia --project=docs -e '
using Pkg
Expand Down
2 changes: 1 addition & 1 deletion Project.toml
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
name = "MiniLoggers"
uuid = "93f3dd0f-005d-4452-894a-a31841fa4078"
authors = ["Andrey Oskin and contributors"]
version = "0.4.3"
version = "0.5.0"

[deps]
Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
Expand Down
8 changes: 7 additions & 1 deletion src/MiniLoggers.jl
Original file line number Diff line number Diff line change
Expand Up @@ -5,9 +5,15 @@ using Markdown
import Logging: AbstractLogger, shouldlog, min_enabled_level, catch_exceptions, handle_message, LogLevel
using Logging: Warn, Info, Debug, Error, BelowMinLevel, AboveMaxLevel, global_logger, with_logger, default_logcolor

export MiniLogger, global_logger, with_logger
export MiniLogger, JsonLogger, global_logger, with_logger

# Utils
include("common.jl")
include("tokenizer.jl")
include("modes.jl")

# Loggers
include("minilogger.jl")
include("jsonlogger.jl")

end # module
27 changes: 27 additions & 0 deletions src/common.jl
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
abstract type AbstractMiniLogger <: AbstractLogger end

shouldlog(logger::AbstractMiniLogger, level, _module, group, id) = lock(logger.lock) do
get(logger.message_limits, id, 1) > 0
end

min_enabled_level(logger::AbstractMiniLogger) = logger.minlevel

catch_exceptions(logger::AbstractMiniLogger) = true

function Base.close(logger::AbstractMiniLogger)
if logger.io != stdout && logger.io != stderr && isopen(logger.io)
close(logger.io)
end

if logger.ioerr != stdout && logger.ioerr != stderr && isopen(logger.ioerr)
close(logger.ioerr)
end
end

getio(io, append) = io
getio(io::AbstractString, append) = open(io, append ? "a" : "w")

getflushthreshold(x::Integer) = x
getflushthreshold(x::TimePeriod) = Dates.value(Millisecond(x))

tsnow(dtf) = Dates.format(Dates.now(), dtf)
141 changes: 141 additions & 0 deletions src/jsonlogger.jl
Original file line number Diff line number Diff line change
@@ -0,0 +1,141 @@
struct JsonLogger{AM <: AbstractMode, IOT1 <: IO, IOT2 <: IO, DFT <: DateFormat} <: AbstractMiniLogger
io::IOT1
ioerr::IOT2
errlevel::LogLevel
minlevel::LogLevel
message_limits::Dict{Any,Int}
flush::Bool
format::Vector{Token}
dtformat::DFT
mode::AM
squash_delimiter::String
flush_threshold::Int
lastflush::Base.RefValue{Int64}
lock::ReentrantLock # thread-safety of message_limits Dict
end

"""
JsonLogger(; <keyword arguments>)
JsonLogger constructor creates custom logger with json output, which can be used with usual `@info`, `@debug` commands.
Supported keyword arguments include:
* `io` (default `stdout`): IO stream which is used to output log messages below `errlevel` level. Can be either `IO` or `String`, in the latter case it is treated as a name of the output file.
* `ioerr` (default `stderr`): IO stream which is used to output log messages above `errlevel` level. Can be either `IO` or `String`, in the latter case it is treated as a name of the output file.
* `errlevel` (default `Error`): determines which output IO to use for log messages. If you want for all messages to go to `io`, set this parameter to `MiniLoggers.AboveMaxLevel`. If you want for all messages to go to `ioerr`, set this parameter to `MiniLoggers.BelowMinLevel`.
* `minlevel` (default: `Info`): messages below this level are ignored. For example with default setting `@debug "foo"` is ignored.
* `append` (default: `false`): defines whether to append to output stream or to truncate file initially. Used only if `io` or `ioerr` is a file path.
* `flush` (default: `true`): whether to `flush` IO stream for each log message. Flush behaviour also affected by `flush_threshold` argument.
* `squash_delimiter`: (default: "\\t"): defines which delimiter to use when squashing multilines messages.
* `flush_threshold::Union{Integer, TimePeriod}` (default: 0): if this argument is nonzero and `flush` is `true`, then `io` is flushed only once per `flush_threshold` milliseconds. I.e. if time between two consecutive log messages is less then `flush_threshold`, then second message is not flushed and will have to wait for the next log event.
* `dtformat` (default: "yyyy-mm-dd HH:MM:SS"): if `datetime` parameter is used in `format` argument, this dateformat is applied for output timestamps.
* `format`: defines which keywords should be used in the output. If defined, should be a string which defines the structure of the output json. It should use keywords, and allowed keywords are:
* `timestamp`: timestamp of the log message
* `level`: name of log level (Debug, Info, etc)
* `filepath`: filepath of the file, which produced log message
* `basename`: basename of the filepath of the file, which produced log message
* `line`: line number of the log command in the file, which produced log message
* `group`: log group
* `module`: name of the module, which contains log command
* `id`: log message id
* `message`: message itself
Format string should consists of comma separated tokens. In it's simplest form, tokens can be just keywords, then names of the keywords are used as a fieldnames. So, for example `"timestamp,level,message"` result in `{"timestamp":"2023-01-01 12:34:56","level":"Debug","message":"some logging message"}`. If fields must be renamed, then one should use `<field name>:<keyword>` form. For example, `"severity:level"` result in `{"severity":"Debug"}`, here field name is `severity` and the value is taken from the logging `level`. One can also create nested json, in order to do it one should use `<field name>:{<format string>}` form, where previous rules for format string also applies. For example, `source:{line, file:basename}` result in `{"source":{"line":123,"file":"calculations.jl"}}`
By default, `format` is `timestamp,level,basename,line,message`.
"""
function JsonLogger(; io = stdout, ioerr = stderr, errlevel = Error, minlevel = Info, append = false, message_limits = Dict{Any, Int}(), flush = true, format = "timestamp,level,basename,line,message", dtformat = dateformat"yyyy-mm-dd HH:MM:SS", flush_threshold = 0, squash_delimiter = "\t")
tio = getio(io, append)
tioerr = io == ioerr ? tio : getio(ioerr, append)
lastflush = Dates.value(Dates.now())
JsonLogger(tio,
tioerr,
errlevel,
minlevel,
message_limits,
flush,
tokenize(JsonLoggerTokenizer(), format),
dtformat,
JsonSquash(),
squash_delimiter,
getflushthreshold(flush_threshold),
Ref(lastflush),
ReentrantLock())
end

function handle_message(logger::JsonLogger, level, message, _module, group, id,
filepath, line; maxlog=nothing, kwargs...)
if maxlog !== nothing && maxlog isa Integer
remaining = lock(logger.lock) do
logger.message_limits[id] = max(get(logger.message_limits, id, maxlog), 0) - 1
end
remaining 0 || return
end

io = if level < logger.errlevel
isopen(logger.io) ? logger.io : stdout
else
isopen(logger.ioerr) ? logger.ioerr : stderr
end

buf = IOBuffer()
iob = IOContext(buf, io)

isfirst = true
for token in logger.format
val = token.val
if val == "timestamp"
print(iob, "\"", tsnow(logger.dtformat), "\"")
elseif val == "level"
print(iob, "\"", string(level), "\"")
elseif val == "filepath"
print(iob, "\"", filepath, "\"")
elseif val == "basename"
print(iob, "\"", basename(filepath), "\"")
elseif val == "line"
print(iob, line)
elseif val == "group"
print(iob, "\"", group, "\"")
elseif val == "module"
print(iob, "\"", _module, "\"")
elseif val == "id"
print(iob, "\"", id, "\"")
elseif val == "message"
print(iob, "\"")
showmessage(iob, message, logger, logger.mode)
if length(kwargs) > 0 && !isempty(message)
print(iob, " ")
end

iscomma = false
for (k, v) in kwargs
if string(k) == v
print(iob, k)
iscomma = false
else
iscomma && print(iob, ", ")
print(iob, k, " = ")
showvalue(iob, v, logger, logger.mode)
iscomma = true
end
end
print(iob, "\"")
else
print(iob, val)
end
end
write(io, postprocess(logger.mode, logger.squash_delimiter, buf))

if logger.flush
if logger.flush_threshold <= 0
flush(io)
else
t = Dates.value(Dates.now())
if t - logger.lastflush[] >= logger.flush_threshold
logger.lastflush[] = t
flush(io)
end
end
end
nothing
end
111 changes: 6 additions & 105 deletions src/minilogger.jl
Original file line number Diff line number Diff line change
@@ -1,10 +1,4 @@
abstract type AbstractMode end
struct NoTransformations <: AbstractMode end
struct Squash <: AbstractMode end
struct FullSquash <: AbstractMode end
struct MDown <: AbstractMode end

struct MiniLogger{AM <: AbstractMode, IOT1 <: IO, IOT2 <: IO, DFT <: DateFormat} <: AbstractLogger
struct MiniLogger{AM <: AbstractMode, IOT1 <: IO, IOT2 <: IO, DFT <: DateFormat} <: AbstractMiniLogger
io::IOT1
ioerr::IOT2
errlevel::LogLevel
Expand All @@ -20,12 +14,6 @@ struct MiniLogger{AM <: AbstractMode, IOT1 <: IO, IOT2 <: IO, DFT <: DateFormat}
lock::ReentrantLock # thread-safety of message_limits Dict
end

getio(io, append) = io
getio(io::AbstractString, append) = open(io, append ? "a" : "w")

getflushthreshold(x::Integer) = x
getflushthreshold(x::TimePeriod) = Dates.value(Millisecond(x))

getmode(mode) = mode
getmode(mode::AbstractString) = getmode(Symbol(mode))
function getmode(mode::Symbol)
Expand All @@ -40,16 +28,6 @@ function getmode(mode::Symbol)
end
end

function Base.close(logger::MiniLogger)
if logger.io != stdout && logger.io != stderr && isopen(logger.io)
close(logger.io)
end

if logger.ioerr != stdout && logger.ioerr != stderr && isopen(logger.ioerr)
close(logger.ioerr)
end
end

"""
MiniLogger(; <keyword arguments>)
Expand Down Expand Up @@ -107,83 +85,6 @@ function MiniLogger(; io = stdout, ioerr = stderr, errlevel = Error, minlevel =
ReentrantLock())
end

shouldlog(logger::MiniLogger, level, _module, group, id) = lock(logger.lock) do
get(logger.message_limits, id, 1) > 0
end

min_enabled_level(logger::MiniLogger) = logger.minlevel

catch_exceptions(logger::MiniLogger) = true

# Formatting of values in key value pairs
squash(msg, logger, mode) = string(msg)
function squash(msg, logger, mode::Squash)
smsg = string(msg)
smsg = replace(smsg, "\r" => "")
smsg = replace(smsg, "\n" => logger.squash_delimiter)
end

showvalue(io, msg, logger, mode) = print(io, squash(msg, logger, mode))

function showvalue(io, e::Tuple{Exception,Any}, logger, mode)
ex, bt = e
Base.showerror(io, ex, bt; backtrace = bt!==nothing)
end
showvalue(io, ex::Exception, logger, mode) = Base.showerror(io, ex)
showvalue(io, ex::AbstractVector{Union{Ptr{Nothing}, Base.InterpreterIP}}, logger, mode) = Base.show_backtrace(io, ex)

# Here we are fighting with multiple dispatch.
# If message is `Exception` or `Tuple{Exception, Any}` or anything else
# then we want to ignore third argument.
# But if it is any other sort of message we want to dispatch result
# on the type of message transformation
_showmessage(io, msg, logger, mode) = print(io, squash(msg, logger, mode))
_showmessage(io, msg, logger, ::MDown) = show(io, MIME"text/plain"(), Markdown.parse(msg))

showmessage(io, msg, logger, mode) = _showmessage(io, msg, logger, mode)
showmessage(io, e::Tuple{Exception,Any}, logger, mode) = showvalue(io, e, logger, mode)
showmessage(io, ex::Exception, logger, mode) = showvalue(io, ex, logger, mode)
showmessage(io, ex::AbstractVector{Union{Ptr{Nothing}, Base.InterpreterIP}}, logger, mode) = Base.show_backtrace(io, ex)

function postprocess(mode, delimiter, iobuf)
print(iobuf, "\n")
take!(iobuf)
end

function postprocess(mode::FullSquash, delimiter, iobuf)
buf = take!(iobuf)
delm = Vector{UInt8}(delimiter)
res = similar(buf)
L = length(res)
j = 1
@inbounds for (i, c) in pairs(buf)
c == UInt8('\r') && continue
if c == UInt8('\n')
for c2 in delm
if j > L
resize!(res, 2*L)
L *= 2
end
res[j] = c2
j += 1
end
continue
end
res[j] = c
j += 1
end
if j > L
resize!(res, 2*L)
L *= 2
end
res[j] = UInt8('\n')

resize!(res, j)

return res
end

tsnow(dtf) = Dates.format(Dates.now(), dtf)

function colorfunc(level::LogLevel, _module, group, id, filepath, line, element)
level < Info ? Color(Base.debug_color()) :
Expand Down Expand Up @@ -243,14 +144,14 @@ function handle_message(logger::MiniLogger, level, message, _module, group, id,
end

iscomma = false
for (key, val) in kwargs
if string(key) == val
print(iob, key)
for (k, v) in kwargs
if string(k) == v
print(iob, k)
iscomma = false
else
iscomma && print(iob, ", ")
print(iob, key, " = ")
showvalue(iob, val, logger, logger.mode)
print(iob, k, " = ")
showvalue(iob, v, logger, logger.mode)
iscomma = true
end
end
Expand Down
Loading

2 comments on commit 6b4c0d7

@Arkoniak
Copy link
Collaborator 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/77688

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 v0.5.0 -m "<description of version>" 6b4c0d73429ac6b5d783489905b4be1d5c3111e4
git push origin v0.5.0

Please sign in to comment.