Setting Log Level in v0.6?

[ccoffrin]

It seems since using v0.6 setlevel!(LOGGER, "info") does not report info to the terminal. I explored using Memento.config(LOGGER, "info") but ran into seg fault issues. Any insights?

[ccoffrin]

Upon further inspection, it seems like the root logging level might have been changed. What could change the default logging level changed from info to warn?

[rofinn]

It seems since using v0.6 setlevel!(LOGGER, "info") does not report info to the terminal. I explored using Memento.config(LOGGER, "info") but ran into seg fault issues. Any insights?

This is related to #63. Essentially, setlevel!(LOGGER, "info") will only set the logging level for the child logger LOGGER. Most messages must propagate to the root logger in order to be printed to STDOUT, unless you've registered a handler to the child logger. This is by design, as you typically only want info/debug messages from your root/application logger and you usually don't want message from libraries unless explicitly set along side the root logger. Memento.config(LOGGER, "info") is setting up an arbitrary logger in the same way that root logger is configured by Memento.config("info"), including adding a handler for printing directly to STDOUT.

Upon further inspection, it seems like the root logging level might have been changed. What could change the default logging level changed from info to warn?

The root logging level can changed just like every other logger:

1) Memento.config("info") is the most common way that the root logger level is changed. 2) setlevel(getlogger(), "info") will also change the root logger level.

Regarding the segfault issue, if the LOGGER is being used in a package that is precompileable then some care should be taken to register and configure the logger in an __init__ method. Posting a link might be the easiest option if your code is publicly available.

[ccoffrin]

Ok. It is quite important that the default logging behavior of PowerModels be "info" and not "warn", which seems to happen to me often. How would you recomend achieving that semantics?

[rofinn]

If you're just working with PowerModels.jl on the REPL directly then I'd recommend Memento.config(getlogger("PowerModels"), "info") (same goes for debugging issues in your test/runtests.jl). FWIW, running Memento.config inside your package, but not in the __init__ function will likely cause segfaults.

[ccoffrin]

I did some testing and converged on this fix,

https://github.com/lanl-ansi/PowerModels.jl/commit/c657a37c2e38ee08158b21a415aae696b04f0cf9

Does it look reasonable to you?

Some notes from my testing on Julia v0.6, PowerModels v0.6, Memento v0.6

# in package, no info messages shown
setlevel!(LOGGER, "info")

# in REPL, no info messages shown
using PowerModels; using Memento
setlevel!(getlogger(PowerModels), "info")

# in REPL, info messages shown
using PowerModels; using Memento
Memento.config(getlogger("PowerModels"), "info")

# in REPL, info messages shown
using PowerModels; using Memento
setlevel!(getlogger(), "info")

# in package __init__, info messages shown
Memento.config(LOGGER, "info")

[rofinn]

1. # in package, no info messages shown
   setlevel!(LOGGER, "info")

   No message will be shown unless you do using Memento; Memento.config("info") in the REPL

2. # in REPL, no info messages shown
   using PowerModels; using Memento
   setlevel!(getlogger(PowerModels), "info")

   Again, this is expected as the root logger is still set to "warn" by default. So

   # in REPL, no info messages shown
   using PowerModels; using Memento
   Memento.config("info")
   setlevel!(getlogger(PowerModels), "info")

   would work.

3. using PowerModels; using Memento
   Memento.config(getlogger("PowerModels"), "info")

   This one is expected to print your info messages because it is both setting the level to "info" and adding a handler for it to print to STDOUT. Warning: if you did Memento.config("info") later on then you'd start getting duplicate messages because both the child and root loggers would be seeing the message and writing it to their respective handlers.

4. # in REPL, info messages shown
   using PowerModels; using Memento
   setlevel!(getlogger(), "info")

   I'm assuming that you had setlevel!(LOGGER, "info") in your package? Then yes, the child logger will propagate the message and the root logger (set to "info") will write it to its handler. Memento.config("info") would achieve the same result and is clearer IMHO.

5. # in package __init__, info messages shown
   Memento.config(LOGGER, "info")

   This is essentially the same as 3 and has the same potential problem of duplicate messages. Outside of application packages (folks are only interacting with your package on the repl) I strong advise against this pattern.

Overall, I recommend using Memento.config(getlogger("MyPkg"), "info") on the REPL or in package tests. One pattern that some folks like is providing a MyPkg.config(...) (or MyPkg.interactive(...)) function which handles setting up logging on the REPL in a nice way, but doesn't force anyone using your package in their application to get info messages (I usually only care about "notice" or higher).

using Memento

function config(level)
     # By running Memento.config(level) and setlevel! we avoid potential duplicate messages
     Memento.config(level)
    setlevel!(getlogger("MyPkg"), level)
end

The general design goal for Memento is that we want to allow for fine grained control over logging from all of our different packages at runtime. For example, when debugging issues I often only want to see info level messages from my application package and maybe 1 dependent package Foo, but I want to see debug messages just from a submodule that's causing me problems Foo.Bar. We're still trying to sort out how to provide all of that flexibility while making it easy for folks to get info message from 1 pkg without needing to know about Memento. I hope that clears things up a little.

[ccoffrin]

For PowerModels, the root of the issue is really about the default behavior. Julia's standard is that info() messages go to the terminal, while Memento's default appears to be at the warn level. This causes confusion for novice users, who are used to the Julia default and expect info messages to be printed without the need to explicitly increase the logging level.

Would you be open to changing Memento's default behavior?

[rofinn]

Hmmm, I largely disagree with how info works in base julia (it's basically just a glorified print statement), but I guess having an issue that people can up/down vote might be worthwhile.

[rofinn]

The latest release of Memento supports a recursive flag on config! and setlevel! and the default level is now info on master. Is it alright if I close this issue once both of those changes are in a tagged releases?

[ccoffrin]

Oh great! Sure lets close this and please ping me once a version is tagged with this change so I can update and test PowerModels.