replaced println() with LogLevel macros (issue #10)

railtoolkit · Jun 15, 2024 · 98a0fc4 · 98a0fc4
1 parent 6cf028e
commit 98a0fc4
Show file tree

Hide file tree

Showing 10 changed files with 152 additions and 136 deletions.
diff --git a/Project.toml b/Project.toml
@@ -8,6 +8,7 @@ DataFrames = "a93c6f00-e57d-5684-b7b6-d8193f3e46c0"
 Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
 JSONSchema = "7d188eb4-7ad8-530c-ae41-71a32a6d4692"
 Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
+LoggingExtras = "e6f89c97-d47a-5376-807f-9c37f3926c36"
 Statistics = "10745b16-79ce-11e8-11f9-7d13ad32a3b2"
 UUIDs = "cf7118a7-6976-5b1a-9a39-7adc72f591a4"
 YAML = "ddb6d928-2868-570f-bddf-ab3f9cf99eb6"

diff --git a/src/TrainRuns.jl b/src/TrainRuns.jl
@@ -10,7 +10,7 @@ module TrainRuns
 ## loading standard library packages
 using UUIDs, Dates, Statistics, Logging
 ## loading external packages
-using YAML, JSONSchema, DataFrames
+using YAML, JSONSchema, DataFrames, LoggingExtras
 
 export
 ## Interface
@@ -21,6 +21,9 @@ global g      = 9.80665  # acceleration due to gravity (in m/s^2)
 global μ      = 0.2      # friction as constant, TODO: implement as function
 global Δv_air = 15.0/3.6 # coefficient for velocitiy difference between train and outdoor air (in m/s)
 
+const Trace = Logging.LogLevel(-2000)
+const Fatal = Logging.LogLevel(3000)
+
 ## include package files
 include("types.jl")
 include("constructors.jl")
@@ -45,16 +48,21 @@ xxx.xx # in seconds
 """
 function trainrun(train::Train, path::Path, settings=Settings()::Settings)
 
-    logger = set_log_level(settings)
+    loglevel = get_loglevel(settings)
+    logger = LoggingExtras.LevelOverrideLogger(loglevel, global_logger()) # Bug - Log messages below LogLevel(-1000) are ignored
+    # workaround:
+    Logging.disable_logging(loglevel-1) # https://github.com/JuliaLang/julia/issues/52234
 
     with_logger(logger) do
+        @debug "" train
+        @debug "" path
+        @debug "" settings
+
         # prepare the input data
         (characteristicSections, poi_positions) = determineCharacteristics(path, train, settings)
-            # TODO settings.outputDetail == :verbose && println("The characteristics haven been determined.")
 
         # calculate the train run with the minimum running time
         drivingCourse = calculateMinimumRunningTime(characteristicSections, settings, train)
-            # TODO settings.outputDetail == :verbose && println("The driving course for the shortest running time has been calculated.")
 
         # accumulate data and create an output dictionary
         output = createOutput(settings, drivingCourse, poi_positions)

diff --git a/src/behavior.jl b/src/behavior.jl
diff --git a/src/calc.jl b/src/calc.jl
@@ -107,10 +107,14 @@ function calculateMinimumRunningTime(CSs::Vector{Dict}, settings::Settings, trai
 
            # for testing:   # TODO
            if drivingCourse[end][:s] != CS[:s_exit]
-               println("ERROR: In CS", csId," the train run ends at s=",drivingCourse[end][:s]," and not s_exit=",CS[:s_exit])
+                pos1 = drivingCourse[end][:s]
+                pos2 = CS[:s_exit]
+                @warn "In CS $csId the train run ends at s=$pos1 and not s_exit=$pos2" drivingCourse CS
            end
            if drivingCourse[end][:v] > CS[:v_exit]
-               println("ERROR: In CS", csId," the train run ends with v=",drivingCourse[end][:v]," and not with v_exit=",CS[:v_exit])
+                speed1 = drivingCourse[end][:v]
+                speed2 = CS[:v_exit]
+                @warn "In CS $csId the train run ends with v=$speed1 and not with v_exit=$speed2" drivingCourse CS
            end
    end #for
 
@@ -142,7 +146,7 @@ julia> calculateTractiveEffort(30.0, [(0.0, 180000), (20.0, 100000), (40.0, 6000
 """
 function calculateTractiveEffort(v::AbstractFloat, tractiveEffortVelocityPairs::Array{})
     if v < 0.0
-        #println("v=",v)
+        @debug "v=$v"
         return 0.0
     end
 

diff --git a/src/constructors.jl b/src/constructors.jl
@@ -18,7 +18,7 @@ Create a settings object for [`trainrun`](@ref).
 - `approxLevel::Number=3`: used when rounding or iterating.
 - `outputDetail:Symbol`: `:running_time`_(default)_, `:points_of_interest`, `:data_points` or `:driving_course`
 - `outputFormat::Symbol`: `:dataframe`_(default)_ or `:vector`
-- `verbosity::Symbol`: `:unset`_(default)_, `:info`, `:debug`, `:warn`, or `:error`
+- `verbosity::Symbol`: `:unset`_(default)_, `:trace`, `:debug`, `:info`, `:warn`, `:error`, or `:fatal`
 
 # Example
 ```julia-repl
@@ -34,7 +34,7 @@ function Settings(
             approxLevel::Number  = 3,
             outputDetail::Symbol = :running_time,
             outputFormat::Symbol = :dataframe,
-            verbosity::Symbol    = :info
+            verbosity::Symbol    = :unset
         )
     ## load from file
     if file != "DEFAULT"
@@ -70,7 +70,7 @@ function Settings(
                 "verbosity": {
                     "description": "Output format",
                     "type": "string",
-                    "enum": [ "debug", "info", "warn", "error" ]
+                    "enum": [ "unset", "trace", "debug", "info", "warn", "error", "fatal" ]
                 }
             }
         }""")
@@ -79,7 +79,7 @@ function Settings(
 
         ## validate the loaded file
         if !isvalid(schema, settings)
-            println("Could not load settings file '$file'.\n Format is not recognized - using default as fall back.")
+            @warn "Could not load settings file '$file'. Format is not recognized!" "Using default as fall back."
             settings = Dict()
         end
 
@@ -127,7 +127,7 @@ function Path(file, type = :YAML)
     if type == :YAML
 
         ## error messages
-        format_error = "\n\tCould not parse file '$file'.\n\tNot a valide railtoolkit/schema format.\n\tCurrently supported version: 2022.05\n\tFor the format see: https://github.com/railtoolkit/schema"
+        error_msg_format = "\n\tCould not parse file '$file'.\n\tNot a valide railtoolkit/schema format.\n\tCurrently supported version: 2022.05\n\tFor the format see: https://github.com/railtoolkit/schema"
 
         ## JSON schema for YAML-file validation
         railtoolkit_schema = Schema("""{
@@ -212,11 +212,11 @@ function Path(file, type = :YAML)
         }""")
 
         data = YAML.load(open(file))
-        data["schema"] == "https://railtoolkit.org/schema/running-path.json" ? nothing : throw(DomainError(data["schema"],format_error))
-        data["schema_version"] == "2022.05"                                  ? nothing : throw(DomainError(data["schema_version"],format_error))
-        isvalid(railtoolkit_schema, data["paths"])                           ? nothing : throw(DomainError(data["paths"],format_error))
+        data["schema"] == "https://railtoolkit.org/schema/running-path.json" ? nothing : throw(DomainError(data["schema"],error_msg_format))
+        data["schema_version"] == "2022.05"                                  ? nothing : throw(DomainError(data["schema_version"],error_msg_format))
+        isvalid(railtoolkit_schema, data["paths"])                           ? nothing : throw(DomainError(data["paths"],error_msg_format))
 
-        length(data["paths"]) > 1 ? println("WARNING: the loaded file contains more than one path. Using only the first!") : nothing
+        length(data["paths"]) > 1 ? (@warn "The loaded file contains more than one path. Using only the first!") : nothing
         path = data["paths"][1]
 
         ## set the variables in "path"
@@ -391,7 +391,7 @@ function Train(file, type = :YAML)
     if type == :YAML
 
         ## error messages
-        format_error = "\n\tCould not parse file '$file'.\n\tNot a valide railtoolkit/schema format.\n\tCurrently supported version: 2022.05\n\tFor the format see: https://github.com/railtoolkit/schema"
+        error_msg_format = "\n\tCould not parse file '$file'.\n\tNot a valide railtoolkit/schema format.\n\tCurrently supported version: 2022.05\n\tFor the format see: https://github.com/railtoolkit/schema"
 
         ## JSON schema for YAML-file validation
         railtoolkit_schema = Schema("""{
@@ -544,16 +544,16 @@ function Train(file, type = :YAML)
 
         ## validation
         data = YAML.load(open(file))
-        data["schema"] == "https://railtoolkit.org/schema/rolling-stock.json" ? nothing : throw(DomainError(data["schema"],format_error))
-        data["schema_version"] == "2022.05"                                   ? nothing : throw(DomainError(data["schema_version"],format_error))
-        isvalid(railtoolkit_schema, data)                                     ? nothing : throw(DomainError(data,format_error))
+        data["schema"] == "https://railtoolkit.org/schema/rolling-stock.json" ? nothing : throw(DomainError(data["schema"],error_msg_format))
+        data["schema_version"] == "2022.05"                                   ? nothing : throw(DomainError(data["schema_version"],error_msg_format))
+        isvalid(railtoolkit_schema, data)                                     ? nothing : throw(DomainError(data,error_msg_format))
 
     else
         throw(DomainError("Unknown file type '$type'"))
     end #if type
 
     trains = data["trains"]
-    Base.length(trains) > 1 ? println("WARNING: the loaded file contains more than one train. Using only the first!") : nothing
+    Base.length(trains) > 1 ? (@warn "The loaded file contains more than one train. Using only the first!") : nothing
     Base.length(trains) == 0 ? throw(DomainError("No train present in file '$file'")) : nothing
     train = trains[1]
     used_vehicles = unique(train["formation"])
@@ -608,8 +608,8 @@ function Train(file, type = :YAML)
             deleteat!(vehicles, i)
         end
     end
-    Base.length(loco)  > 1 ? println("WARNING: the loaded file contains more than one traction unit or multiple unit. Using only the first!") : nothing
-    loco[1].n     > 1 ? println("WARNING: the loaded file contains more than one traction unit or multiple unit. Using only one!") : nothing
+    Base.length(loco)  > 1 ? (@warn "The loaded file contains more than one traction unit or multiple unit. Using only the first!") : nothing
+    loco[1].n          > 1 ? (@warn "The loaded file contains more than one traction unit or multiple unit. Using only one!") : nothing
     Base.length(loco) == 0 ? throw(DomainError("No traction unit or multiple unit present in file '$file'")) : nothing
     loco = loco[1].data
     cars = vehicles

diff --git a/src/output.jl b/src/output.jl
@@ -132,20 +132,33 @@ function createDataFrame(output_vector::Vector{Dict}, outputDetail::Symbol, appr
     return dataFrame
 end #createDataFrame
 
-function set_log_level(settings::Settings)::AbstractLogger
-    log_level = settings.verbosity
-    @debug "Changing log level to `$log_level`."
-    if     log_level == :info
-        logger = ConsoleLogger(stderr, Logging.Info)
-    elseif log_level == :debug
-        logger = ConsoleLogger(stderr, Logging.Debug)
-    elseif log_level == :warn
-        logger = ConsoleLogger(stderr, Logging.Warn)
-    elseif log_level == :error
-        logger = ConsoleLogger(stderr, Logging.Error)
+function get_loglevel(settings::Settings)::LogLevel
+    current_logger = global_logger()
+    if settings.verbosity != :unset
+        current_level = lowercase(String(Symbol(current_logger.min_level)))
+        new_level = String(settings.verbosity)
+        if current_level != new_level
+            @debug "Changing log level from `$current_level` to `$new_level`."
+            if settings.verbosity == :trace
+                loglevel = Trace
+            elseif settings.verbosity == :debug
+                loglevel = Logging.Debug
+            elseif settings.verbosity == :info
+                loglevel = Logging.Info
+            elseif settings.verbosity == :warn
+                loglevel = Logging.Warn
+            elseif settings.verbosity == :error
+                loglevel = Logging.Error
+            elseif settings.verbosity == :fatal
+                loglevel = Fatal
+            else
+                @warn "Did not recognize the log level `$new_level`." "Log level was not changed!"
+            end
+        else
+            loglevel = current_logger.min_level
+        end
     else
-        @warn "Did not recognize the log level `$new_level`." "Log level was set to :info!"
-        logger = ConsoleLogger(stderr, Logging.Info)
+        loglevel = current_logger.min_level
     end
-    return logger
+    return loglevel
 end
diff --git a/src/types.jl b/src/types.jl
@@ -13,7 +13,7 @@ struct Settings
     outputDetail::Symbol # single Float() ":running_time", Vector() of ":points_of_interest", Vector() of ":data_points"
                          # or complete Vector() ":driving_course"
     outputFormat::Symbol # output as ":dataframe" or as ":vector".
-    verbosity::Symbol    # logging levels :debug, :info (default), :warn, and :error
+    verbosity::Symbol    # logging levels :unset (default), :trace, :debug, :info, :warn, :error, and :fatal
 
 end #struct Settings
 

diff --git a/test/logging_levels.jl b/test/logging_levels.jl
@@ -0,0 +1,34 @@
+#!/usr/bin/env julia
+# -*- coding: UTF-8 -*-
+# __julia-version__ = 1.10.0
+# __author__        = "Martin Scheidt"
+# __copyright__     = "2024"
+# __license__       = "ISC"
+
+using Logging
+
+function log_messages()
+    # @logmsg TrainRuns.Trace "trace" # currently no macro for testing self defined loglevels
+    @debug "debug"
+    @info  "info"
+    @warn  "warn"
+    @error "error"
+    # @logmsg TrainRuns.Fatal "fatal" # currently no macro for testing self defined loglevels
+end
+
+@testset "logging levels" begin
+    logger = ConsoleLogger(TrainRuns.get_loglevel(Settings(verbosity = :trace)))
+     # currently no macro for testing self defined loglevels
+     # TODO: add @test_logs (:trace, "trace") (:fatal, "fatal")
+    with_logger(logger) do
+        @test_logs (:debug, "debug") (:info,  "info") (:warn,  "warn") (:error, "error") min_level=TrainRuns.Trace log_messages()
+    end
+
+    @test TrainRuns.get_loglevel(Settings(verbosity = :trace)) == LogLevel(-2000)
+    @test TrainRuns.get_loglevel(Settings(verbosity = :debug)) == LogLevel(-1000)
+    @test TrainRuns.get_loglevel(Settings(verbosity = :info))  == LogLevel(0)
+    @test TrainRuns.get_loglevel(Settings())                   == LogLevel(0)
+    @test TrainRuns.get_loglevel(Settings(verbosity = :warn))  == LogLevel(1000)
+    @test TrainRuns.get_loglevel(Settings(verbosity = :error)) == LogLevel(2000)
+    @test TrainRuns.get_loglevel(Settings(verbosity = :fatal)) == LogLevel(3000)
+end
diff --git a/test/logging_test.jl b/test/logging_test.jl
diff --git a/test/runtests.jl b/test/runtests.jl
@@ -7,5 +7,5 @@
 
 using TrainRuns, Test
 
-include("logging_test.jl")
+include("logging_levels.jl")
 include("highlevel_test.jl")