Creating a custom log message categorie

Hello,
I am using the default Logger of Julia, and in the documentation it is mentioned that you can create custom log messages.

I could not find out how, though.

This works:

using Logging
logger = ConsoleLogger(stdout, Logging.Info) # Warn or Info or Debug
global_logger(logger)

@info ("Running script test_gen_query2.jl...")

Now I would like to do:

using Logging
logger = ConsoleLogger(stdout, Logging.Trace) # Warn or Info or Debug
global_logger(logger)

@trace ("Special trace message ...")

And how can I set the level of my custom message?

It should be between warn and info messages. If logging at “Trace” level @info messages should not be logged.

You’re looking for @logmsg. If you want to create a new loglevel between info and warn, you need to create one with the appropriate level via LogLevel(level). I don’t know the levels of info and warn off the top of my head, but I remember there being space between them for precisely this usecase.

It’s all only semi well documented since at the moment the Logging stdlib just reexports base stuff.

EDIT:

Found it:

I am trying your suggestion, but it doesn’t work yet:

using Logging

const Trace          = LogLevel(500)

macro  trace(exs...) logmsg_code((@_sourceinfo)..., :Trace,  exs...) end

function show(io::IO, level::LogLevel)
    if     level == BelowMinLevel  print(io, "BelowMinLevel")
    elseif level == Debug          print(io, "Debug")
    elseif level == Info           print(io, "Info")
    elseif level == Trace          print(io, "Trace")    
    elseif level == Warn           print(io, "Warn")
    elseif level == Error          print(io, "Error")
    elseif level == AboveMaxLevel  print(io, "AboveMaxLevel")
    else                           print(io, "LogLevel($(level.level))")
    end
end

logger = ConsoleLogger(stdout, Logging.Info) # Warn or Info or Debug
global_logger(logger)

@trace "A trace message ..."

I get the error message:

ERROR: LoadError: LoadError: UndefVarError: @_sourceinfo not defined
Stacktrace:
 [1] top-level scope
 [2] include at ./boot.jl:328 [inlined]
 [3] include_relative(::Module, ::String) at ./loading.jl:1094
 [4] include(::Module, ::String) at ./Base.jl:31
 [5] include(::String) at ./client.jl:431
 [6] top-level scope at REPL[1]:1
in expression starting at /home/ufechner/n4Server/local_tests/test_gen_query2.jl:9
in expression starting at /home/ufechner/n4Server/local_tests/test_gen_query2.jl:9

julia> 

Any idea?

Well, this doesn’t help.
I tried the following:

using Logging

import Base: show

const Trace          = LogLevel(500)

macro _sourceinfo()
    esc(quote
        (__module__,
         __source__.file === nothing ? "?" : String(__source__.file),
         __source__.line)
    end)
end

# macro  trace(exs...) logmsg_code((@_sourceinfo)..., :Trace,  exs...) end

function show(io::IO, level::LogLevel)
    if level == Logging.Debug          print(io, "Debug")
    elseif level == Logging.Info           print(io, "Info")
    elseif level == Logging.Trace          print(io, "Trace")    
    elseif level == Logging.Warn           print(io, "Warn")
    elseif level == Logging.Error          print(io, "Error")
    else                           print(io, "LogLevel($(level.level))")
    end
end

logger = ConsoleLogger(stdout, Logging.Info) # Warn or Info or Debug
global_logger(logger)

@logmsg Trace "A trace message ..."

This results in the error message:

Exception handling log message: UndefVarError(:Trace)
  module=Main  file=/home/ufechner/n4Server/local_tests/test_gen_query2.jl  line=35
  Second exception: UndefVarError(:Trace)
using Logging

const Trace          = LogLevel(500)

macro _sourceinfo()
    esc(quote
        (__module__,
         __source__.file === nothing ? "?" : String(__source__.file),
         __source__.line)
    end)
end

macro  trace(exs...) logmsg_code((@_sourceinfo)..., :Trace,  exs...) end

