PlutoLogging.jl

PlutoLogging.jl

### A Pluto.jl notebook ###
# v0.11.3

using Markdown
using InteractiveUtils

# ╔═╡ 7154a0e6-d7a3-11ea-2657-db1e00c80460
md"Define a function which will do some logging. Note that this could just as well be in an external library"

# ╔═╡ 514ac9ea-d7a0-11ea-1512-e99df979d240
md"Let's collect some logs using `with_logger`, and `Test.TestLogger` for a quick and dirty way to demonstrate this (`TestLogger` is a semi-internal API). In practice, Pluto.jl may want its own logger."

# ╔═╡ 86794d1c-d7a0-11ea-393b-f540f7fd608b
md"Format the logs as a tabular view.

In practice this would presumably be part of the Pluto cell UI somehow; perhaps folded away but available in a popup.

Obviously there's a lot of options for how to do this nicely, and it would be cool if there was UI to do some light filtering, and perhaps an option to map variables to column of the table, and to display Julia values richly in a similar way to the default Pluto output.

The example here is a bit of a formatting disaster, really!
"

# ╔═╡ 16cb8602-d79f-11ea-1230-55a5ece049fc
md"A function to create a tabular view of logging info"

# ╔═╡ f6ebcfb8-d79e-11ea-00e5-79a5d6e0d812
md"Primitive styling experiments. Pardon the mess, I know only enough HTML/CSS to be dangerous :)"

# ╔═╡ 9a565fe6-d796-11ea-01ef-5f2e3c3bbbd0
html"""
<table style="width:100%">
<tr><th style="width:10%">Level</th><th>Module</th><th>Message</th></tr>
<tr style="background-color:#DDDDFF;"><td>Debug</td><td title="Hover!">Base</td><td>"Debugging!"</td></tr>
<tr style="background-color:#DDDDDD;"><td>Info</td><td>Base</td><td>"Some information"</td></tr>
<tr style="background-color:#FFEEDD;"><td>Warn</td><td>MyPkg</td><td>"Uh oh"</td></tr>
<tr style="background-color:#FFDDDD;"><td>Error</td><td>MyPkg</td><td>"Bad things"</td></tr>

</table>
"""

# ╔═╡ e1859b80-d7a4-11ea-2bcd-ed8a0cbf4c7d
html"""
<detail style="display: block;">
<summary>
A summary
</summary>
<p>
Hi blah blah
</p>
</detail>
"""

# ╔═╡ 176456f8-d7ad-11ea-0796-158017db0c16
md"Trying to make use of Pluto's builtin value formatting... Almost, but not quite.  Some styling thing is going wrong here!"

# ╔═╡ 47652cb6-d79d-11ea-33c4-c175255a6101
using Logging, Test, TerminalLoggers, Markdown

# ╔═╡ 86d5c12c-d7a6-11ea-2733-f7e48ab50543
using Pluto

# ╔═╡ 5239d6cc-d7a3-11ea-03a6-5d92a5ef9538
function some_logging(x)
	@debug "Debugging some julia code! `x^2`" x x^2
	for i=1:3
		@info "Iterating" i
	end
end

# ╔═╡ 2cb8772e-d79d-11ea-1e80-9fb5faaa2b63
logs = begin
	# May not want debug level by default... but it's here for demonstration
	t = Test.TestLogger(min_level=Logging.Debug)

	with_logger(t) do
		x = rand(UInt8, 2,2)
		some_logging(x)
		@warn """
			Uh oh, something weird happened and we needed to warn you about it. You could try:
		
			* foo
			* bar
			"""
		try
			1÷0
		catch ex
			@error "An error" exception=(ex,catch_backtrace())
		end
	end

	t.logs
end

# ╔═╡ 96d92068-d79d-11ea-2eb4-1d4fbe697824
level_colors = Dict(
	Logging.Debug=>"#DDDDFF",
	Logging.Info=>"#DDDDDD",
	Logging.Warn=>"#FFEEDD",
	Logging.Error=>"#FFDDDD"
)

