RFC: Base logging

[c42f]

Here's the first part of #23712 cleaned up so that it's in a more digestible and less obviously broken form. There's basically two things here:

The core of MicroLogging (src/core.jl), very slightly tweaked.

Most of this arguably needs to be in Base because log messages from the rest of Base will be using the logging macros, and ideally messages from the parser and runtime C code will be dispatched to the logging system (see #23712 for partial implementation of these extensions). We may be able to move a little more of it to stdlib however - I anticipate a stdlib Logging library with more general configuration and logging tools.

Port of all Base logging from the function call style to logging macros

This second part was somewhat mechanical, assisted by a hacked version of Deprecations.jl. This is mostly a straight port, resisting the urge to use the new features in an attempt to avoid bugs (many of these messages are untested, I think.). Some things are edited for consistency:

• Where exceptions were interpolated, they're instead added as keyword arguments: exception=ex
• An attempt has been made to punctuate log messages consistently with the convention from pkg: Short messages start with a capital, but have no period.
• In some places where the log message is generated using logic, the logic is pulled inside the message generation block. (Good practice from a scoping and efficiency point of view.)

TODO

There's still a few things to do (some copied from c42f/MicroLogging.jl#5)

• User manual documentation
• Log testing infrastructure (ie, a replacement or upgrade of test_warn)
• Port all tests which use test_warn over to the new system
• Copy core test code from MicroLogging
• API naming review for AbstractLogger related functions, log level limits, etc. Some of these made more sense when scoped inside a package, but don't so much in Base.
• Deprecate info() and warn().

[KristofferC]

Missing max_log=1?

[c42f]

Good catch. You can tell this is one i hand edited :)

[c42f]

I guess arguably these two should be @error

[ararslan]

Port of all Base logging from the function call style to logging macros

What was wrong with functions?

[c42f]

What was wrong with functions

With macros several very useful things can be done which either aren't possible with functions or impose a syntax burden:

• For efficiency, the message should never be generated until you know there's a decent chance it will survive filtering. With a function based interface this is difficult to do in a lightweight way because the function arguments must be evaluated before being passed to the function. Really the only option in this case is to have the user pass a closure. With a macro based interface the closure can be created behind the scenes, and several layers of protection against doing unnecessary work can be added. See the code here: https://github.com/JuliaLang/julia/pull/24490/files#diff-5973e57dcc6fc4a64951865e1090aa9bR278
• Using macros allows the generation of a unique identifier for each source of log records. For this to be stable (ie, not change as the source code is changed elsewhere in the file) it needs to be based on the message generating Expr which is only accessible via a macro. Why do you need a unique id? Well it allows you to do efficient log throttling (at simplest, limit to showing the message only once), log filtering (eg, you can blacklist a particular message id based on complex criteria. The complex predicate need only be computed once, and from then on you can rely on the id)
• Using macros allows compile time collection and calculation of rich metadata (the Module of the log record source, the file path and line number, the message id and default message group.) The file and line number are only otherwise accessible via a backtrace, the module I'm not sure about, and precomputation of the message group and id obviously isn't available.

[StefanKarpinski]

I need to review this more thoroughly, but from a quick perusal, I really like this.

[c42f]

Great. Here's the deprecation plan for the current logging functions info() warn() and logging():

• info() and warn() can continue to work in 0.7 (though emit a deprecation), and continue to direct their messages to the streams defined by logging(). Then at least, any applications using these three together will continue to work for one release.
• logging() will also emit a deprecation but otherwise do what it does now.
• However, all Base messages will be directed to the new logging infrastructure, so the streams given to logging() won't capture these any more. If anyone really needs the old system to keep working for Base, they can always define a custom Logger which directs the new system to the old one.

[c42f]

As it turns out I'm not really happy with the log testing tools in MicroLogging so this is causing a bit of a delay here while I rethink them. But I think I have a plan - it's just a "small matter of code" to implement it. Rough anticipated syntax and semantics for a tool to replace @test_warn and @test_nowarn:

To test that some code inside foo() calls @info "message" and @warn "ohno" in that order:

@test_logs (Info, "message") (Warn, "ohno") foo()

The idea is that this will be sugar for something like

@test logs_match((Info, "message"), (Warn, "ohno")) do
    foo()
end

