`@safe_debug` does not always work well with `LoggingExtras.jl`

[haakon-e]

I use LoggingExtras.jl for fine-grained logging control. In the following instance, it seems it does not play well with GPUCompiler.jl's @safe_debug:

# julia
# ]activate --temp
# ] add GPUCompiler, LoggingExtras
using GPUCompiler, Logging, LoggingExtras

# Define a custom filter logger 
console_logger = Logging.ConsoleLogger(stdout, Logging.Debug)  # deliberately set to debug
info_logger = LoggingExtras.EarlyFilteredLogger(log -> log.level >= Logging.Info, console_logger)  # here, I filter out anything below Info
global_logger(info_logger)

# in Julia REPL, test some logging levels:
julia> @info "hi"
[ Info: hi

julia> @debug "hi"  # no output

julia> GPUCompiler.@safe_debug "hi"
┌ Debug: hi
└ @ Main REPL[50]:1

The example above is a bit contrived because I obviously could achieve this using Logging.ConsoleLogger(stdout). In my actual code, I am using LoggingExtras.TeeLogger to write to file and stdout simultaneously, e.g.:

logger = LoggingExtras.TeeLogger((
    LoggingExtras.FileLogger("info.log"),  # if I comment out this line, then @safe_debug, below, doesn't print
    Logging.ConsoleLogger(stdout)
))
global_logger(logger)

julia> GPUCompiler.@safe_debug "hi"
┌ Debug: hi
└ @ Main REPL[74]:1

---

Julia Version 1.11.5, GPUCompiler v1.6.1, LoggingExtras v1.1.0

[maleadt]

cc @danielwe.

I don't have experience with LoggingExtras so it may be better to file an issue there.

[danielwe]

I don't think you can expect the @safe_ logging macros to interoperate nicely with LoggingExtras. To be safe, they need to define and use their own custom logger, bypassing both the global and custom logger. They try to respect the min_level of the global logger, but, again to be safe, they cannot use the more specific filtering rules that may be defined in the logger's shouldlog method.

[oxinabox]

I agree with @danielwe I don't see any way they can be made to be both safe and interoperable with LoggingExtras.
The core point of the @safe_ logging macros is to avoid task switches (yeilds), which can only be done if you control exactly what code gets called -- since any user code is able to yield (and logging code is very likely to).
The core point of LoggingExtra is to allow the insertion of user code into the logger logic."
It's mutually incompatible.

Longer term maybe we should ask the compiler folk to give us a tool to disable yields in dynamic scope.
I talked to @vchuravy about doing this with Cassette a few juliacons ago.
Such a thing could automatically be done in generated functions.
There is currently no such issue in JuliaLang/Julia (at least not that i could find)

My suggestion for handling this in the case of the TeeLogger is to push it down to the OS.
Run julia using the unix tool tee
and log everything to stdout, and make tee handle writing stuff to different streams (and use other tools like awk/grep/sed to do your filtering/trasforms)

[haakon-e]

Thanks for the feedback and reflections.

After some tinkering, I was able to work around this issue by wrapping the desired logger in LoggingExtras.MinLevelLogger as follows:

Logging.global_logger(LoggingExtras.MinLevelLogger(logger, Logging.Info))

---

Additional digging

I noticed that GPUCompiler.jl invokes Logging.min_enabled_level to get the log level, and then creates a simple console logger by Logging.ConsoleLogger(io, min_level).

Example 1 from above

The first example above makes GPUCompiler.jl emit debug messages because:

julia> Logging.min_enabled_level(info_logger)
Debug

which happens because the EarlyFilteredLogger returns the min level of the encapsulated logger:

# LoggingExtras.jl/src/CompositionalLoggers/earlyfiltered.jl:L35
min_enabled_level(logger::EarlyFilteredLogger) = min_enabled_level(logger.logger)

Example 2 from above

The second example above emits debug messages because TeeLogger implements min_enabled level by:

# LoggingExtras.jl/src/CompositionalLoggers/tee.jl:L33
function min_enabled_level(demux::TeeLogger)
    minimum(min_enabled_level(logger) for logger in demux.loggers)
end

and the wrapped loggers each emit:

julia> Logging.min_enabled_level.(logger.loggers)
(BelowMinLevel, Info)

This indicates that the second example alternatively can be fixed by wrapping the FileLogger in MinLevelLogger:

logger = LoggingExtras.TeeLogger((
    LoggingExtras.MinLevelLogger(LoggingExtras.FileLogger("info.log"), Logging.Info),  # if I comment out this line, then @safe_debug, below, doesn't print
    Logging.ConsoleLogger(stdout)
))
# indeed, we now have:
julia> Logging.min_enabled_level(logger)
Info

The caveat to this workaround, of course, is that GPUCompiler.jl still only emits log messages to console, because it defines its own ConsoleLogger with the derived min_level. As such, no messages from this package are saved to file. In my case, this is unproblematic as I am nominally not interested in messages emitted from GPUCompiler.jl anyways, particularly not debug-level messages.