RFC: Add support for "all except x" in JULIA_DEBUG

[DilumAluthge]

If I want to see debugging messages for the module Foo, I can set the JULIA_DEBUG environment variable to loading.

If I want to see debugging messages from all modules, I can set the JULIA_DEBUG environment variable to all.

However, if I want to see all debugging messages EXCEPT those from the Foo module, currently there is no way of doing this in Julia.

This pull request adds the ability to turn on debugging messages from all modules except a specified list. The modules to exclude are prefixed with ! when listed in JULIA_DEBUG. For example, ENV["JULIA_DEBUG"] = "all,!Foo,!Baz" will turn on debugging messages from all modules except Foo and Baz.

The existing behavior of JULIA_DEBUG is preserved.

Example usage

Summary

JULIA_DEBUG	Foo	Bar	Baz
	❌	❌	❌
Foo	✅	❌	❌
Foo,Baz	✅	❌	✅
all	✅	✅	✅
all,!Foo	❌	✅	✅
!Foo	❌	✅	✅
!Foo,!Baz	❌	✅	❌
all,!all	❌	❌	❌
all,!all,!Foo	❌	❌	❌
all,!all,!Foo,!Baz	❌	❌	❌
!all,!Foo	❌	❌	❌
!all,!Foo,!Baz	❌	❌	❌
all,!all,!Foo,Bar,!Baz	❌	✅	❌
!all,!Foo,Bar,!Baz	❌	✅	❌

Code

julia> module Foo
       hello() = @debug("Hello from Foo")
       end
Main.Foo

julia> module Bar
       hello() = @debug("Hello from Bar")
       end
Main.Bar

julia> module Baz
       hello() = @debug("Hello from Baz")
       end
Main.Baz

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

julia> Foo.hello()

julia> Bar.hello()

julia> Baz.hello()

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

julia> Foo.hello()
┌ Debug: Hello from Foo
└ @ Main.Foo REPL[1]:2

julia> Bar.hello()

julia> Baz.hello()

julia> ENV["JULIA_DEBUG"] = "Foo,Baz"
"Foo,Baz"

julia> Foo.hello()
┌ Debug: Hello from Foo
└ @ Main.Foo REPL[1]:2

julia> Bar.hello()

julia> Baz.hello()
┌ Debug: Hello from Baz
└ @ Main.Baz REPL[3]:2

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

julia> Foo.hello()
┌ Debug: Hello from Foo
└ @ Main.Foo REPL[1]:2

julia> Bar.hello()
┌ Debug: Hello from Bar
└ @ Main.Bar REPL[2]:2

julia> Baz.hello()
┌ Debug: Hello from Baz
└ @ Main.Baz REPL[3]:2

julia> ENV["JULIA_DEBUG"] = "all,!Foo"
"all,!Foo"

julia> Foo.hello()

julia> Bar.hello()
┌ Debug: Hello from Bar
└ @ Main.Bar REPL[2]:2

julia> Baz.hello()
┌ Debug: Hello from Baz
└ @ Main.Baz REPL[3]:2

If !all is specified, it "cancels out" all.

julia> ENV["JULIA_DEBUG"] = "all,!all"
"all,!all"

julia> Foo.hello()

julia> Bar.hello()

julia> Baz.hello()

julia> ENV["JULIA_DEBUG"] = "all,!all,!Foo"
"all,!all,!Foo"

julia> Foo.hello()

julia> Bar.hello()

julia> Baz.hello()

julia> ENV["JULIA_DEBUG"] = "all,!all,!Foo,!Baz"
"all,!all,!Foo,!Baz"

julia> Foo.hello()

julia> Bar.hello()

julia> Baz.hello()

If neither all nor !all are specified, then !x implies all.

julia> ENV["JULIA_DEBUG"] = "!Foo"
"!Foo"

julia> Foo.hello()

julia> Bar.hello()
┌ Debug: Hello from Bar
└ @ Main.Bar REPL[2]:2

julia> Baz.hello()
┌ Debug: Hello from Baz
└ @ Main.Baz REPL[3]:2

julia> ENV["JULIA_DEBUG"] = "!Foo,!Baz"
"!Foo,!Baz"

julia> Foo.hello()

julia> Bar.hello()
┌ Debug: Hello from Bar
└ @ Main.Bar REPL[2]:2

julia> Baz.hello()

If !all is specified, then !x does not imply all.

julia> ENV["JULIA_DEBUG"] = "!all,!Foo"
"!all,!Foo"

julia> Foo.hello()

julia> Bar.hello()

julia> Baz.hello()

julia> ENV["JULIA_DEBUG"] = "!all,!Foo,!Baz"
"!all,!Foo,!Baz"

julia> Foo.hello()

julia> Bar.hello()

julia> Baz.hello()

julia> ENV["JULIA_DEBUG"] = "!all,!Foo,Bar,!Baz"
"!all,!Foo,Bar,!Baz"

julia> Foo.hello()

julia> Bar.hello()
┌ Debug: Hello from Bar
└ @ Main.Bar REPL[2]:2

julia> Baz.hello()

julia> ENV["JULIA_DEBUG"] = "all,!all,!Foo,Bar,!Baz"
"all,!all,!Foo,Bar,!Baz"

julia> Foo.hello()

julia> Bar.hello()
┌ Debug: Hello from Bar
└ @ Main.Bar REPL[2]:2