Where the logs_match function will capture all log records, then match them against the function arguments in turn using a function which can be extended by the user (perhaps just ismatch() with LogRecord types as the second argument). This design allows the arguments to be something other than the literal Tuples given above, for example:

@test_logs LogPattern(Info, r"Failed at iteration [0-9]+", a=10) foo()

[c42f]

A small question: is it ok to put this note here, or should the parts of util.jl which are deprecated be explicitly moved? It's 200 lines of code or so which is why I left it in place for now.

[c42f]

@StefanKarpinski what's the chance of this making it into 0.7? I'd really like to see the effort I've put into this make it into 1.0. If not, compatibility in the 1.0 cycle technically dictates several more years of logs-as-text which I think would be a real pity when we're on the cusp of something far more powerful.

At the moment I'm trying really hard to push through to the end with this and I'm rather close to making all the tests work - probably a day or two away. But if it's not worth the slog I'll think about giving myself a break!

[ViralBShah]

cc @tanmaykm

[StefanKarpinski]

I say let's go ahead with this!

[ararslan]

We typically avoid underscores like this, so I think it'd be better to call this maxlog.

[c42f]

Yeah ok, let's do that. Updated now.

[StefanKarpinski]

One comment: this is a significant number of new related exports from Base. How about wrapping the new functionality in a Base.Logging module and then exporting them from there? The @info, @warn and @debug names can be exported from Base though. Otherwise this is good.

[JeffBezanson]

Functionality looks great. I'd rather not add 13 exports to Base for this. I think a stdlib psuedo-package would be the way to go here; the code can be in base but you do using Logging to get at the names.

[StefanKarpinski]

Oh yeah, using a stdlib package for the non-basic functionality is even better. Then it can evolve.

[c42f]

Excellent! I'm totally on board with putting as much of this in a stdlib package as possible. What you see here has already had a fair bit of reduction and removal of several features which need more thought. (For instance, you'll see there's no mention of a log record data structure, collection of log records, functions for configuring the current logger, log formatting or filtering, etc.)

The reason it's not reduced further is that it seems important for Base to be able to direct logs to the same system - including the parser and runtime. In fact, these extensions are already implemented for the parser/lowerer over at #23712, and that will be the next much smaller PR once this is merged.

I'll have to think about how to move even more functionality over to a Logging stdlib module. It will probably involve some refactoring - for example LogLevel is mentioned explicitly by the logging macros, but that's not necessarily required. Maybe the key is to have a private interface between Base and Logging where messages can be passed in a uniform way, but leaving us free to evolve the system.

[ararslan]

Another option would be to have Logging be a submodule of Base, i.e. Base.Logging, rather than a stdlib module. That allows Base to use it internally as needed without adding a bunch of exports.

[JeffBezanson]

Refactoring things to actually move code out of Base is fine if it's not too difficult, but that's not even necessary --- Logging can be a "skeleton" stdlib package that literally just imports some names from Base (or from Base.Foo) and exports them.

[c42f]

Thanks Jeff, I think that makes sense. I'm a little hazy on the subtleties though - it seems like there might be several things we'd like. What are we aiming for, primarily? Are we:

1. Advertising that the names in Logging are not part of Base compatibility guarantees. For example, that when upgrading from julia-1.0 to julia-1.1, some parts of the stdlib Logging which come bundled with the julia distribution may be deprecated?
2. Allowing users to do a Pkg update on Logging while keeping the same version of julia. For example, with julia-1.0, should users be able to install a newer Logging than the bundled one?

If we just need (1), I can make a skeleton package for now, and remove most or all of the exports from Base. This seems easy and good. The only hitch is that I'd really like the frontend logging macros available by default - I think it makes sense for people to reach for them in many cases instead of println() or @show. Thoughts?

Regarding point (2) - I haven't looked closely but we seem to be missing some infrastructure for this at the moment. So I'm going to ignore it unless someone says otherwise.

[StefanKarpinski]

The only hitch is that I'd really like the frontend logging macros available by default - I think it makes sense for people to reach for them in many cases instead of println() or @show.

Right, that's why I suggested exporting @info, @warn, @debug and such from Base. So here's my suggestion: define everything in Base but only export these names from Base:

• @debug
• @info
• @warn
• @error

Create a stub Logging package in stdlib and export the rest of the names from it:

