Make handle_message return true/false depending on if accepted

[tkf]

Continuing #1, it would be nice to have SwitchLogger as described below. Do you want to add a logger like this? If so, what is the name for it?

---

I'm +1 for TeeLogger, as I can imagine another logger wrapping multiple loggers that uses the fist matched logger. It can be used as, e.g., SwitchLogger(ProgressLogger(...), TBLogger(...), global_logger()), to let special loggers handle special log events. To be more precise, the implementation would be something like

function handle_message(logger::SwitchLogger, args...; kwargs...)
    i = findfirst(l -> comp_shouldlog(l, args...), logger.logging)
    i === nothing && return
    return handle_message(logger.logging[i], args...; kwargs...)
end

Originally posted by @tkf in #1 (comment)

[oxinabox]

So what this basically does, that a DemuxLogger doesn't
is give a kind of priority to any filter-loggers below it.

You can always achieve the same with a DemuxLogger + tweaking the filters to be mutually exlusive rules.

I am not sure wether that is clear or not.
Pros: shorter filters
Cons: implict filtering information in the order. Which kinda makes this logger a filter.

After a quick attempt at writing this with mutually exclusive filters I find it painful,
So maybe this is a good idea.

IDK about naming it,
but it should have first or something like that somewhere in the name

[tkf]

One possibility is MuxLogger which emphasizes kind of a dual nature wrt DemuxLogger (although #22 may remove it). Another possibility is FirstMatchLogger to emphasize the order dependency. I initially suggested "switch" since it has this meaning in "switch statement" of some languages.

[oxinabox]

This is not what MuxLogger would do.
See #19

Mux senses multiple messages over a single stream,
Demux splits them out into many streams
(right now out DemuxLogger does that with the help of Filters, thus the badness of the name).
This is actually just another kind of Demux.
The Mux-Demux metaphore doesn't work great here.

[oxinabox]

I initially suggested "switch" since it has this meaning in "switch statement" of some languages.

Switch means many things. So not clear
In C it means: the first that matchs and all after that (until break).

[c42f]

In C it means: the first that matchs and all after that (until break).

Sure, but the ability to leave out a break is generally considered confusing, and compilers will warn about this now (gcc -Wimplicit-fallthrough). Don't get me wrong, fallthrough has its uses (I've used it myself on various occasions), but it's a once-in-a-while kind of thing.

As a general observation, it seems striking to me that we're replicating the world of normal programming control constructs as an object tree here, with SwitchLogger and TeeLogger being largely equivalent, other than some fine detail of how they do dispatch inside handle_message. Would it be more helpful to go somewhat in the opposite direction: provide some object scaffolding to store the sinks, but allow the filtering and dispatch to various sinks to be written directly as normal code in a closure? Essentially allow the user to write handle_message in any way they please, but free them from the need to define the supporting types.

[tkf]

Would it be more helpful to go somewhat in the opposite direction: provide some object scaffolding to store the sinks, but allow the filtering and dispatch to various sinks to be written directly as normal code in a closure?

I think an easy way to do this is to "collapse" the logging interface to a single function of the form

handler(level, message, _module, group, id, file, line; kwargs...) :: Bool

which returns true when the message is handled and false otherwise.

Then, we can implement

struct AdHocLogger{F,T<:Tuple{Vararg{AbstractLogger}}} <: AbstractLogger
    combinator::F
    loggers::T
end

shouldlog(::AdHocLogger, _...) = true
min_enabled_level(::AdHocLogger) = Logging.BelowMinLevel

function handle_message(adhoc::AdHocLogger, args...; kwargs...)
    handlers = map(adhoc.loggers) do logger
        (args...; kwargs...) -> tryhandle(logger, args...; kwargs...)
    end
    adhoc.combinator(handlers)(args...; kwargs...)
end

function tryhandle(logger, args...; kwargs...)
    if comp_handle_message_check(logger, args...; kwargs...)
        handle_message(logger, args...; kwargs...)
        return true
    end
    return false
end

which can be used to define TeeLogger and FirstMatchLogger as a closure

