Weird MethodError with custom logger

I’m trying to construct a custom logger and getting a weird MethodError. For MWE, I copied SimpleLogger and changed its name to TestLogger.
Here’s the logger code (testlog.jl):

using Logging
using Logging: Info

# TestLogger


"""
    TestLogger(stream=stderr, min_level=Info)
Simplistic logger for logging all messages with level greater than or equal to
`min_level` to `stream`.
"""
struct TestLogger <: AbstractLogger
    stream::IO
    min_level::LogLevel
    message_limits::Dict{Any,Int}
end
TestLogger(stream::IO=stderr, level=Info) = TestLogger(stream, level, Dict{Any,Int}())

shouldlog(logger::TestLogger, level, _module, group, id) =
    get(logger.message_limits, id, 1) > 0

min_enabled_level(logger::TestLogger) = logger.min_level

catch_exceptions(logger::TestLogger) = false

function handle_message(logger::TestLogger, level, message, _module, group, id,
                        filepath, line; maxlog=nothing, kwargs...)
    if maxlog != nothing && maxlog isa Integer
        remaining = get!(logger.message_limits, id, maxlog)
        logger.message_limits[id] = remaining - 1
        remaining > 0 || return
    end
    buf = IOBuffer()
    iob = IOContext(buf, logger.stream)
    levelstr = level == Warn ? "Warning" : string(level)
    msglines = split(chomp(string(message)), '\n')
    println(iob, "┌ ", levelstr, ": ", msglines[1])
    for i in 2:length(msglines)
        println(iob, "│ ", msglines[i])
    end
    for (key, val) in kwargs
        println(iob, "│   ", key, " = ", val)
    end
    println(iob, "└ @ ", something(_module, "nothing"), " ",
            something(filepath, "nothing"), ":", something(line, "nothing"))
    write(logger.stream, take!(buf))
    nothing
end

And if I try to use it:

julia> include("testlog.jl")
handle_message (generic function with 1 method)

julia> global_logger(SimpleLogger())
ConsoleLogger(Base.TTY(Base.Libc.WindowsRawSocket(0x00000000000002b8) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

julia> global_logger(TestLogger())
ERROR: MethodError: no method matching min_enabled_level(::TestLogger)
Closest candidates are:
  min_enabled_level(::Test.TestLogger) at C:\cygwin\home\Administrator\buildbot\worker\package_win64\build\usr\share\julia\stdlib\v1.1\Test\src\logging.jl:34
  min_enabled_level(::ConsoleLogger) at C:\cygwin\home\Administrator\buildbot\worker\package_win64\build\usr\share\julia\stdlib\v1.1\Logging\src\ConsoleLogger.jl:43
  min_enabled_level(::SimpleLogger) at logging.jl:520
  ...
Stacktrace:
 [1] Base.CoreLogging.LogState(::TestLogger) at .\logging.jl:374
 [2] global_logger(::TestLogger) at .\logging.jl:469
 [3] top-level scope at none:0

julia> min_enabled_level(TestLogger())
Info

julia> versioninfo()
Julia Version 1.1.1
Commit 55e36cc308 (2019-05-16 04:10 UTC)
Platform Info:
  OS: Windows (x86_64-w64-mingw32)
  CPU: Intel(R) Core(TM) i7-3632QM CPU @ 2.20GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-6.0.1 (ORCJIT, ivybridge)

The weird is that the code is the same as the SimpleLogger and the errored method exists and works if I call it on it’s own.
Is this a bug or am I missing something? Or it has changed from v1.1.1 to #master? (I didn’t checked latter yet.)

Base.CoreLogging.min_enabled_level(logger::TestLogger) = logger.min_level

That seems to work…

julia> global_logger(TestLogger())
ConsoleLogger(Base.TTY(RawFD(0x0000001a) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}())
1 Like

Thank you! I should have paid more attention to te error message.

The fact that these methods come from CoreLogging is an implementation detail which you shouldn’t really depend on. It’s better if you do the following instead:

Logging.min_enabled_level(logger::TestLogger) = logger.min_level

@cserteGT3 to explain a bit more, this isn’t specific to Logging, but rather a misunderstanding about how you extend methods. If you don’t prefix a new method with the originating module of the function (or explicitly import the function) you create an entirely new function with a separate method table rather than extending the existing function.

This goes for shouldlog, catch_exceptions, etc: you need to prefix those with Logging. or they won’t be added to the proper method table and won’t get called properly by the logging system.

4 Likes

Are you sure that works? That is what I tried first, and it didn’t seem to take affect. I ended up having to read the code around global_logger to see that min_enabled_level was defined in Base.CoreLogging.

Sure, the following works for me:

using Logging
using Logging: Info, Warn

"""
    TestLogger(stream=stderr, min_level=Info)
Simplistic logger for logging all messages with level greater than or equal to
`min_level` to `stream`.
"""
struct TestLogger <: AbstractLogger
    stream::IO
    min_level::LogLevel
    message_limits::Dict{Any,Int}
end
TestLogger(stream::IO=stderr, level=Info) = TestLogger(stream, level, Dict{Any,Int}())

Logging.shouldlog(logger::TestLogger, level, _module, group, id) =
    get(logger.message_limits, id, 1) > 0

Logging.min_enabled_level(logger::TestLogger) = logger.min_level

Logging.catch_exceptions(logger::TestLogger) = false

function Logging.handle_message(logger::TestLogger, level, message, _module, group, id,
                                filepath, line; maxlog=nothing, kwargs...)
    if maxlog != nothing && maxlog isa Integer
        remaining = get!(logger.message_limits, id, maxlog)
        logger.message_limits[id] = remaining - 1
        remaining > 0 || return
    end
    buf = IOBuffer()
    iob = IOContext(buf, logger.stream)
    levelstr = level == Warn ? "Warning" : string(level)
    msglines = split(chomp(string(message)), '\n')
    println(iob, "┌ ", levelstr, ": ", msglines[1])
    for i in 2:length(msglines)
        println(iob, "│ ", msglines[i])
    end
    for (key, val) in kwargs
        println(iob, "│   ", key, " = ", val)
    end
    println(iob, "└ @ ", something(_module, "nothing"), " ",
            something(filepath, "nothing"), ":", something(line, "nothing"))
    write(logger.stream, take!(buf))
    nothing
end

:expressionless: I don’t understand…it’s working now…I swear it wasn’t before…probably a disconnect between the head and the keyboard…sorry.

No problem! If you do find the need to mention CoreLogging in your own code, I think that’s a bug in the stdlib. Actually I see that tab completion is broken for the symbols from Logging; I’ll try to fix that.

Tab completion with Logging should be fixed by https://github.com/JuliaLang/julia/pull/32473

2 Likes

Thank you for the explanation! And also for the fix of the tab completion. I didn’t understand why it’s not working.

1 Like