Catching @test_warn Errors

[ccoffrin]

This example was tested with the following packages on Julia v0.7,

• PowerModels v0.8.8
• Memento v0.10.0
• TestPkg v0.0.0 #master git@github.com:ccoffrin/TestPkg.git

The following code works as expected,

module ModB
    using PowerModels
    using Memento

    const PMs = PowerModels

    const LOGGER = getlogger(PowerModels)

    function danger()
        warn(LOGGER, "ModB warning")
    end

    function danger(expr::AbstractString)
        warn(LOGGER, "ModB warning \"$expr\"")
    end
end

using Test; using PowerModels; using Memento
TESTLOG = getlogger(PowerModels)

ModB.danger()

@test_warn(TESTLOG, "", ModB.danger())
@test_warn(TESTLOG, "ModB warning", ModB.danger())

Has the output,

julia> ModB.danger()
[warn | PowerModels]: ModB warning

julia> @test_warn(TESTLOG, "", ModB.danger())

julia> @test_warn(TESTLOG, "ModB warning", ModB.danger())

However, if I take the same code and put it in a package (see, TestPkg.jl) then the warnings stop being captured by @test_warn. For example,

using TestPkg

using Memento; using PowerModels; using Test
TESTLOG = getlogger(PowerModels)

TestPkg.danger()

@test_warn(TESTLOG, "", TestPkg.danger())
@test_warn(TESTLOG, "TestPkg warning", TestPkg.danger())

results in the following,

julia> TestPkg.danger()
[warn | PowerModels]: TestPkg warning

julia> @test_warn(TESTLOG, "", TestPkg.danger())
[warn | PowerModels]: TestPkg warning
Test Failed at /Users/carleton/.julia/packages/Memento/QMKyB/src/memento_test.jl:35
  Expression: handler.found[1] == $(Expr(:escape, "warn"))
   Evaluated: "" == "warn"
ERROR: There was an error during testing

julia> @test_warn(TESTLOG, "TestPkg warning", TestPkg.danger())
[warn | PowerModels]: TestPkg warning
Test Failed at /Users/carleton/.julia/packages/Memento/QMKyB/src/memento_test.jl:35
  Expression: handler.found[1] == $(Expr(:escape, "warn"))
   Evaluated: "" == "warn"
ERROR: There was an error during testing

[rofinn]

What happens if you add __init__() = Memento.register(LOGGER) to your TestPkg? My guess is that TestPkg is getting precompiled and LOGGER isn't getting registered at runtime.

[ccoffrin]

It looks like this fixes the @test_warn issue, but it seems to mess something else up. After applying this fix if I do,

 setlevel!(getlogger(PowerModels), "error")

It will impact the messages generated by TestPkg but not those generated by PowerModels.

[rofinn]

Oh, sorry, I didn't notice that LOGGER was the PowerModels logger rather than a TestPkg logger. So this is still related to precompilation. In your original case, LOGGER is using a compiled version of the PowerModels logger that isn't configurable at runtime. Memento.register is designed to make package loggers available for configuration at runtime, but in your case the Memento.register of the PowerModels logger in TestPkg is overriding any registration that might have happened in the PowerModels.__init__ function. As a result, your configuration of the newly registered logger isn't propagating back to PowerModels. Memento should avoid overwriting registered loggers at runtime, but for now I'd recommend doing something like:

function __init__()
    LOGGER = getlogger("PowerModels")
end

So we're just overwriting TestPkg.LOGGER at runtime to match the getlogger("PowerModels") logger that's available at runtime.

[ccoffrin]

After adding global to the init variable, this seems to be working. Thanks!

[ccoffrin]

Close this issue as you prefer.

[rofinn]

Alright, I'll make a separate issue to change the Memento.register behaviour. Do you feel like this use case is common enough to mention it in the docs?

[ccoffrin]

I think an example of how to piggy back on another packages log in the docs would be great.