A way to set logging level in Pluto notebooks

[AsgerHB]

Is there a way to set the logging level of a cell in Pluto? By default it will show everything, including debug. Or even just a way to set it globally?

Pluto notebooks are a great way to debug newly developed code, and sometimes I have a need for debug prints when going over complex loops. Other times these same prints would flood the output, causing lag and taking out space.

I find myself using this pattern a lot

my_log_level >= -1000 && @debug "my message"

but it seems redundant to re-invent the wheel.

Alternatively, I can create my own logger and send it to stdout, which will show up under the cell.

logger1 = ConsoleLogger(stdout, Logging.Info)

with_logger(logger1) do
	foo()
	current_logger()
end

However, this converts the logs to pure text, losing some of the advanced display functionality Pluto has. Also, the font color for part of the text is not suitable for the background.

[mrufsvold]

You can set a created logger as the global logger!

I’m not at my computer at the moment, but I think if you’re skip passing in the ‘stderr’ stream, a SimpleLogger should act like the default Logger.

[AsgerHB]

The SimpleLogger makes all the text the same color, which fixes that problem. Thanks!

with_logger(SimpleLogger(stdout, Logging.Info)) do
    foo()
    current_logger()
end

However, it seems global_logger is ignored by Pluto.

begin
    global_logger(SimpleLogger(stdout, Logging.Info))
    foo()
end

[mrufsvold]

Maybe, before launching Pluto, you could try setting the global logger in the REPL? It’s not great since you can’t switch once you’re in the notebook.

Update: I tried and it didn’t seem to work.

Maybe @fonsp can help?

[disberd]

I think also @Pangoraw can shed some light here, not sure if currently possible in Pluto

[mrufsvold]

Okay, I read the source code, and it sure does look impossible given the current structure. Each cell is assigned its own logger, and it checks Logger.shouldlog (method to dispatch on PlutoCellLogger is here). Right now, it is hard coded with:

level = convert(Logging.LogLevel, level)
    (_module isa Module && is_pluto_workspace(_module)) ||
        level >= Logging.Info ||
        level == Logging.LogLevel(-1) ||
        level == stdout_log_level

So it passes through info and above for non-pluto modules, and everything from within the notebook. Given that it’s all contained inside the Pluto logic, I think the only solution would be a toggle in the GUI.

I guess you could potentially have the constructor for PlutoCellLogger check the level of the global logger and match it. But then you could only change with with the hacky workaround: launch Pluto with Threads.@spawn and then use the REPL to change logger level. Doesn’t really work with Pluto’s design principles.

[disberd]

I was also looking at the source code.
It seems that you can filter log level globally by overloading the Logging.min_enabled_level which is defined here:

fonsp/Pluto.jl/blob/91b0e9280840817bedb11227fc9980753f75246c/src/runner/PlutoRunner.jl#L2337

You can see that this work on this simple notebook:

[AsgerHB]

Setting global logging in this way is also very useful. However, it seems that I can’t have both at once.

For some reason, if I set the global logging level as @disberd describes, alternative loggers will stop working:

Code for above scrot

begin
    using Logging
    Logging.min_enabled_level(::PlutoRunner.PlutoCellLogger) = Logging.Info
end

foo()

debug_logger = SimpleLogger(stdout, Logging.Info)

with_logger(debug_logger) do
    foo()
end

But if I comment out the line that sets global logging, it starts behaving again.

I think for now I will stick to custom logging logic in my code, or alternatively dump it all to the terminal instead.

[disberd]

@AsgerHB, that is because the standard loglevel of the captured stdout from Pluto is -555 (it’s stored inside the variable PlutoRunner.stdout_log_level.

If you change the global logging min value like so:

Logging.min_enabled_level(::PlutoRunner.PlutoCellLogger) = PlutoRunner.stdout_log_level

you should also be able to see the captured stdout while stil filtering out the @debug messages since they have a level of -1000

Edit: With the help of the very nice LogginExtras package, you can also achieve this (and even more complex stuff) easily on a cell-by-cell basis:

[AsgerHB]

That clears it up!

And thanks for the tip on LoggingExtras. This lets me achieve the workflow I want by suppressing debug prints normally, and then using the LevelOverrideLogger to enable it in specific cells as needed.

Code snippet for the above scrot

# ╔═╡ Cell 1
begin
    using Logging
    using LoggingExtras
    Logging.min_enabled_level(::PlutoRunner.PlutoCellLogger) = 
            PlutoRunner.stdout_log_level
end

# ╔═╡ Cell 2
foo()

# ╔═╡ Cell 3
with_logger(LevelOverrideLogger(Logging.Debug, current_logger())) do
    foo()
end

[fonsp]

Hey everyone! Happy to see that you looked into our source code!

Our intention is as follows:

• By default, show all logs of level Info and above (plus ProgressLogging and our custom Stdout captures)
• If the log originated from code written in the notebook, then also show Debug logs. That means: not from a package or from include("some other file.jl"). The @debug statement must be written in a cell.
• (Not yet implemented) You can use the ENV["JULIA_DEBUG"] variable to also see debug logs outside of your notebook code, eg from a package you are developing or debugging. Logging: use the JULIA_DEBUG ENV value · Issue #2509 · fonsp/Pluto.jl · GitHub Be sure to upvote and subscribe to that issue if it would be useful.
• You can use with_logger and LoggingExtras.jl to control logging for a specific cell, like you already discovered .
  • We don’t really recommend setting the global logger because it’s a stateful side effect (which is hard for us to support in a consistent way), nor patching the PlutoRunner.PlutoCellLogger because this API might change in the future, and your notebook file won’t run outside of Pluto.

Hope this helps! In your example, was the @debug statement in foo defined in the notebook?

[AsgerHB]

The debug statement was indeed defined in the notebook. It didn’t occur to me that there might be a difference depending on origin.

It is a good behavior for my workflow, though. When developing a package I can write in debug-statements everywhere in the package, and view them as needed by doing

# ╔═╡ Cell 1
fast_debug = SimpleLogger(stdout, Logging.Debug)

# ╔═╡ Cell 2
 # Have to be created using a function, otherwise captured logs will go to this cell
pretty_debug() = LevelOverrideLogger(Logging.Debug, current_logger())

# ╔═╡ Cell 3
with_logger(fast_debug) do
    foo()
end

To select a logger as needed. I have noticed that standard-out is much more performant, probably because the output is all in the same text field. Not as nicely formatted though, so unless I expect 500+ prints, I’ll go with a LevelOverrideLogger.

[fonsp]

Feel free to write a little example notebook that showcases the performance difference and we will fix it!

[AsgerHB]

I wrote something here:
https://hastebin.skyra.pw/raw/powelelive

I benchmarked “pretty” to take about a second with beers=5000 while “fast” only took 80ms.
In addition to this and more importantly, Firefox(111.0.1 (64-bit) canonical snap for Ubuntu) starts struggling when the output of “pretty” is rendered. Things like mouseover, editing, and moving cells becomes clunky.