# ╔═╡ a673f174-d79d-11ea-3290-f76c71cb8cba
function make_logs_table(logs)
	rows = []
	for log in logs
		# The message should be formatted as markdown
		message = if log.message isa AbstractString
			sprint() do io
				show(io, MIME"text/html"(), Markdown.parse(log.message))
			end
		else
			sprint(show, log.message)
		end
		if !isempty(log.kwargs)
			# Hooking into Pluto's output system would be nice,
			#   but I've busted the formatting somehow...
			# vars = first(Pluto.PlutoRunner.format_output(log.kwargs))
			ctx = IOContext(devnull, :displaysize=>(200,100))
			var_rows = TerminalLoggers.format_key_value_pairs(log.kwargs, ctx)
			vars_detail = join([' '^r[1]*r[2] for r in var_rows], "\n")
			vars = """
			<pre>$vars_detail</pre>
			"""
		else
			vars = ""
		end
		# Drop the Pluto cell from the file name
		file,cell = split(string(log.file), "#==#")
		push!(rows,
			"""
			<tr style="background-color:$(level_colors[log.level]);">
				<td title="$(log.level) @ $(log._module) — $(file):$(log.line)">
					$message</td>
				<td>$vars</td>
			</tr>
			""")
	end
	HTML("""
		<table>
		<tr>
			<th>Message</th>
			<th  style="width:40%">Variables</th>
		</tr>
		$(join(rows, "\n"))
		</table>
		""")
end

# ╔═╡ a42f5718-d79e-11ea-0335-7f2ba6bbf61f
make_logs_table(logs)

# ╔═╡ 98455c7c-d7a6-11ea-17b7-15bb344ad833
HTML("""<pluto-output class="inline_output "><div>$(first(Pluto.PlutoRunner.format_output(logs[1]))))</div></pluto-output>""")

# ╔═╡ ba0f02a0-d7a5-11ea-2f91-75041665e3e5
# Trying to make use of Pluto's builtin value formatting... Almost, but not quite.  Some styling thing is going wrong here!
HTML(sprint(show, MIME"application/vnd.pluto.tree+xml"(), Dict(string(k)=>v for (k,v) in logs[1].kwargs)))

# ╔═╡ a0469142-d7ae-11ea-009a-79e8b45cb010
logs[1]

# ╔═╡ Cell order:
# ╟─7154a0e6-d7a3-11ea-2657-db1e00c80460
# ╠═5239d6cc-d7a3-11ea-03a6-5d92a5ef9538
# ╟─514ac9ea-d7a0-11ea-1512-e99df979d240
# ╠═2cb8772e-d79d-11ea-1e80-9fb5faaa2b63
# ╟─86794d1c-d7a0-11ea-393b-f540f7fd608b
# ╠═a42f5718-d79e-11ea-0335-7f2ba6bbf61f
# ╠═96d92068-d79d-11ea-2eb4-1d4fbe697824
# ╟─16cb8602-d79f-11ea-1230-55a5ece049fc
# ╠═a673f174-d79d-11ea-3290-f76c71cb8cba
# ╠═47652cb6-d79d-11ea-33c4-c175255a6101
# ╟─f6ebcfb8-d79e-11ea-00e5-79a5d6e0d812
# ╠═9a565fe6-d796-11ea-01ef-5f2e3c3bbbd0
# ╠═e1859b80-d7a4-11ea-2bcd-ed8a0cbf4c7d
# ╠═86d5c12c-d7a6-11ea-2733-f7e48ab50543
# ╟─176456f8-d7ad-11ea-0796-158017db0c16
# ╠═98455c7c-d7a6-11ea-17b7-15bb344ad833
# ╠═ba0f02a0-d7a5-11ea-2f91-75041665e3e5
# ╠═a0469142-d7ae-11ea-009a-79e8b45cb010

I see potential! Logging should be more than just a stream of text

