Skip to content

Commit

Permalink
Logger writes to both Terminal and File (#911)
Browse files Browse the repository at this point in the history
Fixes #502 
Fixes #747

Using `LoggingExtras` as a basis to write logs to two places at the same
time.
The verbosity only applies to the file logger.
The terminal logger will always be on Progress level (-1).

The settings.json was adjusted to exclude some folders that do not help
in our development.

---------

Co-authored-by: Martijn Visser <[email protected]>
  • Loading branch information
deltamarnix and visr authored Jan 11, 2024
1 parent a3c91ea commit ee626c3
Show file tree
Hide file tree
Showing 19 changed files with 287 additions and 123 deletions.
7 changes: 6 additions & 1 deletion .vscode/settings.json
Original file line number Diff line number Diff line change
Expand Up @@ -22,5 +22,10 @@
"."
],
"python.testing.unittestEnabled": false,
"python.testing.pytestEnabled": true
"python.testing.pytestEnabled": true,
"julia.lint.disabledDirs": [
".pixi",
"utils/juliaup"
],
"julia.lint.run": true
}
36 changes: 36 additions & 0 deletions Manifest.toml
Original file line number Diff line number Diff line change
Expand Up @@ -159,6 +159,12 @@ git-tree-sha1 = "70232f82ffaab9dc52585e0dd043b5e0c6b714f1"
uuid = "fb6a15b2-703c-40df-9091-08a04967cfa9"
version = "0.1.12"

[[deps.CodeTracking]]
deps = ["InteractiveUtils", "UUIDs"]
git-tree-sha1 = "c0216e792f518b39b22212127d4a84dc31e4e386"
uuid = "da1fd8a2-8d9e-5ec2-8556-3022fb5608a2"
version = "1.3.5"

[[deps.CodecBzip2]]
deps = ["Bzip2_jll", "Libdl", "TranscodingStreams"]
git-tree-sha1 = "c0ae2a86b162fb5d7acc65269b469ff5b8a73594"
Expand Down Expand Up @@ -715,6 +721,12 @@ version = "1.16.0"
[deps.JuMP.weakdeps]
DimensionalData = "0703355e-b756-11e9-17c0-8b28908087d0"

[[deps.JuliaInterpreter]]
deps = ["CodeTracking", "InteractiveUtils", "Random", "UUIDs"]
git-tree-sha1 = "e49bce680c109bc86e3e75ebcb15040d6ad9e1d3"
uuid = "aa1ae85d-cabe-5617-a682-6adf51b2e16a"
version = "0.9.27"

[[deps.KLU]]
deps = ["LinearAlgebra", "SparseArrays", "SuiteSparse_jll"]
git-tree-sha1 = "884c2968c2e8e7e6bf5956af88cb46aa745c854b"
Expand Down Expand Up @@ -873,6 +885,12 @@ weakdeps = ["ChainRulesCore", "ForwardDiff", "SpecialFunctions"]
ForwardDiffExt = ["ChainRulesCore", "ForwardDiff"]
SpecialFunctionsExt = "SpecialFunctions"

[[deps.LoweredCodeUtils]]
deps = ["JuliaInterpreter"]
git-tree-sha1 = "0b8cf121228f7dae022700c1c11ac1f04122f384"
uuid = "6f1432cf-f94c-5a45-995e-cdbf5db27b0b"
version = "2.3.2"

[[deps.Lz4_jll]]
deps = ["Artifacts", "JLLWrappers", "Libdl"]
git-tree-sha1 = "6c26c5e8a4203d43b5497be3ec5d4e0c3cde240a"
Expand Down Expand Up @@ -1147,6 +1165,12 @@ uuid = "3fa0cd96-eef1-5676-8a61-b3b8758bbffb"
deps = ["SHA"]
uuid = "9a3f8284-a2c9-5f02-9a11-845980a1fd5c"

[[deps.ReTestItems]]
deps = ["Dates", "Logging", "LoggingExtras", "Pkg", "Serialization", "Sockets", "Test", "TestEnv"]
git-tree-sha1 = "e8dd0646b221f3b75af2f36f83f509e2dde8dbe8"
uuid = "817f1d60-ba6b-4fd5-9520-3cf149f6a823"
version = "1.22.0"

