Logging - handling repeated warnings

[crbinz]

My code calls a function in another module that emits warning when certain conditions are met. Often, if I’m not careful, that condition will be met for many thousands of calls, resulting in many thousands of repeated warnings being printed. How can I mitigate this? I’d like to only show the first instance, if possible.

I’ve read the Logging section of the docs, and I know about maxlog, but it seems that doesn’t help me unless it’s my own code emitting the warning. Granted, I do not feel I have a very good grasp of how the new logging system works.

Here’s an example, not sure how helpful it is:

julia> using EarthOrientation, Dates

julia> daterange = DateTime("2022-01-01T00:00"):Day(1):DateTime("2022-01-05")
2022-01-01T00:00:00:1 day:2022-01-05T00:00:00

julia> getxp.(daterange) # 5 warnings; would prefer just one
┌ Warning: No data available after 2020-02-29. The last valid value will be returned.
└ @ EarthOrientation ~/.julia/packages/EarthOrientation/sQYt3/src/EarthOrientation.jl:50
┌ Warning: No data available after 2020-02-29. The last valid value will be returned.
└ @ EarthOrientation ~/.julia/packages/EarthOrientation/sQYt3/src/EarthOrientation.jl:50
┌ Warning: No data available after 2020-02-29. The last valid value will be returned.
└ @ EarthOrientation ~/.julia/packages/EarthOrientation/sQYt3/src/EarthOrientation.jl:50
┌ Warning: No data available after 2020-02-29. The last valid value will be returned.
└ @ EarthOrientation ~/.julia/packages/EarthOrientation/sQYt3/src/EarthOrientation.jl:50
┌ Warning: No data available after 2020-02-29. The last valid value will be returned.
└ @ EarthOrientation ~/.julia/packages/EarthOrientation/sQYt3/src/EarthOrientation.jl:50
5-element Array{Float64,1}:
 0.021509
 0.021509
 0.021509
 0.021509
 0.021509

[c42f]

As a crude solution which will kill all warnings and other messages from the third party module EarthOrientation, you can attach a NullLogger while you call that code:

using Logging

result = with_logger(NullLogger()) do
    EarthOrientation.getxp(daterange)
end

This is definitely a little heavy handed though, because it gives no way for the parent application to turn these messages back on when using your module; in this sense it is a non-composable (though expedient!) solution.

I think a more composable solution would involve installing a log filter while you call EarthOrientation.getxp() which could do one of several things, but attaching an additional maxlog=1 key to those specific log events would be the most straightforward. Then the log events would flow downstream to the application as we’d like.

I do have a prototype of a more general log filtering system over at GitHub - c42f/MicroLogging.jl at cjf/log-filtering which would hopefully let you do this kind of thing easily. This is a good motivating use case, so thanks for asking the question

[c42f]

To illustrate a composable solution, here’s a log filter which adds a set of keywords to all log messages matching a pattern:

using Logging

mutable struct LogKeysFilter{Parent<:AbstractLogger,Pattern,NT<:NamedTuple} <: AbstractLogger
    parent::Parent
    pattern::Pattern
    extra_keys::NT
end

Logging.shouldlog(f::LogKeysFilter, args...) = Logging.shouldlog(f.parent, args...)
Logging.min_enabled_level(f::LogKeysFilter) = Logging.min_enabled_level(f.parent)
Logging.catch_exceptions(f::LogKeysFilter) = Logging.catch_exceptions(f.parent)

function Logging.handle_message(f::LogKeysFilter, level, message, _module, group, id,
                        filepath, line; kwargs...)
    if occursin(f.pattern, message)
        Logging.handle_message(f.parent, level, message, _module, group, id, filepath, line;
                               merge(values(kwargs), f.extra_keys)...)
    else
        Logging.handle_message(f.parent, level, message, _module, group, id, filepath, line; kwargs...)
    end
end

with_logkeys(f, pattern; extra_keys...) = with_logger(f, LogKeysFilter(current_logger(), pattern, values(extra_keys)))

Usage would look like

function verbose()
    for i=1:3
        @warn "Some verbose message"
    end
end

function do_stuff()
    verbose()
end


@info "Do stuff without filter"
do_stuff()

@info "Do stuff with filter"
with_logkeys("verbose message", maxlog=1) do
    do_stuff()
end

With result:

