Documentation for the Logging stdlib

[c42f]

Here's some documentation covering the Logging stdlib.

Fixes #25154

[stevengj]

key=value pairs or key–value pairs

[stevengj]

key–value pairs

(note en dash)

[stevengj]

task-local logger (hyphenate compound adjectives)

(note hyphen, not an en dash)

[stevengj]

em dash (—), not hyphen, with no surrounding spaces

(I end up giving all my students the talk about hyphen vs en dash vs em dash vs minus sign. 😉 )

[c42f]

Thanks. I normally get the emdash correct, but there's no nice way to type it in markdown so I got sloppy ;-) Oddly enough, the julia markdown parser accepts the LaTeX -- for endash but not --- for emdash.

[stevengj]

On most operating systems there are keyboard shortcuts to type the Unicode dashes directly. For example, on MacOS you type option-hyphen for en dash and option-shift-hyphen for em dash.

[stevengj]

comma before "which"

[stevengj]

What methods should a custom logger define?

[stevengj]

If these are the ones in the Processing events section below, you can just cross-reference that here.

[c42f]

I've added a section about this.

[stevengj]

Is there any way to attach additional information to log events?

For example, in IJulia we might want to attach additional information about the current execution cell, so that the log message is printed in the right output cell. (If necessary, we can extract this from the file metadata, since the input cell name is used as the filename, but I'm curious if there is a way to attach additional runtime information. For example, if you define a custom logger, could you implement a method to generate additional key-value pairs based on some dynamic global state at the time the log message is emitted?)

[c42f]

Absolutely — dynamic context is something which can be added by installing a custom logger as a filter (add a key–value pair and pass to the next logger up the stack). This could include information such as:

• Global or task-local variables as you're suggesting
• The time of the event
• A backtrace

I think this is going to be a common enough pattern that we could support it in the library. For now however it's pretty bare bones and provides just enough structure for this kind of stuff to be done outside Base/stdlib.

For IJulia I expect you'll want to install a custom logger anyway because formatting of log messages can be a lot nicer in the browser compared to the console.

[swt30]

At the risk of turning this into a proofreading session, I popped in some more minor grammatical/punctuation suggestions along the same lines as stevengj. I really love the new logging system, by the way---well done!

[swt30]

user-defined

[swt30]

I'd use "that" instead of "which" here.

[c42f]

Aha, I've already removed most of these "which"s locally. Will push an update shortly.

[swt30]

Excellent, you've clearly got your pronouns under control then ;)

[swt30]

I'd also use "that" instead of "which" here.

[swt30]

Comma before "which"

[swt30]

Newly-spawned

[c42f]

Thanks, any gifts of compound adjective detection are gratefully received :-)

[swt30]

task-local in the line above too!

[stevengj]

Actually, this is incorrect: you don't hyphenate compound adjectives where the modifier is an adverb ending with "ly": https://www.merriam-webster.com/words-at-play/6-common-hypercorrections-and-how-to-avoid-them/hyphenating-ly-adverbs

[swt30]

^ that's true, my bad!

[swt30]

If you're fixing the hyphen -> em dash above then you should do this one too, or you could just turn it into a comma: "where the logger is lexically scoped, provided explicitly by the module author"

[c42f]

Already done (locally) :-)

[c42f]

I've pushed some tweaks to address the questions which came up here (thanks).

Writing the section about the AbstractLogger functions made me reconsider which functions should have default implementations. I think the defaults for shouldlog and min_enabled_level were more likely to cause confusion than be useful so I've removed those for now.

[quinnj]

Love it! My only request would be maybe include a very quick "example AbstractLogger"? Maybe something like a "JSONLogger" that output everything in JSON? Just a thought.

[quinnj]

why take this out?

[c42f]

Yes, I loved this feature and removing it makes me sad. But I think it's too unreliable as a user facing interface for progress reporting. Consider

for i=1:N
    foo()
    @info "blah" progress=i/N
end

This looks super simple and nice, but what if foo() throws? Then you're left with an incomplete progress bar which needs to be cleaned up with a heuristic of some kind.

We might "fix" this by limiting things to one progress bar at a time. But this doesn't make sense for nested progress bars and more general concurrent situations where the loop above may be executing from more than one task at once. In these cases you really want a reliable way to detect when the progress step is complete.

So I think it's better to remove this for now and reintroduce a more reliable progress reporting interface later.

[StefanKarpinski]

I think that's a sane approach. Better to be a little cautious now and give the good stuff later.

[stevengj]

Don't hyphenate compounds for an adverb ending in "ly" (google it)…

[KristofferC]

Is there a way to just write text to a logger? Basically just want to use the stream of the logger but completely format it myself.

[c42f]

@KristofferC logging produces a stream of log events, each of which has the structure described in the documentation. You can encode formatting hints in this structure if you so please, but not all loggers will understand such hints unless there's a common convention.

