Implement table log monitor

[tkf]

#4 needs to go first, but this already (somewhat) works.

Example:

using Logging
using TerminalLoggers
using VegaDatasets
using Tables
using Printf
using ProgressLogging

with_logger(TerminalLogger()) do
    limit = 3
    @progress for row in Iterators.take(Tables.rows(dataset("cars")), limit)
        @info "" table=(
            Name = (@sprintf "%35s" row.Name),
            Year = row.Year,
            var"Miles per Gallon" = row.Miles_per_Gallon,
        ) _id=:outer
        for key in propertynames(row)
            if key ∉ (:Name, :Year, :Miles_per_Gallon)
                @info "" table=(
                    Variable = (@sprintf "%20s" key),
                    Value = getproperty(row, key),
                ) _id=:inner
            end
            sleep(0.01)
        end
        sleep(0.5)
    end
    @info "" table=nothing _id=:inner
    @info "" table=nothing _id=:outer
end

Output:

[c42f]

Very interesting.

 @info "" table=(
            Name = (@sprintf "%35s" row.Name),
            Year = row.Year,
            var"Miles per Gallon" = row.Miles_per_Gallon,
        ) _id=:outer

I've been wondering about content vs presentation here. In particular, should we be able to take records from someone who didn't anticipate structuring the logs as a table and put them into tabular form? I feel like we should, so you could just do

@info "" Name=(@sprintf "%35s" row.Name) Year=row.Year var"Miles per Gallon" = row.Miles_per_Gallon

But of course the backend then needs some fancy configuration to set up formatting for this particular record which is annoying and difficult. Another vague thought I've had is that the frontend @info usage could somehow hint at the formatting to be used, somehow independently of the key value pairs, or via the types of the values.

That var"Miles per Gallon" usage is entertaining by the way :-) I really didn't expect to see var"" turning up in so many places.

[tkf]

I've been wondering about content vs presentation here. In particular, should we be able to take records from someone who didn't anticipate structuring the logs as a table and put them into tabular form?

I think it makes sense to treat as an API contract that table messages are "rectangular" (i.e., has same set of keys) for each _id. It is automatic if you write it using @info without _id, though.

More practically, how do we mix table and normal logging with the "flat" message like @info "" Name=... Year=... var"Miles per Gallon" = ...? For example:

using Logging
using TerminalLoggers

with_logger(TerminalLogger()) do
    @info "" table=(
        var"First column" = rand(1:9999),
        var"Second column" = rand(1:9999),
    ) _id=:table1
    @info "" table=(
        var"First column" = rand(1:9999),
        var"Second column" = rand(1:9999),
    ) _id=:table1
    @info "" table=(
        var"Third column" = rand(1:9999),
        var"Fourth column" = rand(1:9999),
    ) _id=:table2
    @info "Some message" alpha=rand() beta=rand()
    @info "" table=(
        var"First column" = rand(1:9999),
        var"Second column" = rand(1:9999),
    ) _id=:table1
    @info "" table=nothing _id=:table2
    @info "" table=nothing _id=:table1
end

prints

│          881 │          2769 │
│         8232 │          3176 │         7173 │          7873 │
├──────────────┼───────────────┼──────────────┼───────────────┤
│ First column │ Second column │ Third column │ Fourth column │
└──────────────┴───────────────┴──────────────┴───────────────┘
┌ Info: Some message
│   alpha = 0.6824375271871292
└   beta = 0.04138740536726648

│          163 │          3035 │
├──────────────┼───────────────┤
│ First column │ Second column │
└──────────────┴───────────────┘

I think it's important that we still can print non-table logs. Also, it's not difficult to transform "flat" messages to table messages using LoggingExtras.jl. I think explicit API like table makes transformation easier.

Another vague thought I've had is that the frontend @info usage could somehow hint at the formatting to be used, somehow independently of the key value pairs, or via the types of the values.

This is something I've been wondering: do we want an "open" API or a "centralized" API?

For progress logging, "open" API is something like the current situation that the frontend and backend just need to follow some specification. By "centralized" API, I mean it's something like JuliaLogging/ProgressLogging.jl#7 (comment) where you need to use a particular type for the progress value. The "open" API approach is nice because it's pretty light-weight but it's hard to enforce a particular specification. OTOH, the "centralized" API is nice because what API you are using is explicit (and you can version it using SemVer of the "base" package).

I really didn't expect to see var"" turning up in so many places.

It's pretty handy! Thanks a lot for implementing this :)

[tkf]

Here is a screen capture:

Code

using Logging
using TerminalLoggers
using VegaDatasets
using Tables
using Printf
using ProgressLogging

with_logger(TerminalLogger()) do
    limit = 10
    @progress for (i, row) in enumerate(Iterators.take(Tables.rows(dataset("cars")), limit))
        @info "" table = (
            Name = (@sprintf "%35s" row.Name),
            Year = row.Year,
            var"Miles per Gallon" = row.Miles_per_Gallon,
        ) _id = :outer
        sleep(0.5)
        for key in propertynames(row)
            if key ∉ (:Name, :Year, :Miles_per_Gallon)
                @info "" table = (
                    Variable = (@sprintf "%20s" key),
                    Value = getproperty(row, key),
                ) _id = :inner
            end
            sleep(0.01)
        end
        if i % 3 == 0
            @info "Non-table message example." i
        elseif i % 4 == 0
            @info "" table = nothing _id = :inner
            @info "Removed the inner table."
            sleep(1)
        end
    end
    @info "" table = nothing _id = :inner
    @info "" table = nothing _id = :outer
end

[c42f]

This is something I've been wondering: do we want an "open" API or a "centralized" API?

Yes, a very good question. We seem to have several possible designs which are quite different for this stuff.

1. Attach semantic to the key names, as currently done for progress. Upside - no dependencies; big downside - no way to add new meaning for keys without possibly breaking user code.
2. Attach semantic to value types. Upside: allows older user-generated records to work with new backends. Small-ish downside: needs some centralization of these types. Another downside: what are the keys for? How does one process asdf=Progress(...)?
3. Somehow attach semantic to the record as a whole. For example, could the type of the message and the log level be somehow used together? Upside: allows keys to be grouped, and users to be specific about the meaning of their record as a whole. Possible downside: may encourage splitting of logs into several events when they should have been a single event. (I think a major benefit of the current design is that it encourages atomicity of events composed of several fields.)

Many difficulties come down to the fact that there's a flat namespace of keys with no separation between those which have some systematic semantic vs those which can be arbitrarily used by users to attach metadata they think "might be interesting".

[tkf]

Just for completeness, I think another option is to not use logging in the first place. I commented it in Discourse https://discourse.julialang.org/t/different-logging-output-between-juno-execute-and-julia-repl/30933/10

[c42f]

I think the system would have failed in its design goals if everyone needs to implement their own disparate APIs for filtering, routing, and display event streams.

But it's certainly possible to fail! As I said on discourse, it could be useful to try a separate progress logging system to get a feeling for what we're missing, if anything. Ultimately I would hope we can just add in the necessary feature or clarify the semantics of logging to cover the progress logging case better.

[tkf]

Looking at this again now, I realize that it'd be better to overload push! and pushfirst!.

[rveltz]

Hi,

What is the state of this?