ConsoleLogger for more fully featured log printing

[c42f]

Here I've taken SimpleLogger, copied it into the logging module, and started on some formatting features which will make it a lot nicer to use. I've also made it the default instead of SimpleLogger which we might consider making even simpler.

Primarily, the printing of key value pairs has been beefed up so that large data structures are summarized with the :limit=>true IOContext setting (may be disabled with a setting), and exceptions are now printed using showerror including a backtrace if it's supplied or inferred from the contents of catch_backtrace().

Formatting of exceptions:

Show limiting:

I've also incorporated the right justification of metadata to get this out of the way, and removed the Info and Debug prefix by default, but with a setting to control this. The current default style:

@fredrikekre

[fredrikekre]

Great! One thing that I wanted to do also is to remove the "exception = " prefix, which IMO looks a bit funny. I think it would look nicer with something like the following:

julia> @info "An error while creating the log event" sqrt(-1)
┌ Error: Exception while generating log record in module Main at REPL[1]:1
│   DomainError with -1.0:
    sqrt will only return a complex result if called with a complex argument. Try sqrt(Complex(x)).
└ @ Main REPL[1]:1

[KristofferC]

Perhaps turn off the line info by default?

Also, why are we printing Error: .... Error @? Seems a waste to print Error twice.

[StefanKarpinski]

I'd prefer to keep the Info and Debug prefixes for clarity. Otherwise looks lovely!

[yurivish]

[Edit: moving to another issue...]

[KristofferC]

The formatting of stacktraces is very non related to this PR here. Please open a new issue for that discussion.

[alyst]

Is it guaranteed that msglines has at least one element? (split("") gives an empty array in 0.6)

[alyst]

If length(msglines) == 0 and length(kwargs) == 1, kwarg would not be printed.

[c42f]

True, this is also a bug in SimpleLogger.

[c42f]

Actually no - split("", '\n') gives an array of length 1, so this is actually fine. I'll add a corresponding test case.

[alyst]

For consistency with single line mode, locationstr could be printed at the last message/kwarg line if it fits.

[c42f]

That would be nice. It does complicate the implementation significantly.

[c42f]

I think I'll punt on this for now. Getting right justification correct in general seems to involve removing ANSI escape sequences from the formatted values to determine the text width of the line prefix. It really seems somewhat messy.

[c42f]

One thing that I wanted to do also is to remove the "exception = " prefix

Yes there's a bit of tension here between having general key value pairs and the specific, very useful case of transporting an exception as context for a message. I'm not sure what to do about that; it seems a little less than ideal to give no indication of the key. But it also seems redundant and noisy to have the exception = prefix in there. It would be good to encourage people to use exception as the standard key for passing exceptions for consistency, so having it do something useful and visible in the printing would be nice ;-)

[KristofferC]

The same backtrace filtering as the REPL does should likely be done here as well.

[fredrikekre]

it seems a little less than ideal to give no indication of the key

But in the case failure when generating the message the key exception is not something the user has defined, its just an internal thing, so thats why I don't like the printing of it, it looks like I had a variable called exception in my code.

[KristofferC]

Piggybacking on the key = value printing, when no such thing existed in the user code indeed seems confusing.

It is a big difference between an exception getting thrown when creating the logging message and just capturing an exception with the key = value syntax.

[c42f]

It is a big difference between an exception getting thrown when creating the logging message and just capturing an exception with the key = value syntax.

I think we should fix this by setting the group metadata entry to :logging_failure or some such key. This way messages resulting from failed logging will be directly and simply distinguishable by checking the group. For example, it will be straightforward to filter and find all instances of failed logging, straightforward to display them in a unique way, etc.

But I think worrying about this is a bit of a distraction: these types of messages should not be something you'll see often, and I'd like to focus this PR on getting the formatting as readable as possible in the common case. For that, I think markdown based formatting of the log message is probably the next thing to tackle (in addition to cleaning up various issues people have pointed out above).

[c42f]

it looks like I had a variable called exception in my code

The underlying issue is there's currently no distinction between keys which have special meaning to the system (currently maxlog, exception, and probably progress in the near future) from any other variable the user may attach. For now I thought that imposing the least structure was best, but there's a range of syntactic options or naming conventions we could adopt. Simplest would probably be to prefix all "special" log keys with an underscore. So far I just punted on solving this problem.

[c42f]

Ok, I think I've got a much cleaner implementation of metadata printing: there's now a meta_formatter which can be passed on construction of ConsoleLogger which returns a prefix and suffix of metadata to be added to the message. By default the prefix is $level: for all levels, and the suffix is @ $module $file:$line. But this is now completely customizable which I think also addresses #25106 in a reasonably nice way.

