Verbosity System [Very Rough Draft]

[jClugstor]

This is a very early rough draft of the verbosity system described in SciML/SciMLBase.jl#962.

It closely follows what was written there. I wanted to put this here as a demo of what this could look like, but likely the final definitions etc. will be located in SciMLBase.

The basic idea is that there's an ODEVerbosity type, which has fields error_control, performance, and numerical, which are ODEErrorControlVerbosity, ODEPerformanceVerbosity, and ODENumericalVerbosity. ODEVerbosity also has a Bool type parameter, that just represents a toggle determining whether there will be any log messages that are emitted. The reason it's a type parameter is so that the code that creates the error messages can be statically determined to not run. I'm not sure it's necessary for that to work yet though. ODEErrorControlVerbosity etc. holds fields that will toggle individual log messages. The "types" of each field will determine what log message level is emitted, there's also an option to emit no log message. The verbosity levels are defined as a Moshi.jl ADT, which provides namespacing for the Verbosity types, and exhaustive pattern matching. This can be changed pretty easily, but it matches the namespacing of enums in the issue linked.

The ODEVerbosity is held in the DEOptions object in the integrator. The verbosity object is callable, with two different methods. One is (verbose::ODEVerbosity)(message, option, group, values...), which emits message, at the level set by option. group represent which of error control, performance, or numerical this message falls under, and will be included in the metadata for the log message and can be used for filtering. (verbose::ODEVerbosity)(f::Function, option, values...) will run the function and use the return value as the log message, and facilitate the do block syntax and allow for things like:

  integrator.opts.verbose(:thing1, :error_control) do 
        "message is $(tdir * dt₀)"
    end

so that the message can involve calculated information. If the ODEVerbosity type parameter is false, calling the verbosity object goes to an empty function. Also, if the toggle in the ODEVerbosity is Verbosity.None() the function does not get run.

I kept the "choosing what is printed and at what level" separate from "choosing where each level goes", which can be handled by the logger. We can provide an ODELogger function that's just creates a composition of loggers from LoggingExtras with some convenient options for toggling REPL printing and printing to files. We might want to add a with_logger somewhere and have a logger keyword argument, but that does make stacktraces and using the debugger a lot more annoying, so maybe if logger is nothing it bypasses the with_logger.

using LoggingExtras
using OrdinaryDiffEq
using OrdinaryDiffEqCore

function lorenz!(du, u, p, t)
    du[1] = 10.0 * (u[2] - u[1])
    du[2] = u[1] * (28.0 - u[3]) - u[2]
    du[3] = u[1] * u[2] - (8 / 3) * u[3]
end

u0 = [1.0; 0.0; 0.0]
tspan = (0.0, 0.5)
prob = ODEProblem(lorenz!, u0, tspan)


error_control = OrdinaryDiffEqCore.ODEErrorControlVerbosity(OrdinaryDiffEqCore.Verbosity.Warn())

performance = OrdinaryDiffEqCore.ODEPerformanceVerbosity(OrdinaryDiffEqCore.Verbosity.Info(), OrdinaryDiffEqCore.Verbosity.Warn())

numerical = OrdinaryDiffEqCore.ODENumericalVerbosity(OrdinaryDiffEqCore.Verbosity.Error(), OrdinaryDiffEqCore.Verbosity.Level(93))

verb = OrdinaryDiffEqCore.ODEVerbosity{true}(error_control, performance, numerical)

sol = solve(prob, Rodas5(), verbose=verb)

┌ Warning: message is 3.5678604836301404e-7
└ @ OrdinaryDiffEqCore ~/Documents/Work/dev/OrdinaryDiffEq.jl/lib/OrdinaryDiffEqCore/src/verbosity.jl:116
[ Info: Length is greater than zero.
┌ Error: Some serious numerical issue!
│   values = ()
└ @ OrdinaryDiffEqCore ~/Documents/Work/dev/OrdinaryDiffEq.jl/lib/OrdinaryDiffEqCore/src/verbosity.jl:107
┌ LogLevel(93): Some other numerical issue!
└   values = ()

sol = solve(prob, Rodas5(), verbose=OrdinaryDiffEqCore.ODEVerbosity(OrdinaryDiffEqCore.Verbosity.None()))

We can define a helper function that just constructs a composition of loggers from LoggingExtras. In order to make this really easy for users we might want to make this a keyword argument that passes to a with_logger, so we could just do something like
solve(prob, verbose = ODEVerbosity(Verbosity.Default()), logger = ODELogger(info_file = "info.txt", info_repl = false)) for example.

I think by using specific combinations of ODEVerbosity settings and custom loggers

function ODELogger(; info_repl=true, warn_repl=true, error_repl=true, info_file=nothing, warn_file=nothing, error_file=nothing)
    info_sink = isnothing(info_file) ? NullLogger() : FileLogger(info_file)
    warn_sink = isnothing(warn_file) ? NullLogger() : FileLogger(warn_file)
    error_sink = isnothing(error_file) ? NullLogger() : FileLogger(error_file)

    repl_filter = EarlyFilteredLogger(current_logger()) do log
        if log.level == Logging.Info && info_repl
            return true
        end

        if log.level == Logging.Warn && warn_repl
            return true
        end

        if log.level == Logging.Error && error_repl
            return true
        end

        return false
    end

    info_filter = EarlyFilteredLogger(info_sink) do log
        log.level == Logging.Info
    end

    warn_filter = EarlyFilteredLogger(warn_sink) do log
        log.level == Logging.Warn
    end

    error_filter = EarlyFilteredLogger(error_sink) do log
        log.level == Logging.Error
    end


    TeeLogger(repl_filter, info_filter, warn_filter, error_filter)

end

logger = ODELogger(info_repl=true, warn_repl=true, error_repl=true, info_file="info.txt", warn_file="warn.txt")

with_logger(logger) do 
    sol = solve(prob, Rodas5(), verbose=verb)
end

[oscardssmith]

what's this?

[jClugstor]

There are only two uses of the verbose keyword in OrdinaryDiffEq so I had to make some up for demo purposes. In reality these will all be options that toggle error messages related to error control.

[jClugstor]

I also want to add a macro for this so that we can automatically get the correct line number, file, and module using __source__.

[jClugstor]

Switched to using a macro, now you can just write

@SciMLMessage(integrator.opts.verbose, :thing1, :error_control) do
        "u₁ is $u₁"
 end

or

@SciMLMessage("This is a logging message", integrator.opts.verbose, :thing3, :numerical)

and it will automatically get the correct file name, line, and module.

May need to think about hygiene more though.

[ChrisRackauckas]

This isn't a numerical issue. It's an error or control flow one

[ChrisRackauckas]

This doesn't make much sense to track

[ChrisRackauckas]

This isn't necessary

[jClugstor]

The specific messages here are more for demonstration purposes, I made some up to show that the macro works, this one demonstrates that you can write a do-block involving the outside variables and the result will be put in the log.

If it makes sense to do it this way, most of this stuff should be moved to SciMLBase and then we can start writing error messages using the macro.

[ChrisRackauckas]

The verbosity system looks right. I think we can start the move of the interface to SciMLBase

[ChrisRackauckas]

Type stability