Printing additional information

[devmotion]

With ProgressMeter, it is possible to print additional information. As far as I can see (please correct me if I'm wrong), in principle the old progress logging syntax would allow to provide additional keyword arguments to @logmsg or @logprogress but this is not possible anymore with Progress and currently there exists no visualization backend for ProgressLogging that would print this additional information.

I'm wondering if this would be a useful feature that could be added to ProgressLogging and appropriate visualization backends (such as, e.g., TerminalLoggers), or if there exist alternative approaches that could be used to provide a user with more detailed information without flooding the terminal with @info.

[tkf]

If you want to use it right now with TerminalLoggers.jl, you can use the sticky message:

julia> @info "hello" sticky=true _id=:message_id

julia> @info "another message" sticky=true _id=:message_id

julia> @info "" sticky=:done _id=:message_id  # remove

I think Juno supports message keyword argument to show the tooltip. It should still be usable with @logprogress. I guess TerminalLoggers.jl can support it by using the sticky message mechanism. It's good for compatibility with Juno and also useful for simple messages.

I think a better (although a bit more involved) approach is to create yet another "log record standard" package like ProgressLogging.jl for transient UI messages. Like ProgressLogging.jl, it needs to provide an exception-safe API to cleanup the transient messages when exiting a scope.

[c42f]

but this is not possible anymore with Progress and currently there exists no visualization backend for ProgressLogging that would print this additional information.

Actually @logprogress can still accept key value pair information, it's just that TerminalLogger doesn't know how to format it. Installing SimpleLogger as follows you can see this information is available to the backend; we just need to figure out how to format it in TerminalLogger.

julia> global_logger(SimpleLogger(stderr, Logging.Debug))

julia> @withprogress for i=1:5
           if i == 50
               @info "Middle of computation" i
           elseif i == 70
               println("Normal output does not interfere with progress bars")
           end
           sleep(0.01)
           @logprogress "Name $i" i/5 i
       end
┌ LogLevel(-1): 
│   progress = NaN
└ @ Main /home/chris/.julia/dev/ProgressLogging/src/ProgressLogging.jl:385
┌ LogLevel(-1): Name 1
│   progress = 0.2
│   i = 1
└ @ Main /home/chris/.julia/dev/ProgressLogging/src/ProgressLogging.jl:385
┌ LogLevel(-1): Name 2
│   progress = 0.4
│   i = 2
└ @ Main /home/chris/.julia/dev/ProgressLogging/src/ProgressLogging.jl:385

[c42f]

With the current version of the code you can certainly use a separate sticky message if you like.

I think it's a bit of a hack though if you intend the message to be "mainly about progress with a bit of other info included".

[c42f]

Oh by the way, I should point out that with the @logprogress example above I've changed the progress bar name every iteration which will allow you to manually insert whatever extra information you want into the progress bar name string. I'd prefer to make key value pairs work though!

[tkf]

@c42f Juno special-cases message key as a tooltip:

Currently,

for i in 1:100
  @logmsg -1 "$(i)/100" progress=i/100 message="fooing: at element $i"
  sleep(1)
end

produces

--- https://github.com/JunoLab/ProgressLogging.jl/issues/7#issuecomment-545821340

Do you want to support all key-value pairs, like @info "hello" a b=value f(c)?

Also, what should happen with a temporary message like this?

@withprogress begin
    @logprogress 0.1
    sleep(0.1)
    @logprogress 0.2 message = "message as of 20%"
    sleep(0.1)
    @logprogress 0.3
    sleep(0.1)
end

Should message as of 20% be removed when processing the log record @logprogress 0.3?

[c42f]

Hmm, it seems weirdly backward to have the normal log message become the name of the progress bar and then to add a separate message key which is also the message!

I'd be more inclined to have a summary or shortmessage key which would become the name of the progress bar. Or to go with a more type-based API which can bundle both the message and message summary together.

But I guess that's what I get for encouraging unstructured key-value pairs and not providing any standard or much guidance for these things :-)

[c42f]

Another thought: the following markdown version would be cute if it worked (but it might also be a bad idea :-) )

@logprogress 0.1 """# $(i)/100
                    fooing: at element $i"""

[tkf]

it seems weirdly backward to have the normal log message become the name of the progress bar and then to add a separate message key which is also the message

Yeah, I think I agree. This makes writing custom handle_message a bit ugly (as you can't use message in the positional argument). But I don't have a strong preference for keeping/removing message. It's just already supported by Juno so I thought it might be OK to keep using it.

I'd be more inclined to have a summary or shortmessage key which would become the name of the progress bar.

Yeah, I think that makes sense. I was thinking note might be nice as well since it tends to be secondary information.

@pfitzseb What do you think?

[c42f]

Another thought: the following markdown version would be cute if it worked (but it might also be a bad idea :-) )

On further consideration I think this would be a reasonable way of doing it: what we want is message text with enough structure to infer a display-specific presentation format and markdown provides that.

It also matches conceptually with a more heavy weight type-based approach:

struct SummaryAndMessage
    summary::String
    message::String
end

# ...
@logprogress 0.1 SummaryAndMessage("$(i)/100", "fooing: at element $i""")