Latest default format:

Regarding the reporting of exceptions generated within the system, I've modified the group to :logevent_error for those cases which should allow them to be cleanly distinguished by any installed logger.

I think this is probably useful enough to merge now. Further changes like markdown handling and more sophisticated key value pair printing can come later.

[KristofferC]

Looks very nice!

[c42f]

CI failures look unrelated - freebsd failed when cloning a git repo, win32 failed when building deps.

[iblislin]

well, all CI failed on master:
(https://freebsdci.julialang.org/#/builders/1/builds/6159)

[c42f]

Ok. What. That's extremely bad, but also confusing given that CI succeeded on Travis, circleci, appveyor (win64). I'm looking into it immediately.

[c42f]

Ah, I'm not going crazy. This was a clash with changes introduced by #25289 which was merged after the tests were run.

[ararslan]

Why was right justification included? It looks messy and it's hard to visually match info to line numbers when the terminal is set to wide.

[fredrikekre]

[c42f]

It looks messy

So does the option of having the metadata mixed with the messages. If you want to see the message 90% of the time and the metadata 10% of the time it's better to put it out of the way where it's not distracting.

We can add an option for the maximum right justification of the metadata - set it to 80 columns or something by default.

[ararslan]

Can we just make right justification opt-in?

[c42f]

The design goal I'm trying to follow for ConsoleLogger is to make the default printing a really good debugging tool for the average user and package author at the REPL. So whatever it takes to make this happen is what we should do IMO.

My guess is the average user wants to see output more like println() (just their message, no decoration). From this point of view we should just remove all the metadata. But on relatively rare occasions it's really helpful so the thought was to put it away somewhere nonintrusive. Unfortunately there's not a lot of options for achieving this in a terminal.

[JeffBezanson]

I don't think we should do this --- there's no way to know whether the result of catch_backtrace corresponds to the given exception. This mechanism is already pretty fragile and can cause quite a bit of confusion, e.g. #19979

[c42f]

One alternative is to have people pass it explicitly everywhere:

try
    # do stuff
catch ex
    @error "Extra information about something bad" exception=ex,catch_backtrace()
end

This might be an acceptable syntax burden?

[c42f]

On further thought, to be completely safe from the problems of #19979 the pattern would have to look like

try
    # do stuff
catch ex
    bt = catch_backtrace()
    @error "Extra information about something bad" exception=ex,bt
end

Hmm. This breaks the general principle that log events should be lazily generated.

[JeffBezanson]

Overall nice improvement! 👍

[c42f]

Aligned but not completely right justified looks like it might be a good compromise. The following is metadata aligned to the 100th column, right justified:

[Sacha0]

As a counterpoint, right justification strikes me as cleaner. (I tend to vertically split terminal windows on wide screens, making the separation a non-issue.) Best!

[c42f]

@Sacha0 - interesting, this is how I use my terminals as well.

Another option (suggested on slack) is to use something other than spaces as padding. Here's two examples with either full width or aligned to 100 columns.

[alyst]

Some editors/terminals highlight the line under cursor. konsole implements triple click to select the whole line, gnome terminal has the similar thing.
There's also good-old scrolling to the top/bottom edge of the screen.
So right-justification is not fatal even for the wide screens.

Another option (suggested on slack) is to use something other than spaces as padding.

Solid lines look a little bit too intrusive.
Maybe something like . . . . as in the old movies? :)
Although I'm not sure it should be the default option.

[c42f]

Maybe something like . . . . as in the old movies?

I tried a lot of different variants of this with various characters. It's a little more light weight, but not substantially different.

[Sacha0]

I find the horizontal lines quite distracting. Best!

[StefanKarpinski]

I really think the old behavior of printing the @ Module file:line info right after the message in single-line and right below the message in multiline messages was less problematic. Perhaps that should just be the default be there can be knobs to configure this as people prefer?

[StefanKarpinski]

Also, I would add that reviewing these changes has been made rather difficult by the fact that there are major functional changes mixed in with aesthetic changes. I'm all on board with adding the ConsoleLogger here but aspect of the previous incarnation of the output format were preferable.

[c42f]

Sorry about that, this could have been a bit better factored in a couple of places. The original intention was that this be entirely aesthetic changes. Jeff's catch_backtrace() objection is completely reasonable but more a flaw in the original logging PR: it was the documented intent of the exception keyword. Here I thought I was just making use of that existing assumption.