User defined logger behaviour

General Usage
1

Hello,

I read on how logging in Julia works at: Logging · The Julia Language . Great stuff, good to see the split in the overall design between creating events and processing them by means of defining a logger.

I am interested in creating a custom logger which will be adding e.g. DateTime, UserId, etc. to each log event. I understand that this can be achieved by overloading Logging.handle_message . Does anyone have experience with this? A simple example would be great.

an event like

@info "Message 1"

should result in a log

DateTime(), UserId, Message 1

Thanks!

2

This seems to do the job. I can do:

using Logging
using Dates

include("MyLogger.jl")

# --- custom logging with time-stamp included
lg = MyLogger()

with_logger(lg) do
    @info "a context specific log message"
end

which yields

┌ 2021-06-23T18:00:36.118
│ Info: a context specific log message
└ @ Main --- REPL[6]:2

The custom logger definition is as follows.

struct MyLogger <: AbstractLogger
    stream::IO
    min_level::LogLevel
    message_limits::Dict{Any,Int}
end
MyLogger(stream::IO=stderr, level=Logging.Info) = MyLogger(stream, level, Dict{Any,Int}())

Logging.shouldlog(logger::MyLogger, level, _module, group, id) =
    get(logger.message_limits, id, 1) > 0

Logging.min_enabled_level(logger::MyLogger) = logger.min_level

Logging.catch_exceptions(logger::MyLogger) = false

function Logging.handle_message(logger::MyLogger, level, message, _module, group, id,
                        filepath, line; maxlog=nothing, kwargs...)
    if maxlog !== nothing && maxlog isa Integer
        remaining = get!(logger.message_limits, id, maxlog)
        logger.message_limits[id] = remaining - 1
        remaining > 0 || return
    end
    buf = IOBuffer()
    iob = IOContext(buf, logger.stream)
    levelstr = level == Logging.Warn ? "Warning" : string(level)
    msglines = split(chomp(string(message)), '\n')
    println(iob, "┌ ", now()) # ----------------------------------[ inserting time-stamp]
    println(iob, "│ ", levelstr, ": ", msglines[1])
    for i in 2:length(msglines)
        println(iob, "│ ", msglines[i])
    end
    for (key, val) in kwargs
        println(iob, "│   ", key, " = ", val)
    end
    println(iob, "└ @ ", something(_module, "nothing"), " --- ",
            something(filepath, "nothing"), ":", something(line, "nothing"))
    write(logger.stream, take!(buf))
    nothing
end
3

Everything you want exist in the LoggingExtras package. In this case I think you are most interested in TransformerLogger which lets you modify e.g. the message string (there is an example for adding datetime to the message here), and perhaps FormatLogger which gives you full control of the formatting.

3 Likes
4

Thanks for a reply. Yes, indeed, LoggingExtras does the stuff we want to achieve. The links to the examples you provided are useful, thanks!

1 Like
5

Just for sake of completeness. This is how I approached augmenting all the events with time information and user id. The events themselves does not have to include any of the augmenting information.

Great stuff! Thanks for the LoggingExtras!

using LoggingExtras
using Dates

function runFunc(data, userId)
    println("I see my userId is: ", userId, "\n")

    # --- logging with time-stamp and userId included
    augmentingLogger = TransformerLogger(global_logger()) do log
        merge(log, (; message = "$(now()) -- userId: $(userId) -- $(log.message)"))
    end

    with_logger(augmentingLogger) do
        doCalculation(data)
    end
end

function doCalculation(data)
    @info "Calculating a sum ..." # ---> this event does not have to include userId or time of calculation
    sum(data)
end

runFunc(1:10, 1)
runFunc(1:10, 2)