julia> Baz.hello()

[vtjnash]

Seems good to me.

[DilumAluthge]

Done!

!x implies all, but !all does not imply all.

I've updated the tests. I've also updated the examples in the original post.

[DilumAluthge]

It doesn’t look like the buildbot failures are related to this PR.

[DilumAluthge]

Done!

[StefanKarpinski]

This is a nice bit of functionality to have! @c42f, would you be willing to review?

[c42f]

@StefanKarpinski sure.

The functionality here is useful, but I still don't think we should have the JULIA_DEBUG mechanism in CoreLogging because it cuts across the whole intent of the log filtering system with a bunch of non-composable functionality. User-installed loggers can't opt out (see #30003) and adding more complexity will only exacerbate the problem.

As a possible way forward, how about we consider moving all JULIA_DEBUG handling into shouldlog(::ConsoleLogger, ...) (and possibly shouldlog(SimpleLogger, ...) as a concession for early init logging)?

[StefanKarpinski]

As I see it the problem is that other than JULIA_DEBUG not alternative that is as usable or simple has been proposed. If we had an alternative, then perhaps, but based on what you've written, I have no idea how I would go about controlling what does or doesn't get logged.

[c42f]

Apologies for being short / cryptic, I'm just busy. I do appreciate that people care for the usability and I know the current system is difficult to control as it comes "out of the box". However, lacking the time to think deeply about this I'd rather leave the innovation to packages.

My specific concern with JULIA_DEBUG is continuing to bake in functionality to a design that inherently can't be made fast in the future. If we allow logging to be controlled via environment variables we give permission for any piece of code anywhere on the call stack - and on any thread - to change what gets logged at any time (side note - getenv / setenv are not threadsafe to boot). Furthermore we force ourselves to compare strings to decide when the config has changed. These seem like fundamental problems to me and I wish we wouldn't use environment variables for this.

Instead I'd prefer to hoist all this logic into the loggers so that logging control is at least thread local and can't be modified by a callee. Specifically I think we should

• Move this logic into the shouldlog functions of our standard loggers or composable log filters. The LoggingExtras package has some examples of how this kind of thing works.
• Add some convenience functions to Logging to allow modifying the global logger "in place" with the convenience of setting an environment variable.
• Possibly remove the min_enabled_level stuff as I think it caused these problems in the first place.

[c42f]

Ugh, my apologies - I definitely didn't mean to close this.

Nor was I finished replying... The above notes are reasonably representative of my thoughts though, if a bit rough around the edges.

[c42f]

On further consideration I think we should just merge this PR: it's undeniably useful functionality and doesn't change anything fundamental about the way that JULIA_DEBUG is used. A further PR can always refactor a bit to improve the performance and preserve the use case which this serves.

One question: how committed are we to an environment variable being the official API here? I'm still hazy about how stable we require the stdlibs to be and I originally thought of JULIA_DEBUG as simply a useful internal hack for debugging Base during early initialization...

[StefanKarpinski]

how committed are we to an environment variable being the official API here?

Not at all. If there were a better API people we could encourage people to use it.

[DilumAluthge]

Bump. Is there a consensus in favor of merging this PR? If so, do you think it can make it into Julia 1.4?

[KristofferC]

Out of curiosity, what is the use case for this? It seems this is basically saying, "everyone, feel free to spew as much debug messages you want at me, except this guy, you should be quiet". When does that actually happen?

[DilumAluthge]

Yeah good point. For me, the use case is that I'm debugging some application with a whole bunch of modules and dependencies, and I'm trying to nail down exactly where things go wrong. There are so many @debug statements in so many different modules, and I want to see all of them so that I can pinpoint the location of the bug. Since there are so many modules, I don't want to list them out manually, so I use JULIA_DEBUG=all.

Sometimes, though, there are one or two modules that (1) I know are not the source of the bug, and (2) spew a lot of debug messages. In those cases, it's helpful for me to disable debug messages from those modules only, which makes it easier for me to read the logs.

[c42f]

Despite my comment above, I'm still struggling to decide what to do with this as it is. On the one hand it's useful, but I'd feel a lot more comfortable merging it if all the environment variable logic was moved into a helper function and called from shouldlog(::SimpleLogger, ...) and shouldlog(::ConsoleLogger ...).

Do you have time to invest on following this up with a PR which does that? The key is that users should be able to opt out of the entire code path which looks at JULIA_DEBUG by installing their own logger.

[DilumAluthge]

Do you have time to invest on following this up with a PR which does that? The key is that users should be able to opt out of the entire code path which looks at JULIA_DEBUG by installing their own logger.

Honestly, I don't think that I'll have time to work on that PR, at least not in the near future :(

Regarding this PR, how about we close it for now, and revisit it in the future?

[vtjnash]

In those cases, it's helpful for me to disable debug messages from those modules only

Makes sense to me. That aligns pretty well with the original goal of letting you enable them easily based on lots of different criteria.

[c42f]

Ok, well I guess we've got forward progress here (good!) but somewhat at the expense of communication / consensus (not so good :-/ )

@vtjnash I do feel like the conversation was truncated here and it would have been nice if you'd added a comment along the lines of "I'm going to merge this because I think forward progress in this case is better than worrying about the details". At least, I assume that's the judgement call you're making here, and I think it's fair enough.

I need to do a design iteration on log record dispatch anyway, so perhaps this will spur it along 😬