Debug logs are not printed from package, unless logger initialised at "debug" level

[mmiller-max]

I'm configuring a logger within a package like this (modified Example.jl for MWE):

module Example
export hello, domath

using Memento

# Create  module level logger (this will get precompiled)
# const LOGGER = getlogger(@__MODULE__)
const LOGGER  = getlogger(@__MODULE__)

# Register the module level logger at runtime so that folks can access the logger via `get_logger(MyModule)`
# NOTE: If this line is not included then the precompiled `MyModule.LOGGER` won't be registered at runtime.
function __init__()
    LOGGER = Memento.config!("info"; fmt="{date} - {name} - {level} - {msg}", colorized=false)
    Memento.register(LOGGER)
end

"""
    hello(who::String)

Return "Hello, `who`".
"""
function hello(who::String)
    Memento.debug(LOGGER, "debug message")
    Memento.info(LOGGER, "info message")
    Memento.warn(LOGGER, "warn message")
    "Hello, $who"
end
"""
    domath(x::Number)

Return `x + 5`.
"""
domath(x::Number) = x + 5

end

If I then change the log level to debug, the debug message does not appear:

julia> using Example
julia> hello("Memento")
2020-04-09 08:42:10 - Example - info - info message
2020-04-09 08:42:10 - Example - warn - warn message
"Hello, Memento"

julia> using Memento
julia> Memento.setlevel!(Example.LOGGER, "debug")
julia> hello("Memento")
2020-04-09 08:43:04 - Example - info - info message
2020-04-09 08:43:04 - Example - warn - warn message
"Hello, Memento"

If in __init()__ I configure the package with debug rather than info, it doesn't work initially but then after resetting the log level by Memento.setlevel!(Example.LOGGER, "debug") the debug statements then work.

Additionally, @test_log does not fail even when no debug log is produced.

Memento.setlevel!(Example.LOGGER, "debug")
@test_log(Example.LOGGER, "debug", r"Hello*", Memento.debug(Example.LOGGER, "Hello"))

Using the approach suggested here: https://discourse.julialang.org/t/using-project-environments-possible-bug/21744, creating the logger const with const logger = Ref{Memento.Logger}() seemed to work better too.

[rofinn]

I think 2 things would help you here.

1. Don't try to configure the logger in the __init__ that's up to the application to sort out. In the above case you're also configuring the "root" logger (default if no name or logger is given) and assigning that to Example.LOGGER which isn't what you want.
2. In the application code you want to recursively set all loggers to debug by passing recursive=true to the config! call:

Memento.config!(
    "debug; fmt="{date} - {name} - {level} - {msg}", colorized=false, recursive=true
)

Alternatively, if you don't want all loggers to emit debug messages then you can do something like:

setlevel!.(Memento.getpath(getlogger("Example")), "info")

That being said, this issue did inadvertently identify a separate problem when registering a logger without registering the parent in an __init__ function (e.g., Main.Example if you define the module in the REPL).

[mmiller-max]

Thanks for getting back to me.

There were two reasons I was setting the config in the __init__. Firstly I want to set a default configuration that the package uses, rather than having to specify one at the application level, and secondly I got duplicate output messages (see code below).

For the first issue, where would you recommend setting a default config? For the second, is this related to what you mentioned about not resisting the parent, or is there something else going on?

using Memento

const LOGGER  = getlogger(@__MODULE__)

function __init__()
    Memento.register(LOGGER)
end

"""
    hello(who::String)

Return "Hello, `who`".
"""
function hello(who::String)
    Memento.debug(LOGGER, "debug message")
    Memento.info(LOGGER, "info message")
    Memento.warn(LOGGER, "warn message")
    "Hello, $who"
end

julia> using Example
julia> hello("Memento")
[info | Example]: info message
[warn | Example]: warn message
"Hello, Memento"

julia> using Memento
julia> Memento.config!(getlogger(Example), "info"; fmt="{date} - {name} - {level} - {msg}", colorized=false, recursive=true)
julia> hello("Memento")
julia> hello("Memento")2020-04-09 15:03:16 - Example - info - info message
[info | Example]: info message
2020-04-09 15:03:16 - Example - warn - warn message
[warn | Example]: warn message
"Hello, Memento"

I guess I'm expecting the root logger to be turned off by default, but this is not the case.

[rofinn]

I'll just address these in order.