[[deps.RecipesBase]]
deps = ["PrecompileTools"]
git-tree-sha1 = "5c3d09cc4f31f5fc6af001c250bf1278733100ff"
Expand Down Expand Up @@ -1194,6 +1218,12 @@ git-tree-sha1 = "838a3a4188e2ded87a4f9f184b4b0d78a1e91cb7"
uuid = "ae029012-a4dd-5104-9daa-d747884805df"
version = "1.3.0"

[[deps.Revise]]
deps = ["CodeTracking", "Distributed", "FileWatching", "JuliaInterpreter", "LibGit2", "LoweredCodeUtils", "OrderedCollections", "Pkg", "REPL", "Requires", "UUIDs", "Unicode"]
git-tree-sha1 = "6990168abf3fe9a6e34ebb0e05aaaddf6572189e"
uuid = "295af30f-e4ad-537b-8983-00126c2a3abe"
version = "3.5.10"

[[deps.Ribasim]]
deps = ["Accessors", "Arrow", "BasicModelInterface", "CodecLz4", "CodecZstd", "ComponentArrays", "Configurations", "DBInterface", "DataInterpolations", "DataStructures", "Dates", "Dictionaries", "DiffEqCallbacks", "EnumX", "FiniteDiff", "ForwardDiff", "Graphs", "HiGHS", "IterTools", "JuMP", "Legolas", "Logging", "LoggingExtras", "MetaGraphsNext", "OrdinaryDiffEq", "PreallocationTools", "SQLite", "SciMLBase", "SparseArrays", "StructArrays", "Tables", "TerminalLoggers", "TimeZones", "TimerOutputs", "TranscodingStreams"]
path = "core"
Expand Down Expand Up @@ -1506,6 +1536,12 @@ version = "0.1.7"
deps = ["InteractiveUtils", "Logging", "Random", "Serialization"]
uuid = "8dfed614-e22c-5e08-85e1-65c5234f0b40"

[[deps.TestEnv]]
deps = ["Pkg"]
git-tree-sha1 = "c35f69c951ac4f74b8b074f62dfb1e169b351497"
uuid = "1e6cf692-eddd-4d53-88a5-2d735e33781b"
version = "1.101.1"

[[deps.ThreadingUtilities]]
deps = ["ManualMemory"]
git-tree-sha1 = "eda08f7e9818eb53661b3deb74e3159460dfbc27"
Expand Down
3 changes: 3 additions & 0 deletions Project.toml
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,10 @@ authors = ["Deltares and contributors <[email protected]>"]
description = "Meta-project used to share the Manifest of Ribasim and its dependents"

[deps]
ReTestItems = "817f1d60-ba6b-4fd5-9520-3cf149f6a823"
Revise = "295af30f-e4ad-537b-8983-00126c2a3abe"
Ribasim = "aac5e3d9-0b8f-4d4f-8241-b1a7a9632635"
TestEnv = "1e6cf692-eddd-4d53-88a5-2d735e33781b"
TimeZones = "f269a46b-ccf7-5d73-abea-4c690281aa53"
create_binaries = "3cfb6a46-05f0-43df-bb16-bf763deb14b4"
docs = "8daea9ca-fc6c-4731-aa85-717fa0b706bc"
Expand Down
47 changes: 1 addition & 46 deletions build/ribasim_cli/src/ribasim_cli.jl
Original file line number Diff line number Diff line change
@@ -1,52 +1,7 @@
module ribasim_cli

using Logging: global_logger, with_logger
using TerminalLoggers: TerminalLogger
using SciMLBase: successful_retcode
using Ribasim

function help(x)::Cint
println(x)
println("Usage: ribasim path/to/model/ribasim.toml")
return 1
end

function julia_main()::Cint
n = length(ARGS)
if n != 1
return help("Exactly 1 argument expected, got $n")
end
arg = only(ARGS)

if arg == "--version"
version = pkgversion(Ribasim)
print(version)
return 0
end