About the HTML(sprint(show, MIME"application/vnd.pluto.tree+xml"():

It's not yet possible to use the Pluto tree viewer inside HTML output - but this could be added. Maybe it's cool to have the tree viewer inside the table?

@fonsp sorry I didn't see your comments, somehow!

I see potential! Logging should be more than just a stream of text

Yes indeed, this is exactly right! I've always wanted to do things like plot the values of logged variables over time (for example, to plot the convergence of a numerical algorithm). But my user interface skills and time has always been lacking, so this hasn't happened so far :-)

Maybe it's cool to have the tree viewer inside the table?

Yeah that's a thing I tried, but it didn't work out — the format was broken — I had assumed due to some styling issues.

Cool! We should talk more then (fonsvdplas@gmail.com) - Pluto doesn't support print() yet, and I wanted to do a little more than just including a terminal inside the page. https://www.notion.so/a-cooler-way-to-print-24e1c517c3f64bbbbcb97499e2539611 So I'd love to hear some creative ideas!

I think that just getting a basic line chart of printed values is already a huge win. But you don't want to construct that plot manually (like I did in that screenshot), you just want print(i) to later turn into a chart

But you don't want to construct that plot manually (like I did in that screenshot), you just want print(i) to later turn into a chart

Yes exactly. The thing is that the user program should only need to "mention" some variables of interest

for i=1:100
    @info "my chart" i
end

Then the combination of logging backend + UI should in principle be able to present those to the user in a flexible way which is not coupled to the source code.

This decoupling also allows the user to introspect the operation of code which they didn't write and can't immediately modify. For example, a third party solver library.

Awesome!! What do you mean with that last sentence? That you tag a mutable variable before putting it into a 3rd party function?

What do you mean with that last sentence?

I only mean that the third party library could be using the logging system too. And you can collect those messages just the same way as you collect ones from the user code.

We'd probably want some context-specific filtering though: the user's less likely to care about logging from other libraries than they are about messages which originate from their own code in the notebook. (The logging system records detailed source information for all events so that should be fairly easy.)

Just found this discussion while working on JuliaPluto/PlutoUI.jl#31 ...

What is not possible that way is the idea to allow to capture output qualified with sources.
JuliaIO/Suppressor.jl#36 (comment)

But I see with the logging system this possibly could be done by accessing log messages before they are made into strings.

So one way would could be to re-route print to the logging system via capturing stdout if this can be synchronized with other output (this is triggering for me so probably will try this out...)

Alternatively we could keep not supporting print and introduce @note and @Notef (the later like @printf) for pluto
notebooks.

I think the idea here was to not route things through stdout/stderr because they are limited to unstructured text (boo!). Instead, it would be kind of like your final suggestion, but with the default @warn, @info, etc instead of our own @note.

@c42f Do you want to work on integrating this gist into Pluto? I could help with the communication protocol and UI.

The Test.LogRecord already contains all info needed to create https://www.notion.so/a-cooler-way-to-print-24e1c517c3f64bbbbcb97499e2539611

Maybe we can call sometime? fonsvdplas@gmail.com

See also https://github.com/JuliaLang/IJulia.jl/blob/master/src/stdio.jl : they implement their own AbstractPipe...

Proof of concept: route stdout lines to @info messages

macro log_stdout(block)
    quote
	original_stdout = stdout
        out_rd, out_wr = redirect_stdout()
        function myread(out_rd)
            buffer=Array{Pair{String,String},1}(undef,0)
            more=true
            while !eof(out_rd)
                @info readline(out_rd)
                # ^ could be special @from_stdout  message for PlutoLogger
            end
            nothing
        end
	with_logger(ConsoleLogger(stderr)) do
                #   ^ could be PlutoLogger
            reader = @async myread(out_rd)
            $(esc(block))
            # result=grab_data(logger)
	end
	redirect_stdout(original_stdout)
        close(out_wr)
	end
        # result
end

grab_data would return an Array{Pair{SomeMsgType, String},1}

But not sure what would happen if @distributed or @threads is in the block.

fonsp/Pluto.jl#437

Let's keep things simple for now

agree to stick to simplicity in order to be able to maintain things...
But how do you plan to define @info etc ? Via a PlutoLogger <:AbstractLogger pushing data to your channel ?

ok I see it in cell 2cb8772e ....

But then I think the re-routing could be even simpler once the PlutoLogger is already running.
There might be a @from_stdout loglevel which could control this.

macro log_stdout(block)
    quote
	original_stdout = stdout
        out_rd, out_wr = redirect_stdout()
        function myread(out_rd)
            while !eof(out_rd)
                @info readline(out_rd)
            end
            nothing
        end
        reader = @async myread(out_rd)
         $(esc(block))
	redirect_stdout(original_stdout)
        close(out_wr)
 end

If not in Pluto this could also go into PlutoUI instead of the current idea. I would wait for fonsp/Pluto.jl#437 and try this out.

Yep! We will use Base.@info, and define our own logger! I got it working today:

Great! Curious where this leads us!

☺

@fonsp I'm happy to help with integrating this as much as you need. I think the tooling on the Julia side is actually almost all there, it's the UI which seems like a lot of work to me ;-)

route stdout lines to @info messages

@j-fu note that Logging2.jl library already has a way to do this. It's nascent but I can release a version if it's useful.

I see. Indeed it seems that Logging2.jl has what I would love to see, with a more profound way to implement this.
IMHO worth to be merged into Logging.jl ...

Yeah, that's the plan — it's basically a staging area for Logging. The problem with Logging is that — like all other stdlibs — its release cycle is tied to releases of Julia. So for now Logging2 is separate.