• AbstractLogger
• LogLevel
• NullLogger
• @logmsg
• with_logger
• current_logger
• global_logger
• disable_logging
• SimpleLogger

I'm not positive if this is the right split, but my thinking is that the simple logging macros are all that most code need to use basic logging, while the rest are mostly only needed to control logging, or in the case of @logmsg for more advanced logging than most code will need. This API can evolve over time and Base will need to have some code that deals with that, but it should be doable. The basic simple API like @debug won't change much, so that can be stabilized now.

[c42f]

Cool that's exactly the split which makes sense to me. I'll do the export tweaks as soon as I can scrape together a few hours.

[c42f]

Awesome! There's more to do but that's the deprecations out of the way and we can proceed incrementally which will be a lot easier. It's a relief to not be maintaining this on a branch :-)

[fredrikekre]

julia> zeros(rand(3,3))
W- `zeros(a::AbstractArray)` is deprecated, use `fill!(similar(a), 0)` instead. -Warn:Core:julia_internal.h:380
|  caller = jl_call_fptr_internal at julia_internal.h:380 [inlined]
3×3 Array{Float64,2}:
 0.0  0.0  0.0
 0.0  0.0  0.0
 0.0  0.0  0.0

Edit: Nevermind, it's just that the caller look really weird from the REPL. From a function:

julia> foo() = zeros(rand(2,2))
foo (generic function with 1 method)

julia> foo()
W- `zeros(a::AbstractArray)` is deprecated, use `fill!(similar(a), 0)` instead. -Warn:Main:REPL[1]:1
|  caller = foo() at REPL[1]:1
2×2 Array{Float64,2}:
 0.0  0.0
 0.0  0.0

[StefanKarpinski]

Somehow you never really shake out all the bugs until you merge it 😁

[c42f]

Right, I'm waiting in trepidation!

@fredrikekre is this a bug? Ah, I guess it's the jl_call_fptr_internal which is admittedly quite ugly, but as far as I recall only exposing what was there before - I wasn't sure whether to include C frames there, or how best to sanitize the output.

[fredrikekre]

Right, I probably just got scared of the output. Some kind of filtering would be nice for repl usage I guess, the printed internal functions there does not really help

[fredrikekre]

Is it expected that the deprecated methods don't use the new logging interface?

julia> warn("fjdsklfdsjkl")
W- `warn()` is deprecated, use `@warn` instead. -Warn:Core:julia_internal.h:380
|  caller = jl_call_fptr_internal at julia_internal.h:380 [inlined]
WARNING: fjdsklfdsjkl

julia> warn("fjdsklfdsjkl")
WARNING: fjdsklfdsjkl

julia> info("fjksl")
W- `info()` is deprecated, use `@info` instead. -Warn:Core:julia_internal.h:380
|  caller = jl_call_fptr_internal at julia_internal.h:380 [inlined]
INFO: fjksl

julia> info("fjksl")
INFO: fjksl

[fredrikekre]

Also, it would be nice if the logging string was printed in color too, as previously. I.e. "hello" here would print in yellow:

[KristofferC]

Filtering C functions (like the back trace printer seems like a good idea).

[StefanKarpinski]

Is it expected that the deprecated methods don't use the new logging interface?

I would expect them to continue to work the way they previously did.

[fredrikekre]

Is it expected that the deprecated methods don't use the new logging interface?

I would expect them to continue to work the way they previously did.

Right, I confused myself... 😄

[c42f]

Regarding deprecated behavior of warn() - yes this was the intended implementation (see #24490 (comment)). I'm not attached to the detail here, but this seemed like the least breaking option.

Regarding colorization - we could print the entire message in color, but I think if we're not careful we end up with so much color on the screen that it's hard to focus on the parts which matter. I've also got another motive here: I'd like to render the message itself as markdown and this will involve a different competing colorization for parts of the message. This is already done by MicroLogging.InteractiveLogger: https://github.com/c42f/MicroLogging.jl/blob/7f5e280eb0b7fb9334d7ec21eadaae67e4e90697/doc/micrologging_example.png. Even better, I'd like to remove coloriziation entirely from SimpleLogger, and put it into a more featureful logger which lives in stdlib/Logging and is installed by default instead of SimpleLogger.

[c42f]

By the way, I think merging this fixes #13515, #20348, #22043

It also mostly obsoletes #24028