if !isfile(arg)
return help("File not found: $arg")
end

try
# show progress bar in terminal
model = with_logger(TerminalLogger()) do
Ribasim.run(arg)
end
return if successful_retcode(model)
println("The model finished successfully")
0
else
t = Ribasim.datetime_since(model.integrator.t, model.config.starttime)
retcode = model.integrator.sol.retcode
println("The model exited at model time $t with return code $retcode")
println("See https://docs.sciml.ai/DiffEqDocs/stable/basics/solution/#retcodes")
1
end
catch
Base.invokelatest(Base.display_error, current_exceptions())
return 1
end
end
julia_main()::Cint = Ribasim.main(ARGS)

end # module
7 changes: 5 additions & 2 deletions core/src/Ribasim.jl
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ import BasicModelInterface as BMI
import HiGHS
import JuMP
import TranscodingStreams
import LoggingExtras

using Accessors: @set
using Arrow: Arrow, Table
Expand Down Expand Up @@ -46,8 +47,7 @@ using Graphs:
rem_edge!

using Legolas: Legolas, @schema, @version, validate, SchemaVersion, declared
using Logging: current_logger, min_enabled_level, with_logger
using LoggingExtras: EarlyFilteredLogger, LevelOverrideLogger
using Logging: with_logger, LogLevel, AbstractLogger
using MetaGraphsNext:
MetaGraphsNext,
MetaGraph,
Expand All @@ -60,6 +60,7 @@ using OrdinaryDiffEq
using OrdinaryDiffEq: OrdinaryDiffEqRosenbrockAdaptiveAlgorithm
using PreallocationTools: DiffCache, FixedSizeDiffCache, get_tmp
using SciMLBase
using SciMLBase: successful_retcode
using SparseArrays
using SQLite: SQLite, DB, Query, esc_id
using StructArrays: StructVector
Expand All @@ -74,12 +75,14 @@ include("validation.jl")
include("solve.jl")
include("config.jl")
using .config
include("logging.jl")
include("allocation.jl")
include("utils.jl")
include("lib.jl")
include("io.jl")
include("create.jl")
include("bmi.jl")
include("consts.jl")
include("main.jl")

end # module Ribasim
30 changes: 5 additions & 25 deletions core/src/bmi.jl
Original file line number Diff line number Diff line change
Expand Up @@ -663,34 +663,14 @@ BMI.get_time_step(model::Model) = get_proposed_dt(model.integrator)
"""
run(config_file::AbstractString)::Model
run(config::Config)::Model
Run a [`Model`](@ref), given a path to a TOML configuration file, or a Config object.
Running a model includes initialization, solving to the end with `[`solve!`](@ref)` and writing results with [`BMI.finalize`](@ref).
"""
run(config_file::AbstractString)::Model = run(Config(config_file))

function is_current_module(log)
(log._module == @__MODULE__) ||
(parentmodule(log._module) == @__MODULE__) ||
log._module == OrdinaryDiffEq # for the progress bar
end
run(config_path::AbstractString)::Model = run(Config(config_path))

function run(config::Config)::Model
logger = current_logger()

# Reconfigure the logger if necessary with the correct loglevel
# but make sure to only log from Ribasim
if min_enabled_level(logger) + 1 != config.logging.verbosity
logger = EarlyFilteredLogger(
is_current_module,
LevelOverrideLogger(config.logging.verbosity, logger),
)
end

with_logger(logger) do
model = Model(config)
solve!(model)
BMI.finalize(model)
return model
end
model = Model(config)
solve!(model)
BMI.finalize(model)
return model
end
28 changes: 28 additions & 0 deletions core/src/logging.jl
Original file line number Diff line number Diff line change
@@ -0,0 +1,28 @@
"""
is_current_module(log::LogMessageType)::Bool
Returns true if the log message is from the current module or a submodule.
See https://github.com/JuliaLogging/LoggingExtras.jl/blob/d35e7c8cfc197853ee336ace17182e6ed36dca24/src/CompositionalLoggers/earlyfiltered.jl#L39
for the information available in log.
"""
function is_current_module(log)::Bool
(log._module == @__MODULE__) ||
(parentmodule(log._module) == @__MODULE__) ||
log._module == OrdinaryDiffEq # for the progress bar
end

