Instrumenting a module with logging

[dpo]

How do you suggest one instrument a module with logging? In the situation I have in mind, functions exported by the module call logging macros, but logging is turned off by default. Users should be able to enable logging in their own scripts if they want to. Something in the vein of

module SomeModule

export some_function;

using Logging
@Logging.configure(level=OFF)

function some_function()
  @debug("Run for cover!")
end
end

In the user's script,

using SomeModule
using Logging
my_logger = Logger("MyLogger")
Logging.configure(my_logger, level=DEBUG)
some_function()

I can't seem to find the intended syntax to achieve this.

[kmsquire]

Unfortunately, this is an intrinsic limitation of the logging macros right now: the macro definitions that are used are the ones that are available at parse time, which happens when you load the module. Calling @Logging.configure redefines the macros, but Julia doesn't recompile anything else when this happens.

For uses where you want the user to be able to redefine the logging level, you're probably going to need to use debug functions instead. So, for your example, this would be:

module SomeModule

export some_function;

using Logging
Logging.configure(level=OFF)

function some_function()
  debug("Run for cover!")
end
end

and

using SomeModule
using Logging
Logging.configure(level=DEBUG) # The default logger is the one being used in SomeModule
some_function()

[dpo]

Thanks @kmsquire. That makes sense, and now I understand your README better. I have to say though that that behavior is a bit misleading because the macros take a logger as first argument, and the log level is stored inside the logger. So as a user I expected that changing that level should have an effect.

[kmsquire]

Do you have a suggestion as to how the README might be clearer about this point?

In some ways, this is a limitation in Julia herself. For example, if you redefine a function that has been used inside of another function, the previous version is still called:

julia> f() = "hi"
f (generic function with 1 method)

julia> g() = f()
g (generic function with 1 method)

julia> g()
"hi"

julia> f() = "bye"
f (generic function with 1 method)

julia> f()
"bye"

julia> g()
"hi"

This is because g() was already compiled with the earlier version of the function, and Julia doesn't keep track of the fact that it calls f() and that f() was redefined. Really, the same thing is happening here: setting the log level actually redefines the logging macros, but any previously seen uses still use the old definitions. New uses will use the new definitions, though.

So I agree that it's less than ideal, but there's not much I can do about it until Julia starts keeping track of function dependencies and invalidating/recompiling functions when the functions and macros they call are redefined.

[sebastiang]

I've been looking at adding logging to my modules and wonder about this as well. The more common pattern I've seen is that the logging level is queried on each evaluation. What a macro is great for is effectively inserting the if statement so that any potentially expensive message construction can be avoided if the log level is not high enough. Building strings with embedded $ expressions is a non-trivial cost.

That is especially important if you want structured log messages which are increasingly supported by logging back-ends. For instance, you might want to say this

info("parsing dataset", Dict(:size => 21mb, :filename => "bob.txt", :format => :csv))

And a logger might add some additional detail to it (The https://github.com/forio/Lumberjack.jl package does this nicely, though with some gimmicky names)

The problem with calling this as a function is that even if your log level is less than info, you still endure the cost of creating that dictionary. A standard solution in a functional language is to wrap that in a lambda, which is only executed when the log level is high enough

info("message", () -> Dict(:a => 5))

But here again, you endure the cost of creating an anonymous function. Some languages make that cheap, Julia at the moment doesn't really. But even so, a macro is even more efficient

@info("message", Dict(:a => 5))

can just be converted into

if loglevel(my_logger) > Logger.info info("message", Dict(:a => 5)) end

and you have the best of both worlds: avoiding object creation overhead but still doing a (fairly cheap) runtime check so that logging levels can be jacked up if necessary without restarting existing code.

I'm curious if this approach has appeal to you?

[kmsquire]

Given the shortcomings of the current approach, I'd say it makes sense and sounds like a good alternative.

(It also might make sense to simply borrow code from Lumberjack, but renaming to something more boring.)

[sebastiang]

I'm also curious if there's some clever way to put a @logged macro around a whole function or expression and have it do something to add or modify logging for the whole thing at once, e.g. automatically adding the function name & line number to the structured dictionary, etc.