How to properly implement logging in Julia package?

General Usage
,
1

Hi everyone,

I was wondering how to properly implement logging for a function in a julia package.
My problem looks something like this: I have an algorithm with iter iterations and I want to provide the user with information about the current state, so naturally I’d use the @info macro like this:

function algorithm(iter = 1000)
    @info "starting algorithm..."
    for i in 1:iter
        # do something
        @info "current iteration: $i"
    end
    @info "finished algorithm..."
end

This works fine, but the algorithm is quite fast so the calls to @info take up a lot of time compared to the “raw” runtime.
In the real example the algorithm runs in about 60 microseconds without logging and takes 4 milliseconds with logging.
For this reason I’d like to make logging optional.
For now I settled on an approach using a verbose keyword argument like this:

function algorithm(iter = 1000; verbose = false)
    verbose && @info "starting algorithm..."
    for i in 1:iter
        # do something
        verbose && @info "current iteration: $i"
    end
    verbose && @info "finished algorithm..."
end

However I don’t particularly like the fact that this kind of disables logging independently of the minimum global log level. As a user I would expect to get @info statements if my log level is set accordingly.
Additionally this leads to code where users always have to specify keyword arguments if they like verbose output:

algorithm(..., verbose = true)
algorithm(..., verbose = true)

How do you handle these types of logging in your packages?
Is there a “best-practice” way to implement something like this?

The real problem concerns the rotate function in FactorRotations.jl.

1 Like
2

Have you considered using @debug instead?

One can then set the logging level:
https://docs.julialang.org/en/v1/stdlib/Logging/

Also see the logging organization:
https://julialogging.github.io/

3

You can use @logmsg:

level = verbose ? Logging.Info : Logging.Debug
@logmsg level "Hello World"
2 Likes
4

Have a look at LoggingExtras.jl: neat and capable. I use it to print to screen and concurrently into a log file.

using LoggingExtras, Dates

const date_format = "yyyy-mm-dd HH:MM:SS"

timestamp_logger(logger) = TransformerLogger(logger) do log
  merge(log, (; message = "$(Dates.format(now(), date_format)) $(log.message)"))
end



"""
    update_simulation(cdir, simp)

Update the state of the simulation.

Carry out whatever needs to be done to produce the results.

`cdir` = campaign directory, 
`simp` = dictionary of simulation parameters
"""
function update_simulation(cdir, simp)
    @info "Simulation $(simp["name"])"

    dir = joinpath(cdir, "simulations", simp["name"])
    mkpath(dir)
    file = with_extension(simp["name"], ".json")
    jsn = joinpath(dir, file)

    logfile = joinpath(dir, with_extension(simp["name"], ".log"))
    logfilefd = open(logfile, "a")
    logging_level = "logging_level" in keys(simp) ? simp["logging_level"] : "info"
    ll = logging_level == "debug" ? Logging.Debug : Logging.Info
    demux_logger = TeeLogger(
        MinLevelLogger(timestamp_logger(FileLogger(logfilefd)), ll),
        ConsoleLogger(stdout, ll),
    );

    global_logger(demux_logger)
    ...
1 Like
5

Thanks for your replies,

Yes I did originally, but the official documentation states: Logging.Debug (log level -1000) is information intended for the developer of the program. These events are disabled by default.

Since the information is not intended for the developer but the end user I figured @debug is not a very good fit in this case.

The @logmsg level "..." syntax provided by @goerz looks quite nice. Will this have any performance impact over verbose && @info "..."?

To avoid having to specify verbose for every function call I also looked at what the Turing.jl folk did with their progress logging. They have an option to set the progress logging at a global and function level using this pattern:

const verbosity = Ref(false)  # default value

setverbosity!(x::Bool) = verbosity[] = x

function algorithm(args...; verbose = verbosity[])
    # do something
    level = verbose ? Logging.Info : Logging.Debug
    @logmsg level "..."
end

This seems like quite a nice pattern to me since it allows the user to conveniently enable verbosity globally while still logging at the “correct” level.

6

Also check out