function setup_logger(;
verbosity::LogLevel,
stream::IOStream,
module_filter_function::Function = is_current_module,
)::AbstractLogger
file_logger = LoggingExtras.MinLevelLogger(LoggingExtras.FileLogger(stream), verbosity)
terminal_logger = LoggingExtras.MinLevelLogger(
TerminalLogger(),
LogLevel(-1), # To include progress bar
)
return LoggingExtras.EarlyFilteredLogger(
module_filter_function,
LoggingExtras.TeeLogger(file_logger, terminal_logger),
)
end
56 changes: 56 additions & 0 deletions core/src/main.jl
Original file line number Diff line number Diff line change
@@ -0,0 +1,56 @@
function help(x::AbstractString)::Cint
println(x)
println("Usage: ribasim path/to/model/ribasim.toml")
return 1
end

main(toml_path::AbstractString)::Cint = main([toml_path])

"""
main(ARGS::Vector{String})::Cint
This is the main entry point of the application.
Performs argument parsing and sets up logging for both terminal and file.
Calls Ribasim.run() and handles exceptions to convert to exit codes.
"""
function main(ARGS::Vector{String})::Cint
n = length(ARGS)
if n != 1
return help("Exactly 1 argument expected, got $n")
end
arg = only(ARGS)

if arg == "--version"
version = pkgversion(Ribasim)
print(version)
return 0
end

if !isfile(arg)
return help("File not found: $arg")
end

try
# show progress bar in terminal
config = Config(arg)
mkpath(results_path(config, "."))
open(results_path(config, "ribasim.log"), "w") do io
logger =
Ribasim.setup_logger(; verbosity = config.logging.verbosity, stream = io)
with_logger(logger) do
model = Ribasim.run(config)
if successful_retcode(model)
@info "The model finished successfully"
return 0
end

t = Ribasim.datetime_since(model.integrator.t, model.config.starttime)
retcode = model.integrator.sol.retcode
@error "The model exited at model time $t with return code $retcode.\nSee https://docs.sciml.ai/DiffEqDocs/stable/basics/solution/#retcodes"
return 1
end
end
catch
Base.invokelatest(Base.display_error, current_exceptions())
return 1
end
end
38 changes: 0 additions & 38 deletions core/test/cli_test.jl

This file was deleted.

2 changes: 1 addition & 1 deletion core/test/config_test.jl
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@
using Dates

@testset "testrun" begin
config = Ribasim.Config(normpath(@__DIR__, "testrun.toml"))
config = Ribasim.Config(normpath(@__DIR__, "data", "config_test.toml"))
@test config isa Ribasim.Config
@test config.endtime > config.starttime
@test config.solver == Ribasim.Solver(; saveat = 86400.0)
Expand Down
4 changes: 2 additions & 2 deletions core/test/testrun.toml → core/test/data/config_test.toml
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,8 @@ starttime = 2019-01-01
endtime = 2019-12-31

# optional, default is the path of the TOML
input_dir = "../generated_testmodels/lhm"
results_dir = "../generated_testmodels/lhm"
input_dir = "../../generated_testmodels/lhm"
results_dir = "../../generated_testmodels/lhm"

database = "database.gpkg"

Expand Down
7 changes: 7 additions & 0 deletions core/test/data/logging_test_loglevel_debug.toml
Original file line number Diff line number Diff line change
@@ -0,0 +1,7 @@
starttime = 2019-01-01
endtime = 2019-12-31
input_dir = "."
results_dir = "results"

[logging]
verbosity = "debug"
4 changes: 4 additions & 0 deletions core/test/data/logging_test_no_loglevel.toml
Original file line number Diff line number Diff line change
@@ -0,0 +1,4 @@
starttime = 2019-01-01
endtime = 2019-12-31
input_dir = "."
results_dir = "results"
Loading

0 comments on commit ee626c3

Please sign in to comment.