TeeLogger does not work with JULIA_DEBUG?

[tkf]

I thought global_logger(DemuxLogger(NullLogger())) would be a no-op. However, @debug stopped working after this.

julia> ENV["JULIA_DEBUG"] = "Main"
"Main"

julia> @debug "hello"
┌ Debug: hello
└ @ Main REPL[2]:1

julia> @info "hello"
[ Info: hello

julia> using Logging

julia> using LoggingExtras

julia> global_logger(DemuxLogger(NullLogger()))
ConsoleLogger(Base.TTY(RawFD(0x0000000f) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> @debug "hello"

julia> @info "hello"
[ Info: hello

(v1.3) pkg> st LoggingExtras
Status `~/.julia/environments/v1.3/Project.toml`
  [e6f89c97] LoggingExtras v0.3.0

[tkf]

Reading related posts, it seems that JULIA_DEBUG has some issues in its design:
JuliaLang/julia#26265
JuliaLang/julia#30003
JuliaLang/julia#32432

So, maybe LoggingExtras.jl does not have to support it. It would still be nice to mention this in the documentation and provide an alternative.

[oxinabox]

Until today I didn't entirely understand JULIA_DEBUG.
I think I get it after reading the docs.

At first I assumed it didn't work because the behavour was baked into the the ConsoleLogger.
But no, it is more weird than that, it is baked into the logging system and bypasses a bunch of it

---

Some preamble:

LoggingExtras basically exists to solve
@c42f's point in JuliaLang/julia#30003 (comment)

To solve this we "just" need a convenient declarative way of configuring loggers directly rather than indirectly using the environment. The reason this is hard is that defining a "convenient declarative configuration" tends to box in the design of the code which is being configured. To avoid that you really want a broad set of examples (of various implementations of AbstractLogger) on which to base the config system, and we just didn't have that in 0.7 so I admit I punted on it. I was hoping people would pursue it in packages for a while :-)

Doing this kind of configuration via enviroment variables is just too hard to be specific.
And it is also such global state.
It is basically antithitical to making a sensible logging system,
as was pointed out in the issued where it was made.

The Logging Extras Philosophy is that Sinks should accept everything that is given to them.
And filtering should be used to get rid of things.
So what you want should infact be done via EarlyFilterLogger to select that things from Debug Level from the Main module be accepted.

---

Anyway, with the preamble covered:

What is going on is:

julia> global_logger(DemuxLogger(NullLogger()))
ConsoleLogger(Base.TTY(RawFD(0x00000010) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> lg = current_logger()
DemuxLogger(Base.CoreLogging.AbstractLogger[Base.CoreLogging.NullLogger(), ConsoleLogger(Base.TTY(
RawFD(0x00000010) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}(
))])

julia> lg.loggers
2-element Array{Base.CoreLogging.AbstractLogger,1}:
 Base.CoreLogging.NullLogger()
 ConsoleLogger(Base.TTY(RawFD(0x00000010) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> Logging.min_enabled_level(lg)
Info

julia> Logging.min_enabled_level(lg.loggers[1])
AboveMaxLevel

julia> Logging.min_enabled_level(lg.loggers[2])
Info

What ENV["JULIA_DEBUG"] does isn't configure the logger's shouldlog behavour.
but rather bypass it all together **
This means that even though the DemuxLogger has configuration such that it won't log for below Info level (which it inherits from the downstream ConsoleLogger that was the global),
it is caused to log anyway.
But then because the DemuxLog is a good compositional citizen,
it asks its downstream loggers if they are willing to accept a message of Debug level.
Which the ConsoleLogger is like "Nope".
And so the DemuxLogger never passes it on.

**(This bit makes me kinda frustrated. We have a logging system that includes a place to make this check in the loggers, but rather than using them, that feature just bypasses them entirely.
I wonder if a PR to change so that that is a feature of the ConsoleLogger.should_log would be acceptable.)

---

The way to do this:

using Logging, LoggingExtras
ENV["JULIA_DEBUG"] = ""  # this thing is a mess, don't touch it.

sink = ConsoleLogger(stderr, Logging.BelowMinLevel)  # A proper sink
apply_filter(child) = EarlyFilteredLogger(child) do log
    log._module==Main || log.level > Logging.Debug
end

composed_logger = apply_filter(DemuxLogger(NullLogger(), sink;  include_current_global=false))
global_logger(composed_logger)

What do do from here, idk.

• We could make that eviroment variable be checked whenever we are checking downstream composed loggers here
• We could just document this: "LoggingExtras does not play nice with the "JULIA_DEBUG" enviroment variable, but instread provides a far richer compositional logging system that can achieve the same goals and more. See this issue. Rather than ENV["JULIA_DEBUG"]="Main" the LoggingExtras way is: ...."

I lean towards the later.
If we got rid of JULIA_DEBUG then the LoggingExtras way in my example above would actually solve the performance issues in JuliaLang/julia#30003
I could maybe provide an a function in LoggingExtras that the user could call solve_30003() that would just monkey-patch Base and solve it.

[oxinabox]

We also could provide a function that interprets the string in ENV["JULIA_DEBUG"]
and builds you that composable logger.
That could be cool and would be a nice little project if someone was interested.

[tkf]

I wonder if a PR to change so that that is a feature of the ConsoleLogger.should_log would be acceptable.

I think it would be great. I think all JULIA_DEBUG is doing can be done with a function call to swap the global logger or mutate some inner state of the global logger. This also avoids re-parsing ENV["JULIA_DEBUG"] for every single @logmsg...

We also could provide a function that interprets the string in ENV["JULIA_DEBUG"]
and builds you that composable logger.

I don't think JULIA_DEBUG itself is a good feature (except JULIA_DEBUG=loading julia) that is worth replicating. There just has to be an interactive interface for changing what is debugged. Maybe a function like setdebug(Main, MyPackage) or even a macro @setdebug Main MyPackage !HTTP for extra convenience.

But I think the tricky part might be for getting the "child/inner logger" that is wrapped by the filtering logger. That is to say, I think we need a function (say) global_inner_logger() to implement setdebug:

function setdebug(modules::Module...)
    inner_logger = global_inner_logger()
    composed_logger = EarlyFilteredLogger(inner_logger) do log
        log._module in modules || log.level > Logging.Debug
    end
    global_logger(composed_logger)
end

global_inner_logger() = ???

One way to implement this might be to create a special logger type DebugLogger and then

function setdebug(modules::Module...)
    inner_logger = global_inner_logger()
    composed_logger = DebugLogger(modules, inner_logger)
    global_logger(composed_logger)
end

global_inner_logger() = something(inner_logger_of(DebugLogger, global_logger()), global_logger())
inner_logger_of(T, logger) = ...

where inner_logger_of(T, logger) traverses the logger tree, find the first logger of type T, and return the logger wrapped by it (or nothing if not found).

[oxinabox]

what is the motivation for doing interactively?

My experience from Memento has been that configuring your logging up front at the start, then never change it.

Lets open another issue for any further discussion of traversing the logging tree.
There is likely a bunch to discuss around it.

And focus this on things closely related to ENV["JULIA_DEBUG"]

[tkf]

what is the motivation for doing interactively?

I thought the whole reason why current_logger_for_env checks ENV all the time is to change the logging level dynamically. Otherwise I think it would be set in the constructor to hoist it out.

Interactive usage is also mentioned in the documentation now: JuliaLang/julia#33513. I also find it handy to change the log level interactively in the REPL. I think some long-running services support changing log level dynamically, e.g., using SIGUSR1/SIGUSR2.

[c42f]

Sorry guys I don't have time to give this my full attention today. A grab bag of thoughts:

I do feel that current_logger_for_env is a hack. It certainly works against the original intent of the design rather than with it. In implementation, the fact that it dynamically looks up environment variables for each message is especially icky ;-)

I've been musing about how to replace JULIA_DEBUG. There's a more static way to achieve much the same level of interactivity at the REPL: have a REPL logger which wraps each command run from the REPL, essentially with a with_logger(repl_logger) do $user_cmd end. Then the user can modify repl_logger via some convenient API and their modifications will take effect interactively.

The main difference with JULIA_DEBUG is that it doesn't apply globally to all async tasks. The most desirable "correct" behaviour for loggers as applied to async tasks has me confused TBH. Currently their loggers are inherited from the parent task which makes a fair amount of sense in a structured-concurrency style world, but we don't have that yet and it's not yet clear that Julia is going in that direction.

[tkf]

It was frustrating to (retrospectively) see a feature creep of JULIA_DEBUG while you are arguing that there are better ways! (Although to be honest I did +1 on a JULIA_DEBUG issue before knowing Logging.jl a bit more 😅)

Currently their loggers are inherited from the parent task which makes a fair amount of sense in a structured-concurrency style world, but we don't have that yet and it's not yet clear that Julia is going in that direction.

Naively thinking, "local by default" sounds like a nice guideline (e.g., Julia uses global to opt-in global variable). It is easy to make some state of a logger global when it is local by default. For example, we can create a "singleton logger" quite easily to make a logger globally resettable:

struct SingletonLogger <: AbstractLogger end
handle_message(::SingletonLogger, args...; kwargs...) =
    handle_message(_LOGGER, args...; kwargs...)
# ...and so on...

const _LOGGER = Ref{Any}()
setsingletonlogger(logger) = _LOGGER[] = logger

I think the other way around is impossible.

[c42f]

Yes JULIA_DEBUG was frustrating and hard to argue against because I didn't have a solid, implemented, alternative to give people; only high level design advice which can be hard to communicate clearly. It's definitely useful functionality but it leads to a design dead end which we must now dig ourselves out of. Fortunately I don't think that's too hard.

[rssdev10]

JULIA_DEBUG can be enabled with the patch #84 .
But I see more fundamental problems - trying to combine filtering based on levels and exceptional filtering specified by JULIA_DEBUG. There is the function Base.CoreLogging.env_override_minlevel(group, _module). This function is used for doing early filtering of the messages. But next, only this condition is used - min_enabled_level(logger) <= level && shouldlog(logger, level, _module, group, id).

And, moreover, in fact, the function shouldlog for standard loggers is doing almost nothing except restriction by a counter. Both for the ConsoleLogger and for TestLogger.

The question is why we have a configurable Debug level as the only exceptional processing?... Why don't we have a mechanism with configurable levels per class like in Java (a module in the Julia case)?

The sample of the XML config with example of three different levels for chapters.configuration, chapters.configuration.Foo and the root level:

<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>
        %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%kvp- %msg%n
     </pattern>
    </encoder>
  </appender>

  <logger name="chapters.configuration" level="INFO" />
  <logger name="chapters.configuration.Foo" level="DEBUG" />

  <root level="WARN">
    <appender-ref ref="STDOUT" />
  </root>

</configuration>

For that, we need to keep somewhere a Dict of modules and log-levels. And, probably, rethink about shouldlog usage to avoid workarounds with env_override_minlevel.

[oxinabox]

The question is why we have a configurable Debug level as the only exceptional processing?... Why don't we have a mechanism with configurable levels per class like in Java (a module in the Julia case)?

We don't need a dict of levels.
We just configure the logger in code
You just have a EarlyFilteredLogger, including lined which are like.

EarlyFilteredLogger(sink) do log
     log._module == Configuration && log.level >= Info() ||
     log._module == Foo && log.level >= Debug() ||
     log.level >= Warn()
end

Anyway the JULIA_DEBUG issue is fixed.
So this issue can be closed
It does continue to be my positon that configuration of loggers outside of turing complete code, is always going to leave one wanting.
Whether that's with a configuration file of different settings for different modules, or with an enviroment variable.