teelogger(loggers) =
    AdHocLogger(loggers) do handlers
        function (args...; kwargs...)
            for h in handlers
                h(args...; kwargs...)
            end
        end
    end

firstmatchlogger(loggers) =
    AdHocLogger(loggers) do handlers
        function (args...; kwargs...)
            for h in handlers
                h(args...; kwargs...) && return
            end
        end
    end

I guess defining shouldlog(::AdHocLogger, _...) = true etc. is rather sad but I don't think it's possible to generate shouldlog from arbitrary closure defining handle_message.

[c42f]

I guess defining shouldlog(::AdHocLogger, _...) = true etc. is rather sad but I don't think it's possible to generate shouldlog from arbitrary closure defining handle_message.

Yes this seems to be a downside to the current AbstractLogger interface: having it defined using several separate functions makes it unfriendly to configure these things with closures. As a result creating new loggers feels more heavyweight than would be desirable.

[tkf]

@oxinabox I assumed that FirstMatchLogger was the most uncontroversial one and made a PR #24. Please let me know if you want another name.

[tkf]

@oxinabox Actually, let me close this issue. It turned out that TeeLogger-like shouldlog based-handling does not work for the usecase I have in mind. This is because whether a certain log message is handled or not depend on a keyword argument. So, I can't use shouldlog. I should've noticed this before opening the issue. Sorry about that.

More concretely, here is what I'm doing in https://github.com/tkf/ConsoleProgressMonitor.jl:

function Logging.handle_message(
    logger::ProgressLogger,
    level, title, _module, group, id, file, line;
    progress = nothing,
    _...
)
    if progress isa Real && (progress <= 1 || isnan(progress))
        ... update progress bar ...
    elseif progress == "done" || (progress isa Real && progress > 1)
        ... create a progress bar ...
    else
        # Do nothing here.  Ideally delegate the message to the default logger.
    end
end

As you can see, if the message is handled or not depend on the progress keyword argument.

It really would have helped in this particular case if the logger interface was something like the handler function I mentioned above. (Of course, I guess it's non-trivial to match with other design requirements...)

[c42f]

The handler function idea is interesting. Currently handle_message returns nothing useful (it just sinks the message) but we could have a return value of some kind?

By the way, I did quite a bit of work on fancy display of progress logging in MicroLogging but ran out of steam to get it working on windows. Check out MicroLogging master and try out this:

julia> using Logging, MicroLogging
julia> global_logger(MicroLogging.ConsoleLogger(stderr))
julia> for i=1:10
           sleep(0.04)
           @warn "Other Messsage" i
           @info "Blah" progress=i/10
       end

[oxinabox]

You need an Teelogger + ActiveFilteredLogger

Currently handle_message returns nothing useful (it just sinks the message) but we could have a return value of some kind?

We could make ActiveFilteredLogger (and for consistency the others) do that.
Feels right.

[oxinabox]

When I started playing with Logging I also made a thing for progress-bars. OhMyLog, ended up with some problematic interactions because it wanted to erase the old line, when possible,
but that is hard to know if you are allowed to do if someone directly printlns.
see readme.

[oxinabox]

I am going to reopen this to track that idea

• Normal loggers should always return true
• ActiveFilteredLogger returns true or false depending on if message was accepted.
• What is currenty referred to as SwitchLogger considers a message to be accepted if it got past comp_should_log and then handle_message returned anything other than false

[tkf]

I am going to reopen this to track that idea

@oxinabox Thanks 👍 Good to know you are interested in the idea :)

Currently handle_message returns nothing useful (it just sinks the message) but we could have a return value of some kind?

@c42f To be backward compatible, I think the safest implementation of "return true" in my handler API would be to return a new type. For example, just create a type struct Handled end and return Handled() (somewhat similar to Transducers.Reduced).

The reasoning for backward compatibility is that it's rather easy to write a function that accidentally returns true in Juila (e.g., maybe you have condition || do_something at the end of handle_message body).

Check out MicroLogging master and try out this:

This is cool! Actually I had a similar idea in mind; i.e., normal logs leave "traces" and progress bar(s) are redrawn at the end of lines. Extending this thought, having special "table row" log message handler that redraws table header always would be nice. Something like