Providing precise formatting control is problematic because it tightly couples the structure of events to the display capabilities of the logger which can vary widely depending on the environment (console vs juno vs ijulia for example). So you'd like to provide semantic structure in the message which can be interpreted according to the display capabilities which are present. My current best solution for rich formatting of log messages is to document that message strings should be encoded as markdown. This doesn't cover all cases (eg, color) but I think it's a practical compromise for now. I have a branch I was working on to make ConsoleLogger take markdown seriously, I just got a bit bogged down in refactoring Base.Markdown to make it actually work.

[stevengj]

@c42f, do messages have to be strings? If they are opaque objects that simply have appropriate show methods (much like documentation objects), then in principle they could have any kind of rich formatting on appropriate output devices.

[c42f]

@stevengj there's no fundamental reason that messages need to be strings. I feel like having strings be interpreted as markdown is a nice default which is consistent with docstrings. But using show would probably work out nicely. Perhaps something like Logging.showmessage with the default implementations:

showmessage(io, mime, msg) = show(io, mime, msg)
showmessage(io, mime, msg::AbstractString) = show(io, mime, Markdown.parse(msg))

?

[stevengj]

@c42f, I'm skeptical that you should define a showmessage function. I would think that:

• If the caller wants to pass a markdown-formatted string, they should use md"...." to create a Markdown.MD object.

• The current Logger be much like a display function: it should know what kinds of MIME types it can handle, call mimewritable(mime, x) to find out whether the message supports those MIME types, and then call show(io, mime, x) to output it (defaulting to text/plain if no other supported MIME types are found).

[maleadt]

Cool, docs :-)

How would I define a custom log level? I tried:

import Base.CoreLogging: @_sourceinfo, logmsg_code, Debug
const Trace = Debug-1000
macro trace(message, exs...) logmsg_code((@_sourceinfo)..., :Trace, message, exs...) end

But that gives some hygiene errors on code returned by logmsg_code.
Or isn't this intended to be extensible yet? And maybe it makes sense to add a trace level to Base.

Also, the with_logger/global_logger approach seems application oriented. Any suggestions/guidelines for library developers? Say, if I replace logging in my package with the new logging macros, and a user encounters some error, how do I instruct him to ramp up the log level for my package (ie. not just replacing the global logger, which is also pretty user-unfriendly)?

[c42f]

If the caller wants to pass a markdown-formatted string, they should use md"...." to create a Markdown.MD object.

I tried this in an earlier prototype and I didn't care for it.

Just as for docstrings, I think the simplicity and consistency of having an opinionated default makes sense here. In this system the message is "for humans" and the structured key-value pairs is a way to pass auxiliary machine readable data. So having strings which support simple formatting by convention is a win in my opinion. If we were to advertise in the documentation that people can just put an md in front of the message if they feel like it, we'll probably just get less consistency and less readability across the ecosystem as a whole. Coming back to docstrings again, making them markdown was an opinionated design choice, but I think it's worked out really well and I think there's a close analogy here.

[stevengj]

@c42f, in the documentation, the strings are passed through the markdown parser by default, but you can still pass any other kind of object that you want, and it uses the show machinery for rendering. You aren't prevented from using non-Markdown strings.

[c42f]

@stevengj yes, what I'd like to achieve is the same as the documentation system: pass strings through the markdown parser by default, and do "something sensible" with other types. How about we change

The message is a human readable string describing the event in markdown format.

to

The message is an object describing the event. By convention AbstractStrings passed as messages are assumed to be in markdown format. Other types will be displayed using show(io,mime,obj) according to the display capabilities of the installed logger.

[c42f]

@maleadt good questions, mostly the answer to those is "it's not implemented yet, but yes we should have a thing there". Perhaps I should just remove mention of custom log levels for now and we can make sure they work smoothly later. At the moment all you can do is define a custom level and use the generic @logmsg with that level (as in the tests).

I definitely agree that a @trace level is warranted. My feeling is that it should behave a little differently from the other logging macros because for tracing, efficient filtering based on a transparent label is critical. Perhaps something like:

@trace :event_label a=1 b=2

I guess the event label goes into the group variable for ease of filtering.

We should learn as much as possible from the solaris dtrace system which seems super well thought out http://dtrace.org/guide/preface.html#preface.

For now I'd like to punt on the details of tracing and get this merged!

[maleadt]

Rebased and added a snippet on #26265.

Anybody opposed to merging this? All review comments seem addressed, and the remaining questions are on the design of the logging system. I don't think these should hold back documentation on code that has been merged anyway.

[KristofferC]

+1 for merging, this is inf better than what we currently have :)

[stevengj]

Would like to see the clarification/fix on requiring markdown suggested by @c42f above, but otherwise +1.

[c42f]

Thanks a heap @maleadt for following this up, and sorry for being absent from the tail end of this discussion. (I'm in a new job and feeling both distracted by that and also burned out in keeping up with many open source loose ends. Bleh :-/ )