1. Can you give a better explanation of why you want to configure a logger in the package? I've seen some folks include a configure function which will setup the global logging for use on the REPL, but that isn't generally how Memento is intended to be used. The design of Memento is aimed at having package developers specifying what counts as debug, info, notice, etc in relation to the local code. However, it's expected that end scripts/applications should be able to configure where those logs go and how they're formatted to best analyze them. This general separation of package and application logging configuration has proven useful in our production systems where we need to quickly modify the configuration of hundreds of nested loggers without touch the packages that are logging.

2. The reason you're seeing duplicate messages is because Memento.config!(getlogger(Example), "info"; fmt="{date} - {name} - {level} - {msg}", colorized=false, recursive=true) is configuring the "Example" logger with its own default handler (which means your logger and the root logger are writing differently formatted messages to stdout. This can be useful if you have automated scripts that filter log output based on the log formatting used.

I guess I'm expecting the root logger to be turned off by default, but this is not the case.

That's correct. Having the root logger configured by default with info logging seemed like the quickest way to get folks up and running. In our systems, most package level loggers aren't explicitly configured and we just use Memento.config!(::Logger, ...), setlevel!.(Memento.getpath(::Logger)), and push!(::Logger, ::Handler) as needed.

[mmiller-max]

1. I would like a default configuration to be set in the package, rather than only ever setting it inside the package. Having a default configuration allows the package to generate useful logs before any configuration by an application/whatever is using the package. Additionally I'm unlikely to have hundreds of nested loggers, rather I'm using the Julia package via PyCall as part of a larger Python project. Therefore configuring it once inside the package will currently be sufficient for my needs, although I appreciate the flexibility offered by enabling changes outside of the package and may use that in the future.
2. Given that I only want one set of logs coming out of this package, is it better to just use the root logger (somehow) or to use the package logger and set the level of the root logger to a higher level than the package uses? Is there a better way to "turn off" the root logger?

Also, will configuring the logger in__init__ cause problems or is it just something that isn't normally done?

[rofinn]

Also, will configuring the logger in __init__ cause problems or is it just something that isn't normally done?

Mostly, it's just something that isn't recommended because you're changing the global logging state when loading the package which can be confusing for end users of the package. If only you intend to use this package then it should be fine...

Given that I only want one set of logs coming out of this package, is it better to just use the root logger (somehow) or to use the package logger and set the level of the root logger to a higher level than the package uses? Is there a better way to "turn off" the root logger?

I suppose if I didn't intend for anyone other than myself to use the library, outside of the PyCall situation described above, then I'd probably just opt to use the root logger. Just change your getlogger(@__MODULE__) call to getlogger(). If you'd rather use your own logger then just set the root logger level higher (e.g., setlevel!(getlogger(), "critical") which will prevent any debug, info, warn or error message from getting logged from it.

[mmiller-max]

Ok that works as a solution for now, thanks.

Does the package level logger have to initialise the root level logger at the same time? It seems to me that ideally it wouldn't have any effect on the root at all - that the root stays not configured if it wasn't configured before loading the package. Currently the global logging state is changed by loading the package if the root logger is not configured.

A way around this, if it's not possible to have a package logger without a root logger, would be to be able to check whether the root logger was configured or not, and leave it if it is configured or set the level higher (as per your comment) if it wasn't.

This may go against how you are intending it to be used, but I think it would still allow your processes to work of everything being configured by the application.

[rofinn]

Does the package level logger have to initialise the root level logger at the same time? It seems to me that ideally it wouldn't have any effect on the root at all - that the root stays not configured if it wasn't configured before loading the package. Currently the global logging state is changed by loading the package if the root logger is not configured.

The issue is that the root logger will always be configured by default when loading Memento. This is intentionally done to mimic the base Julia behaviour and not require users to run Memento.config("info") on the REPL. Since your use case is a bit different you will be required to modify the root logger. That being said, I'd strongly recommend not doing this configuration at package load time, but rather making an Example.configure function that globally sets logging the way you like. We've done that for some of our application level logic and it works pretty well. It also makes it easier to test and debug logging configuration issues.

A way around this, if it's not possible to have a package logger without a root logger, would be to be able to check whether the root logger was configured or not, and leave it if it is configured or set the level higher (as per your comment) if it wasn't.

This wouldn't be helpful because the root logger is always configured as mentioned above. Memento has no way of distinguishing the default configuration from any other state... and that's probably for the best. Again, I think an explicit and documented configure function for your application is what you want. If you're using PyCall then this would really just be 1 extra function call into your julia code.

[mmiller-max]

Ok great, that makes sense, thanks.