Some logging printing improvements

[fredrikekre]

• use user customizable colors in logging
• nice box drawing chars
• print line info after key value pairs
• always put the line info on its own line for multiline messages
• don't show the loglevel in the location info since it is already printed in the beginning of the message

• use showerror to print exceptions rather than their string representation
  

[fredrikekre]

cc @c42f

[ararslan]

Can we spell out the whole words of "info," "warning," and "error"? I, W, and E is pretty non-descriptive.

[StefanKarpinski]

Agree: I understand why you want a single-letter prefix, but it's a bit cryptic. However, as I understand it, perhaps the plan is to add a ConsoleLogger that makes output more verbose?

[KristofferC]

Having the names short makes the text align nicely and the colors should make it obvious what the intention is.

[ararslan]

You can still get alignment with something like

WARNING: single line message
WARNING:
 │  Multiple
 │  lines
 └ Main:REPL[1]:6

[alyst]

would be nice to have a different color for the location

[StefanKarpinski]

Or this:

WARNING: single line message

WARNING: multiple
 │  lines
 └ Main:REPL[1]:6

[c42f]

Thanks, it's great to have some more people looking at formatting (and no surprise that it's the first thing people want to change :-) ). I like the look of the unicode bracketing.

As for where to put this - I've been trying to avoid features in SimpleLogger; my thought was that we should add a fully featured ConsoleLogger to the Logging stdlib package instead, and install that by default for the REPL instead of SimpleLogger which can be reserved for debugging, and perhaps for tricky situations like maleadt/LLVM.jl#78 (comment). This gives us the option to make ConsoleLogger much prettier and more configurable. For more context about what I've been thinking there, the discussion at #25106 is pretty relevant.

Regarding the prefix being variable width - IMO it's a critical point that the metadata should be nonintrusive and not create additional lines. Otherwise I predict that people will want what they get from println(): just show me my message, stop decorating it! I think the right solution is to simply make the more verbose metadata right justified and appropriately colored. See @KristofferC's concerns at #25106 (comment)

See also how MicroLogging.InteractiveLogger addresses these things - https://github.com/c42f/MicroLogging.jl/blob/7f5e280eb0b7fb9334d7ec21eadaae67e4e90697/doc/micrologging_example.png

How about I create a straw man PR which ports InteractiveLogger as Logging.ConsoleLogger, and we can rip that apart, incorporating what you've got here and additional ideas as desired?

[fredrikekre]

As for where to put this - I've been trying to avoid features in SimpleLogger

TBH I don't see the changes here as features, this is just clearing things up, and just because the SimpleLogger is simple it does not mean the output can't be nice

How about I create a straw man PR which ports InteractiveLogger as Logging.ConsoleLogger, and we can rip that apart, incorporating what you've got here and additional ideas as desired?

That would be nice, perhaps it should be a REPLLogger and live in Base.REPL rather than in the stdlib though, not sure. Also, some documentation for the new logging interface, I feel like I have misunderstood it.

[StefanKarpinski]

perhaps it should be a REPLLogger and live in Base.REPL rather than in the stdlib

Is it really REPL-specific? Don't you want to use the same kind of output if you're running a script in the terminal without a REPL?

[c42f]

I don't think this should be done inside dispatch_message as that will bake in display logic in a way which can't be overridden. Rather, I think it should be part of the logger. See for example https://github.com/JuliaLang/julia/pull/25136/files#diff-f1d5a62767988822d6e6fd5db69f5ea9R79

[c42f]

I've thrown together something over at #25136. It's a bit rough and ready, but can serve as a point of reference if nothing else.

But regardless of that these changes to prettify SimpleLogger seem nice. Using showerror should be done inside SimpleLogger itself.

Sorry about the lack of documentation. I was still working on it when #24490 got merged - it's still on my todo list!

[iamed2]