│ 1    │ 0.214443 │ 2.68322 │
[ Info: First step successful. Continuing...
│ 2    │ 0.282329 │ 2.15429 │
│ 3    │ 0.311364 │ 1.67112 │
│ 4    │ 1.03877  │ 1.11549 │
│ 5    │ 1.18588  │ 0.61109 │
├──────┼──────────┼─────────┤
│ Step │ time     │ loss    │
Progress:  16%|████████████                                      |  ETA: 0:00:04

where the last lines

├──────┼──────────┼─────────┤
│ Step │ time     │ loss    │
Progress:  16%|████████████                                      |  ETA: 0:00:04

are redrawn for each update.

that is hard to know if you are allowed to do if someone directly printlns

@oxinabox I'm kind of hoping that Logging becomes the canonical way to print anything from "non-IO" functions (functions that does not take io::IO). Maybe we can facilitate this by enriching special log handler types (like the table logger I mentioned above).

Another direction I'm interested in is to have IDE-agnostic "rich subdisplay" (which would completely avoid println difficulty). For example, here is a module to draw nested progress bars in a Electron window: https://github.com/tkf/ElectronProgressBars.jl (sorry, no doc ATM).

[tkf]

FYI, MWE of ElectronProgressBars:

using ElectronProgressBars
ElectronProgressBars.install_logger();

for i=1:10
    sleep(0.1)
    @warn "Other Messsage" i
    @info "Blah" progress=i/10
end

[oxinabox]

Extending this thought, having special "table row" log message handler that redraws table header always would be nice

I want this too.
I want to steal the code from Optim.jl probably , and generalize it.

that is hard to know if you are allowed to do if someone directly printlns

@oxinabox I'm kind of hoping that Logging becomes the canonical way to print anything from "non-IO" functions (functions that does not take io::IO).

My thouhts exactly

[c42f]

some problematic interactions because it wanted to erase the old line, when possible,
but that is hard to know if you are allowed to do if someone directly printlns.

I solved this problem by using the terminal scroll region. Try this:

julia> using Logging, MicroLogging
julia> global_logger(MicroLogging.ConsoleLogger(stderr))
julia> for i=1:10
           sleep(0.04)
           println("Ad hoc logging $i")
           @info "Blah" progress=i/10
       end

You can use MicroLogging.StickyMessages to do this in general (it's not logging-specific).

The problem on windows is that we go through libuv + the console which introduces multiple layers which want to interpret control codes so this doesn't work out of the box. It can be made to work but we might need to carry a patch to libuv (see also libuv/libuv#1884)

[c42f]

Actually I had a similar idea in mind; i.e., normal logs leave "traces" and progress bar(s) are redrawn at the end of lines. Extending this thought, having special "table row" log message handler that redraws table header always would be nice

Yes! I've also wanted tabular logging for a long time. The difficult problem is to figure out how to format the table when there's multiple different log messages displaying different information.

[tkf]

I solved this problem by using the terminal scroll region.

Cool! I didn't know the scroll region feature. StickyMessages looks super useful. It would be nice if you can package it up when you have time.

The difficult problem is to figure out how to format the table when there's multiple different log messages displaying different information.

I wasn't thinking about multiple sources. But maybe horizontally concatenate to the existing row and header by re-painting those lines? I think this would require us to have an ID for each table source to distinguish them. It would help message handlers to decide if a row should be vertically or horizontally concatenated.

[c42f]

Cool! I didn't know the scroll region feature. StickyMessages looks super useful. It would be nice if you can package it up when you have time.

Happy to do so, but I wonder where to put it. Ultimately it probably belongs in a terminal UI package somewhere (maybe in the stdlib). If you just want to use it for terminal UI logging stuff, I suggest we consolidate our efforts into one repo (maybe TerminalLogging as suggested on slack) and we can import StickyMessages there and use it directly?

[tkf]

I replied it in slack but it sounds great 👍

[c42f]

I'm kind of hoping that Logging becomes the canonical way to print anything from "non-IO" functions (functions that does not take io::IO).

This was also exactly my thinking when designing the frontend (hopefully you can tell by reading the docs :-) )