[ Info: Do stuff without filter
┌ Warning: Some verbose message
└ @ Main ~/logtest.jl:36
┌ Warning: Some verbose message
└ @ Main ~/logtest.jl:36
┌ Warning: Some verbose message
└ @ Main ~/logtest.jl:36

[ Info: Do stuff with filter
┌ Warning: Some verbose message
└ @ Main ~/logtest.jl:36

[crbinz]

Awesome, this does exactly what I need. Thanks for putting that together.

[crbinz]

Actually… can you think of a way to do this “globally” within a module? i.e. add maxlog=1 to all log messages?

[c42f]

Yes if we generalize LogKeysFilter to accept Modules as log pattern matching criteria, we can globally install such a filter as follows:

global_logger(LogKeysFilter(global_logger(), EarthOrientation, (maxlog=1,)))

This requires the following generalization of LogKeysFilter:

using Logging

"""
    logmatch(pattern, level, message, _module, group, id, filepath, line; keywords...)

Return true if `pattern` matches the log event `(level,message, ...; keywords...)`.
"""
function logmatch
end

logmatch(pattern::Union{AbstractString,Regex}, level, message, _module, group, id, filepath, line; kws...) =
    occursin(pattern, message)
logmatch(pattern::Module, level, message, _module, group, id, filepath, line; kws...) =
    pattern == _module

mutable struct LogKeysFilter{Parent<:AbstractLogger,Pattern,NT<:NamedTuple} <: AbstractLogger
    parent::Parent
    pattern::Pattern
    extra_keys::NT
end

Logging.shouldlog(f::LogKeysFilter, args...) = Logging.shouldlog(f.parent, args...)
Logging.min_enabled_level(f::LogKeysFilter) = Logging.min_enabled_level(f.parent)
Logging.catch_exceptions(f::LogKeysFilter) = Logging.catch_exceptions(f.parent)

function Logging.handle_message(f::LogKeysFilter, level, message, _module, group, id,
                        filepath, line; kwargs...)
    if logmatch(f.pattern, level, message, _module, group, id, filepath, line; kwargs...)
        Logging.handle_message(f.parent, level, message, _module, group, id, filepath, line;
                               merge(values(kwargs), f.extra_keys)...)
    else
        Logging.handle_message(f.parent, level, message, _module, group, id, filepath, line; kwargs...)
    end
end

Note that fiddling with the global logger is by nature a global decision, and should generally be left to the application top level because having multiple modules trying to modify the global logger cannot compose in a systematic way.

[c42f]

By the way, thanks again for these questions. Having a bunch of these kind of practical use cases in mind builds the design confidence we need to go ahead with the next part of stdlib Logging. At the moment there’s frustratingly little backend filtering tooling because I’ve been a bit (overly?) cautious of baking in the wrong design.

[crbinz]

This is great, thanks.

@c42f

Note that fiddling with the global logger is by nature a global decision, and should generally be left to the application top level because having multiple modules trying to modify the global logger cannot compose in a systematic way.

On that, is there a way to filter module-wide without using a global logger? Usually the module calling EarthOrientation and generating all these warnings is my “top-level” application, but not always. I only asked about changing the global_logger because I wasn’t sure how else to accomplish what I want.

@c42f

By the way, thanks again for these questions. Having a bunch of these kind of practical use cases in mind builds the design confidence we need to go ahead with the next part of stdlib Logging .

No problem at all, glad my cluelessness can be of use to someone . Thanks again for these very useful examples.

[c42f]

@crbinz

On that, is there a way to filter module-wide without using a global logger?

There’s the environment variable JULIA_DEBUG but I really want to deprecate that and replace it with equivalent flexible and easy ways to configure the global logger.

Basically any global setting which configures logging is non-composable between modules in the sense that multiple modules may clash in attempting to configure such a global setting. This includes a global per-module verbosity stored in the module itself, an environment variable, the current global logger system, etc etc.

It sounds like you’d like a way to declare “always use these log filters when calling module A from module B”. Unfortunately I can’t see an effective composable way to get this kind of thing to work efficiently, without manually peppering the code with a lot of calls to with_logger(). Some options…

0. For isolated cases, manually pepper the code with with_logger()
1. Create a utility function in your module which makes configuring the global logger a bit easier.
2. Maybe configure your .julia/config/startup.jl to call this setup function, if it’s mainly personal interactive use you’re worried about.

I dunno. It seems kind of useful that some default logger config could be included with modules, but it’s unclear how that can configure what is essentially global state without either being noncomposable or making a system which is hopelessly inefficient. I wish I had a good answer to that problem.

[crbinz]

Thanks again. I think, for now, that I’ll go with option 1/2, since it is mainly personal interactive use that’s driving this.