Logging in notebook

[fonsp]

Schermopname.2021-04-02.om.19.16.30.mov

Adds support for Julia logging: @info, @warn, @debug, @error and custom log messages.

(This does not relay the terminal - that is a different subject.)

TODO

• The log should "pop out" of the overflow:hidden box when you click on it.
• Virtualized logs (only load a viewport worth of logs into the DOM)
• layout might not work if the cell has many lines but cell input is hidden
• Selecting cells is difficult if there are also logs
• Option to hide logs (Future TODO: save that propery in a comment @dralletje
• Narrow-screen layout still needs improvement
• show kwargs
• rich output
• use a lighter background for the kwargs
• State diffing becomes slow when there are lots of logs
• Don't also print logs to terminal?
• Limit a crazy number of logs?
• Dark mode

Test notebook

https://github.com/fonsp/disorganised-mess/blob/main/logging.jl

Try it out!

julia> ]
pkg> activate --temp
pkg> add Pluto#logging
julia> import Pluto; Pluto.run()

[fonsp]

[c42f]

It may be better just to use Logging.with_logger() in some context which surrounds the user's code?

[c42f]

This is super cool!

Let me know if there's any help you'd like in integrating this, or subtle questions about the logging system. I'm also happy to do a call if that's helpful? (Note I am in AEST=UTC+10)

I can help out with the Julia side of the code if necessary. Figuring out the most correct way to format the log messages might be the hard bit.

[fonsp]

Right now the messages only appear if you had the notebook open while the logs happened, so the logs are lost when you refresh. Instead, logs need to be stored in an array inside the cell's state.

Our current state management is not very flexible - implementing this means adding a couple of new message types, handlers and state updates, and some careful thinking to ensure that the state is never corrupt. We were planning to update the state management system soon, so I think it would be nicer to wait for that.

[c42f]

Sure, no problem at all.

What are your thoughts for UI when log records arise from code defined outside Pluto, or from functions defined in other cells?

I can think of a couple of options:

• Dynamically assign them to the line from which they originate (Note that this requires taking a stack trace for every message which will appear in the UI, which can be done by the logging backend. Could be expensive; though UI elements are also expensive so we might be ok :-) )
• Plot them on a line separate from the code lines of the cell. This can be done with the file and line keys that every log record comes with.

I kinda favor trying the dynamic option and seeing how it pans out.

[fonsp]

The dynamical approach is a good idea! Could you show me how to get the stacktrace from a log?

Before your idea, I was thinking that every external log message could appear as a vertical line, since we know it's temporal position, but not the line number. Something like this:

The log would show in the cell that was most recently running.

Finding the backtraced line number is better of course, but we might still need this as a fallback? For async external code for example? Or can those also be backtraced?

[c42f]

Could you show me how to get the stacktrace from a log?

The idea would be to add a call to backtrace() from within handle_message(::PlutoLogger, ...) — this runs as a child function of the user's @info so the backtrace is directly accessible. From that backtrace, extract any info necessary and attach it to the log record as metadata before passing it to the frontend.

For async tasks, note that loggers are inherited from the parent task if Logging.with_logger was used. So as long as you install PlutoLogger before creating those tasks, the same considerations will apply. (Or if you're using global_logger that will be the fallback for any tasks which don't have a local logger installed.)

[LinusSch]

Quick thought on the UI: I would prefer the dots from the same iteration of the loop to be vertically aligned. That way there is a little bit more information, directly visible.

I guess this idea breaks the case where multiple logging events happen on a single line of a single iteration of the loop, but this could be solved by having two or three sectors with different colors as needed. Exactly how many logging events are happening at a single point in the code is rarely as useful as quickly realizing whether several events happening in a loop are happening on the same or on different iterations (in my experience, which is more limited than yours, so feel free to correct me if I'm wrong).

If this idea can work well or not probably depends on how you show the details of each event, that view may become unwieldy in cases where many events get bundled into a single dot. If so then the usefulness may not be worth the drawback.

[fonsp]

[fonsp]

@dralletje Can you take a look at the state diffing performance problem in this PR? You had a solution right?

[pankgeorg]

Is this commented on purpose? @fonsp

[fonsp]

@dralletje Your recent commits (0e5f8ce and cc045d3) did the trick!

Benchmarks

Before:

After:

Script:

https://gist.github.com/fonsp/9551c8688f05b4baf21d3f242696dfcc

[fonsp]