For context for those who haven't been following the markdown stuff we've introduced in TerminalLoggers, see https://github.com/c42f/TerminalLoggers.jl/issues/16

[pfitzseb]

I'm not particularly attached to the current naming convention. The markdown based approach is neat, but maybe a little too cute. How would we handle arbitrary elements? First # tag is the "name", the rest goes into what Juno calls "message" now?

[c42f]

The markdown based approach is neat, but maybe a little too cute.

Yes I was worried about that, but I think there's some benefits beyond being cute. Generally I think we should be preferring log record structure which is logger backend-independent as much as possible. From this point of view putting the "message parts" into what @logmsg considers the message field sees right and it will work sensibly with other backends, even SimpleLogger.

How would we handle arbitrary elements? First # tag is the "name", the rest goes into what Juno calls "message" now?

I'd maybe go even simpler. Something like if if the first markdown content element isa Markdown.Header use that as the name. Otherwise just use the first part of the message, with a heuristic putting the rest into the tooltip?

[tkf]

Generally I think we should be preferring log record structure which is logger backend-independent as much as possible. From this point of view putting the "message parts" into what @logmsg considers the message field sees right and it will work sensibly with other backends, even SimpleLogger.

This is the reason why I implemented custom string for Progress; i.e., it is still reasonably human-readable even with unsupported loggers:

julia> with_logger(SimpleLogger()) do
           @info ProgressLogging.Progress(uuid4(), 0.1)
       end
┌ Info: Progress: 10%
└ @ Main REPL[9]:2

So, I think another possible solution is to put message field in the Progress struct. I was somewhat opposed to it before but now I think it's a good solution.

[c42f]

So, I think another possible solution is to put message field in the Progress struct. I was somewhat opposed to it before but now I think it's a good solution.

Yes I agree. Though thinking about composition, "message and summary" is a distinct concept from Progress, so I'd be somewhat inclined to throw a "thing which is the message and summary" in as the Progress message (currently the "name" field).

(I'm starting to see some kind of pattern here in the logical distinction between the message field as a type vs the key value pairs. Something like... you want to wrap message semantics up in the type for dispatch purposes in the backends, whereas the key value pairs are a way to supply flexible metadata which can be mutated by the log routing pipeline. cf https://github.com/climate-machine/CLIMA/issues/134#issuecomment-595567311)

[tkf]

Though thinking about composition, "message and summary" is a distinct concept from Progress, so I'd be somewhat inclined to throw a "thing which is the message and summary" in as the Progress message (currently the "name" field).

I think I half agree. On one hand, obviously it's good to make things composable. But on the other hand I want to make Progress and its fields concrete and also avoid (over) parametrization. Both Juno and ProgressMeter have tooltip-like feature so maybe that's all what we need.

Also, I think there is another way to conceptualize this. There can be another messaging UI extension to the logging API (just like ProgressLogging.jl) that handles transient messages. Maybe an API like this:

with_transient_message() do msg
    msg[] = "Starting..."
    @progress for i in 1:10
        if i % 3 == 0
            msg[] = "It's $i now."  # old message is overwritten
        end
        sleep(0.2)
    end
end  # clear out `msg` from the UI

Implementation:

using ProgressLogging
using UUIDs

struct TransientMessage
    id::UUID
end

TransientMessage() = TransientMessage(uuid4())

Base.setindex!(msg::TransientMessage, ::Nothing) =
    @info "" _id=msg.id sticky=:done

Base.setindex!(msg::TransientMessage, value) =
    @info value _id=msg.id sticky=true

function with_transient_message(f)
    msg = TransientMessage()
    try
        f(msg)
    finally
        msg[] = nothing
    end
end

A bit crazier thing to do is to allow "nested scoping" of @progress and with_transient_message to interact. So, parentid of the progress log above can be of with_transient_message (which now must be implemented as a macro). This way, log handlers can associate transient messages and progress bars.

you want to wrap message semantics up in the type for dispatch purposes in the backends, whereas the key value pairs are a way to supply flexible metadata which can be mutated by the log routing pipeline

It has been hard for me to decide when to use which in some kind of principled way. I think what you just said is a good guideline. It makes sense for the routing pipeline to use it as there are no other places to put metadata. From the same line of thought, it makes sense to recommend to try put to everything in the message object if you are creating the log record (as it's only you who can do it).

(Though to be honest I still feel a bit uncomfortable that there is only a single namespace to put things. Maybe that's good enough and achieves a good balance, though.)

[c42f]

Though to be honest I still feel a bit uncomfortable that there is only a single namespace to put things. Maybe that's good enough and achieves a good balance, though.

Agreed, this makes me uncomfortable too. The frontend interface makes it so simple to attach context in terms of local variables and I still think this is a good thing. But then local variable names can happen to clash with a convention used in the backend for controlling log records, which really seems not-ok :-/

[c42f]

I think I half agree. On one hand, obviously it's good to make things composable. But on the other hand I want to make Progress and its fields concrete and also avoid (over) parametrization. Both Juno and ProgressMeter have tooltip-like feature so maybe that's all what we need.

This also sounds completely reasonable. I wonder — is there some natural frontend syntax which allows us to be flexible with the representation in the backend?