My suggestions (from #25138):

• use the full log level name, as not everyone has colours at their terminal and the letter is really subtle without colour. I wouldn't consider the log level to be metadata; it's crucial when you're skipping over lots of output to be able to pick out different levels.
• use at in front of the log location to distinguish it from the rest of the message.

I really like the boxed printing!

[c42f]

I really don't like the idea of having INFO at the start of info and debug messages, I think it's terribly visually cluttering and a distinct disadvantage compared to println().

However, it's important that warnings and errors be easy to see. Perhaps we just don't need consistency here between levels, and we can prepend {WARNING,ERROR} but append {INFO,DEBUG} (after all, this is not the one and only true format - it's for maximum readability in the repl).

This also lets us kill off another character in the prefix, and just go with the colored bracketing on the left hand side.

[ararslan]

I disagree, I actually appreciate the INFO: prefix.

[c42f]

What's the function of INFO:? What information does it convey?

[StefanKarpinski]

It tells you that you're seeing in informational log message rather than normal output of your program.

[c42f]

Sure but I think that will be quite adequately conveyed by having the INFO on the right with the other non-message data, and having the bracketing on the left.

[StefanKarpinski]

Ok, well, give it a shot and let's see how it looks!

[c42f]

Indeed! It might just be ugly, we'll see.

[vchuravy]

One Important note is that not everywhere color is enabled and there are also colorblind people, so we shouldn't rely on color to much and without color the single character prefix is less distinct. Having this configurable would be great.

[iamed2]

What's the function of INFO:? What information does it convey?

• I am a new log message
• I am not (and am not part of) an error/warning/etc.
• I am not the result of a print/show/display
• I am an @info message

which are all related and subtly different. I think there are lots of formats that communicate some but not all of these, and it would be nice to have one that communicated all of them.

[StefanKarpinski]

I also think there's a strong case to be made for keeping these log messages simple and uniform. If we want to get more elaborate, we can experiment with that in external loggers and then import features if they work out really well in the future.

[JeffBezanson]

I'll add that the first time I saw I- after getting back from vacation it looked so weird I thought it was a printing bug. I think the single letters are too obscure and user-unfriendly.

[StefanKarpinski]

100% agree. Just print the fully spelled out WARN, DEBUG, INFO and ERROR on all of these at the start of the message. It would be really nice if these all printed full path/to/file.jl:123 locations as well since those are clickable in many terminals to open the file in question. Fancy line drawing art is fine as well but those things are the minimal requirements for this sort of thing.

[fredrikekre]

Seems that the conclusion is to write out the full names as previously. I will rebase and fixup the PR when I get some time over.

[c42f]

I still think this small part here should be reverted - it's in the wrong place because it's not the job of the log dispatch machinery to do formatting. Formatting is the job of the installed Logger. Doing formatting here is also inconsistent with the convention I've followed for exception logging elsewhere in Base.

If you want a replacement, it's quite easy to get equivalent but more general functionality by improving the way we print key value pairs in SimpleLogger when they're Exceptions.

[fredrikekre]

That's what I did at first, but it felt weird to generate part of the message here and part of the message in handle_message. It is also nice not to have special casing inside handle_message based on typeof(val).

[fredrikekre]

Perhaps the full try-catch should me moved to handle_message instead?

[c42f]

In particular - if you want exceptions to be readable, it's the printing of val on this line here which should be beefed up.

[c42f]

Other than the issue with where exception formatting is done, this looks good to me. I think it's appropriate to live without right justification for SimpleLogger - after all, the idea is to keep it simple. The same goes for log level printing I suppose.

[StefanKarpinski]

Should we merge this now and fix the mentioned implementation issue after or wait to tweak that?

[fredrikekre]

After thinking about it a bit more I think that the current implementation is correct; If we get an exception we should generate the full message (i.e. "Exception while generating log record:\n" and append shoerror(err) to that same string) and then try to print that message to the logger stream. I don't understand why we would want to generate the message in two different places.

Also, it is really weird to special case based on the key-value pair. If we special case on the key, (i.e. if key ==:exception) then something like this will not work: @info "my variabel called `exception` has the value" exception, since that will print an error message ("Exception while generating log record:"), and also, we can not use showerror since my variable called exception might not be an Exception.

If we special case on the value (i.e. if isa(val, Exception)) then the same thing happens: ex = ErrorException(); @info "here is my exception" ex will also print something about error when generating the log record.

[c42f]

I think the disconnect here is because you're thinking of log records in terms of what you see (ie, as text), but having them as structured data is much more powerful. For example, consider log filtering and reduction. You might want to filter logs by the exception type they contain - if the exception has already been transformed into text, the logger is limited to some regex matching or some such. If the exception is present as data, you can simply filter the attached exceptions using isa. In general, converting to text early will loose information and impose restrictions on what people can do with their custom loggers.

Elsewhere in Base, I've consistently emitted errors as follows (and as suggested in the logging macro docstring):

@error "Blah" exception=ex

It's very easy to make something readable out of this by having a function fmtvalue() which formats the values in the key value pairs. This is what MicroLogging.InteractiveLogger does:

[c42f]

Also, it is really weird to special case based on the key-value pair

I struggled with this for a while when designing the system. I eventually came to the conclusion that formatting based on the type of the value was the correct thing. For example suppose you have two exceptions to attach to the same @error. No problem, just use @error "blah" exception1=a exception2=b.

If we special case on the value (i.e. if isa(val, Exception)) then the same thing happens ex = ErrorException(); @info "here is my exception" ex will also print something about error when generating the log record.

Sure, and that's correct. I'm not sure what else you could possibly want from this - if you explicitly attach an exception, you should see it, right?

I won't pretend I have all the answers to how formatting should work in all cases here, but the crucial point is that dispatch_message is internal dispatch machinery which AbstractLoggers don't get to opt out of. It should not be making formatting decisions for them.

[KristofferC]

Perhaps add a keyword argument to handle_message that defaults to nothing but contains the exception if one was thrown in the logging.

[c42f]

Perhaps add a keyword argument to handle_message

What's wrong with passing it as a key value pair? Using a plain key value pair simplifies the data model and is consistent with the way users should pass exceptions. (Unless we were to add a special way for them to pass exceptions, but I just don't see that as necessary.)

If we want to distinguish cases where the log generation itself failed, how about flagging this by setting group to something like :logging_error instead? Currently group is used for high level grouping of messages independent of the originating module. For example, all depwarns have group=:depwarn.

[fredrikekre]

Fine, we can call showerror for all key-value pairs where isa(value, Exception) then. What I don't understand then is why the try-catch is in dispatch message, that should also be inside the handle_message function IMO.

[c42f]

we can call showerror for all key-value pairs where isa(value, Exception) then

Thanks, I know I'm being pretty inflexible on what might seem like a small matter, I just feel this is an important matter of consistency for the design as a whole. Please bear with me while I try to get the design out of my head and into some documentation / examples.

What I don't understand then is why the try-catch is in dispatch message, that should also be inside the handle_message function IMO

Good question. The reason for having dispatch_message at all is to protect Loggers from the implementation detail of the message generation closure. At the same time it provides some reasonable default behavior for when message generation or the logger produces an exception.

For example, suppose I've got a long running process which is behaving strangely and needs to be debugged without restarting. So I turn on debug logging to see what's happening, but someone has a buggy @debug (rarely enabled, so rarely fully tested). Without a catch the process will probably just crash which is pretty annoying.

For the message generation closure, if you look at the way it's called you'll see it's somewhat complicated. I think this is a bit ugly and I wanted to avoid making it a public interface. There might be some room for improvement here. For example, if the closure was changed to take no arguments, but to return the message and the key value pairs, perhaps it would be simple enough to defer message generation completely by passing the closure to handle_message.

[fredrikekre]

I understand the try-catch that then prints to STDERR, but I meant the inner try catch (that then retries the same handle_message function), I suggest moving that into handle_message. I will just drop that change in this PR, then we can merge this I think, and I will make a new PR with the error handling change.

[c42f]

There's a reason to have both. Consider someone had written

@info "Current value" a÷b

This is fine until the unexpected happens and b=0, in which case a DivideError is generated. This error should be reported through the logging system rather than STDERR if possible - this is the second call to handle_message in the inner try block. Note that this time we send very different information.

If this call to handle_message also fails, it could be an error in the logger, so we give up and print to STDERR as a last resort. This last resort is not ideal and may result in the message going unnoticed (for example, suppose the currently installed logger is writing over the network to a log server). It's better than nothing, however.

[StefanKarpinski]

Please bear with me while I try to get the design out of my head and into some documentation / examples.

This is a very familiar problem... Good luck!

[StefanKarpinski]

This last resort is not ideal and may result in the message going unnoticed

Could we have a last resort logging function that does something really simple like log "something went wrong with the logging infrastructure" and make sure that we test that this works somehow?

[c42f]

Could we have a last resort logging function that does something really simple like log "something went wrong with the logging infrastructure" and make sure that we test that this works somehow?

Well, we could have an extra layer of try-catch, though that seems a little excessive? Or we could be more conservative about formatting inside the first retry? Ultimately there's only so much we can do because the user is free to install an arbitrarily broken logger. When I talk about "last resort" I'm talking about this case.

[c42f]

I reckon we merge this, it's quite an improvement on the current formatting.

[c42f]

Changing this could end up a bit misleading for custom log levels.

[fredrikekre]

@c42f would you be OK with renaming Warn to Warning? The reason for this change is that all the other levels are nouns, and I prefer we print Warning over Warn.

[c42f]

Yes, it's Warn vs Warning which is the sticking point here. The upside of the current naming is that Warn is consistent with @warn, and all the standard levels are four or five characters long.

So it seems impossible to have complete consistency without renaming to @warning in which case I'd rather just leave it as it currently is. Of course, we can just special case the printing more or less as you've done, but taking into account custom levels. I agree it's not entirely satisfying.

[KristofferC]

Warning seems very standarded to use, looking at random pictures of logging on google... Forcing the levelstr to be the same as the macro used seems a bit inflexible imo. Why can't we use @warn and print it as Warning?

[c42f]

Certainly, we can print it differently for logging output, absolutely no problem with that. I thought the issue was about the named constant Logging.Warn::LogLevel.

For achieving "Warning" printed in the output we can have

1. string(Logging.Warn) == "Warning" - seems too inconsistent to really consider.
2. Rename Logging.Warn -> Logging.Warning (which I thought was being suggested above). I'm not so keen on that, for the reasons of consistency with the spelling of @warn.
3. Just special case the output formatting, as is done already. This seems the best of the lot IMO, though not entirely satisfying.

[KristofferC]

Perhaps I was confused about what @fredrikekre was suggesting. Sorry if I was misunderstanding.

[c42f]

No probs, I really wish we could get together in the same room to discuss where this stuff is going. It's super slow and easy to get confused / talk at cross purposes in text.

Option (2) is a reasonable way out if you want to try it @fredrikekre and see how it feels? I'm not really sure where the best compromise of (2) vs (3) lies. They both have some inconsistencies, unfortunately.

[fredrikekre]

Thanks.

There's a reason to have both. Consider someone had written

@info "Current value" a÷b

This is fine until the unexpected happens and b=0, in which case a DivideError is generated. This error should be reported through the logging system rather than STDERR if possible - this is the second call to handle_message in the inner try block.

I agree that this should be sent to the logger, and understand the second call to handle_message. I think we mostly misunderstood each other above, I will submit a PR later which implements what I had in mind :)

[JeffBezanson]

+2, this printing is much nicer.

I hate to rain on the parade, but the fact is there are many cases in src/ and base/ where we print WARNING and ERROR in all caps, and this now looks kind of inconsistent.

[StefanKarpinski]

True, but could be resolved pretty easily with a search-and-replace for "WARNING" and "ERROR".

[fredrikekre]

Do people prefer WARNING or Warning?

[StefanKarpinski]

I'm fine with titlecase. All caps was a bit screamy. Color should be plenty for people to notice.

[c42f]

there are many cases in src/ and base/ where we print WARNING and ERROR in all caps, and this now looks kind of inconsistent

@JeffBezanson I'm working on it. Please have a look at #25257 for the first installment which fixes the cases in parsing/lowering.

I've also got a second installment which provides tools to do the same in the other parts of src. For base it should mostly be a simple matter of searching and replacing with @warn or @error, though some of those cases may be during initialization or finalizers which could be tricky.