function show(io::IO, level::LogLevel)
    if     level == BelowMinLevel  print(io, "BelowMinLevel")
    elseif level == Debug          print(io, "Debug")
    elseif level == Info           print(io, "Info")
    elseif level == Trace          print(io, "Trace")    
    elseif level == Warn           print(io, "Warn")
    elseif level == Error          print(io, "Error")
    elseif level == AboveMaxLevel  print(io, "AboveMaxLevel")
    else                           print(io, "LogLevel($(level.level))")
    end
end

logger = ConsoleLogger(stdout, Logging.Info) # Warn or Info or Debug
global_logger(logger)

@logmsg Trace "A trace message ..."
[ LogLevel(500): A trace message ...

Well, while your code doesn’t work you gave me a good hint. The following works:

function show(io::IO, level::LogLevel)
    if level == Logging.Debug          print(io, "Debug")
    elseif level == Logging.Info           print(io, "Info")
    elseif level == Trace                  print(io, "Trace")    
    elseif level == Logging.Warn           print(io, "Warn")
    elseif level == Logging.Error          print(io, "Error")
    else                           print(io, "LogLevel($(level.level))")
    end
end

julia> versioninfo()
Julia Version 1.2.0
Commit c6da87ff4b (2019-08-20 00:03 UTC)
Platform Info:
  OS: Linux (x86_64-pc-linux-gnu)
  CPU: Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-6.0.1 (ORCJIT, skylake)

Well, you do not have the line:

import Base: show

Perhaps that makes the difference. But I have another issue:

The trace macro doesn’t work yet:

using Logging

import Base: show

const Trace          = LogLevel(500)

macro _sourceinfo()
    esc(quote
        (__module__,
         __source__.file === nothing ? "?" : String(__source__.file),
         __source__.line)
    end)
end

macro  trace(exs...) logmsg_code((@_sourceinfo)..., :Trace,  exs...) end

function show(io::IO, level::LogLevel)
    if level == Logging.Debug          print(io, "Debug")
    elseif level == Logging.Info           print(io, "Info")
    elseif level == Trace                  print(io, "Trace")    
    elseif level == Logging.Warn           print(io, "Warn")
    elseif level == Logging.Error          print(io, "Error")
    else                           print(io, "LogLevel($(level.level))")
    end
end

logger = ConsoleLogger(stdout, Logging.Info) # Warn or Info or Debug
global_logger(logger)

@logmsg Trace "A trace message ..."
@trace "Even better..."

Error message:

[ Trace: A trace message ...
ERROR: LoadError: LoadError: UndefVarError: logmsg_code not defined

Ok, I could copy and past the whole CoreLogging module, but why am I not able to import any function from this module?

So my current impression is that it is not possible to create and use custom log messages in a clean way with the standard log module of Julia. So I might create an issue for that.

Sorry I couldn’t get back to you yesterday. This is what I had in mind:

julia> @logmsg Trace "This is the way it should be done"
[ Trace: This is the way it should be done

For the macro, I didn’t think I’d need so many things from CoreLogging for it to work:

using Logging

const Trace = LogLevel(500)

const _min_enabled_level = Base.CoreLogging._min_enabled_level
const current_logger_for_env = Base.CoreLogging.current_logger_for_env
const shouldlog = Base.CoreLogging.shouldlog
const handle_message = Base.CoreLogging.handle_message
const logging_error = Base.CoreLogging.logging_error

macro trace(exs...) Base.CoreLogging.logmsg_code((Base.CoreLogging.@_sourceinfo)..., :Trace, exs...) end

function Base.show(io::IO, level::LogLevel)
    if     level == Logging.BelowMinLevel  print(io, "BelowMinLevel")
    elseif level == Logging.Debug          print(io, "Debug")
    elseif level == Logging.Info           print(io, "Info")
    elseif level == Logging.Warn           print(io, "Warn")
    elseif level == Logging.Error          print(io, "Error")
    elseif level == Logging.AboveMaxLevel  print(io, "AboveMaxLevel")
    elseif level == Trace                  print(io, "Trace")
    else                           print(io, "LogLevel($(level.level))")
    end
end

Do note that this is type piracy and only works once since you’re overwriting Base.show, so it’s not really suited for a package or something like that. Also, since CoreLogging is technically not exported and internal, this might change at any time and shouldn’t be relied upon.

Here be dragons.

1 Like

One more thing: this obviously won’t work for other custom loggers, since this is basically hard coding the macro contents to those of Base.CoreLogging.

Yes, this works, but not well in modules and it is also not clear if it will work in future versions of Julia. So I created an issue:

If you don’t care about pretty printing then it’s fairly easy to do this without digging into any internals:

julia> using Logging

julia> Trace = LogLevel(500)
LogLevel(500)

julia> macro trace(exprs...)
           quote
               @logmsg Trace $(map(x -> esc(x), exprs)...)
           end
       end
@trace (macro with 1 method)

julia> @trace "asd"
[ LogLevel(500): asd
1 Like

Good question, I’ve been thinking about this problem on and off for a year now. I added my assessment of the design problem and a possible solution to the github issue (https://github.com/JuliaLang/julia/issues/33418#issuecomment-536823903)

So, we’re considering improving the support for custom log levels over on the github issue. Conceptually I am thinking of log levels as a category which can also be mapped to a default (integer) importance level, and which have an semantic which can be agreed on independently of which module they are used in.

But perhaps this is not the best model! So I thought I’d also cross post back here in an attempt to better understand what people really want from custom log levels. If you have some use cases in mind please do post them here or on the github issue.

How do you think custom levels would help to better understand your application?

Why not just define a new log level type? Since logging code mostly do duck typing, it works with a few methods and there is no need for type-piracy. The downside may be that some third-party loggers may explicitly expect LogLevel.

using Logging

struct MyLogLevel
    level::Int32
end

const Trace = MyLogLevel(-10_000)

Base.isless(a::MyLogLevel, b::LogLevel) = isless(a.level, b.level)
Base.isless(a::LogLevel, b::MyLogLevel) = isless(a.level, b.level)
Base.convert(::Type{LogLevel}, level::MyLogLevel) = LogLevel(level.level)
Base.show(io::IO, level::MyLogLevel) =
    if level == Trace
        print(io, "Trace")
    else
        show(io, LogLevel(level))
    end

Logging.disable_logging(Logging.BelowMinLevel)

with_logger(ConsoleLogger(stderr, convert(LogLevel, Trace))) do
    @logmsg Trace "message"
end
2 Likes

Right!

See also the logging tests (honestly not sure how I semi-forgot about this, given that I wrote that code and associated test :grimacing:)

Having said that, I think this could be a lot nicer and certainly more well documented. The fact that you need to define Base.convert(::Type{LogLevel}, l::MyLevel) is kinda weird.

Great! Good to know that this was the intended usecase and my code was not accidentally working.

Also, my definition of show is kind of a lie. It’s certainly not repr-compatible. Maybe it was better to overload print. Specifying something like this in the documentation would be nice. (Or even do everything automatically with something like @enum MyLevel <: LogLevel Trace = -10_000.)

I’ve been using this pattern but it seems to have been broken by type restrictions introduced in Julia 1.6.0. After updating I’m getting errors like the following:

  MethodError: no method matching handle_message(::ConsoleLogger, ::MyLogLevel, ::String, ::Module, ::Symbol, ::Symbol, ::String, ::Int64)
  Closest candidates are:
    handle_message(::Base.CoreLogging.NullLogger, ::Any...; kwargs...) at logging.jl:103
    handle_message(::ConsoleLogger, ::Base.CoreLogging.LogLevel, ::Any, ::Any, ::Any, ::Any, ::Any, ::Any; kwargs...)