Fixed @test_logs issue, code cleanup

src/Persephone.jl

@@ -20,11 +20,17 @@ using
     GeoArrays, #XXX this is a big dependency - can we get rid of it?
     Logging,
     LoggingExtras,
-    #MacroTools, #may be useful: http://fluxml.ai/MacroTools.jl/stable/utilities/
     Random,
     StableRNGs,
     TOML
 
+## Packages to check out:
+# MacroTools, http://fluxml.ai/MacroTools.jl/stable/utilities/
+# Debugger, https://github.com/JuliaDebug/Debugger.jl
+# Makie, https://docs.makie.org/stable/
+# PackageCompiler, https://julialang.github.io/PackageCompiler.jl/stable/
+# SpatialEcology, https://github.com/EcoJulia/SpatialEcology.jl
+
 ## define exported functions and variables
 export
     #types

src/core/input.jl

@@ -64,14 +64,19 @@ function getsettings(configfile::String, seed::Union{Int64,Nothing}=nothing)
             end
         end
     end
-    # pre-process certain parameters
-    if !isnothing(seed)
-        settings["core.seed"] = seed
-    end
-    if settings["core.seed"] == 0
-        settings["core.seed"] = abs(rand(RandomDevice(), Int32))
+    !isnothing(seed) && (settings["core.seed"] = seed)
+    settings["internal.scanparams"] = scanparams
+    preprocessparameters(settings, defaults["core.outdir"])
 end
-    defaultoutdir = defaults["core.outdir"]
+
+"""
+    preprocessparameters(settings)
+
+Take the raw input parameters and process them (convert types, perform checks, etc.).
+This is a helper function for `getsettings()`.
+"""
+function preprocessparameters(settings::Dict{String,Any}, defaultoutdir::String)
+    (settings["core.seed"] == 0) && (settings["core.seed"] = abs(rand(RandomDevice(), Int32)))
     if settings["core.outdir"] == defaultoutdir
         outdir = defaultoutdir*"_"*string(Dates.today())*"_s"*string(settings["core.seed"])
         settings["core.outdir"] = outdir
@@ -79,8 +84,15 @@ function getsettings(configfile::String, seed::Union{Int64,Nothing}=nothing)
     if settings["core.startdate"] > settings["core.enddate"]
         Base.error("Enddate is earlier than startdate.") #TODO replace with exception
     end
-    !isempty(scanparams) && addprocs(settings["core.processors"])
-    settings["internal.scanparams"] = scanparams
+    settings["core.loglevel"] == "debug" ? settings["core.loglevel"] = Logging.Debug :
+        settings["core.loglevel"] == "warn" ? settings["core.loglevel"] = Logging.Warn :
+        settings["core.loglevel"] = Logging.Info
+    if !isempty(settings["internal.scanparams"])
+        # https://docs.julialang.org/en/v1/manual/distributed-computing/#code-availability
+        addprocs(settings["core.processors"])
+        #addprocs(exeflags="--project") ?
+        @everywhere include("../Persephone.jl") #FIXME
+    end
     settings
 end
 
@@ -90,7 +102,7 @@ end
 An internal utility function to convert the two-dimensional dict returned
 by `TOML.parsefile()` into a one-dimensional dict, so that instead of
 writing `settings["domain"]["param"]` one can use `settings["domain.param"]`.
-Can be reversed with `expandTOML()`.
+Can be reversed with `prepareTOML()`.
 """
 function flattenTOML(tomldict)
     flatdict = Dict{String, Any}()
@@ -127,7 +139,7 @@ function parsecommandline()
             arg_type = String
             required = false
         "--loglevel", "-l"
-            help = "verbosity: \"debug\", \"info\", or \"quiet\""
+            help = "verbosity: \"debug\", \"info\", or \"warn\""
             arg_type = String
             required = false
     end

src/core/output.jl

@@ -22,36 +22,43 @@ function createdatadir(outdir::String, overwrite::Union{Bool,String})
             answer = readline()
             (answer == "yes") && (overwrite = true)
         end
-        if !overwrite
-            #TODO replace with exception
-            Base.error("Output directory exists, will not overwrite. Aborting.") 
-        else
+        !overwrite ? Base.error("Output directory exists, will not overwrite. Aborting.") :
             @warn "Overwriting existing output directory $(outdir)."
-        end
+        #TODO replace with exception
     end
     mkpath(outdir)
 end
 
 """
-    modellogger(logsetting, outdir)
+    modellogger(loglevel, outdir)
 
 Create a logger object that writes output both to screen and to a logfile.
 This object is stored as `model.logger` and can then be used with `with_logger()`.
 Note: requires `createdatadir()` to be run first.
 """
-function modellogger(logsetting::String, outdir::String)
+function modellogger(loglevel::LogLevel, outdir::String)
+    !isdir(outdir) && #TODO replace with exception
+        Base.error("$(outdir) does not exist. Call `createdatadir()` before `modellogger()`.")
     #XXX If this is a parallel run, should we turn off logging to screen?
-    loglevel = Logging.Info
-    if logsetting == "debug"
-        loglevel = Logging.Debug
-    elseif logsetting == "warn"
-        loglevel = Logging.Warn
-    end
     logfile = open(joinpath(outdir, LOGFILE), "w+")
     TeeLogger(ConsoleLogger(logfile, loglevel),
               ConsoleLogger(stdout, loglevel))
 end
 
+"""
+    withtestlogger(model)
+
+Replace the model logger with the currently active logger. This is intended to be
+used in the testsuite to circumvent a Julia issue, where @test_logs doesn't work
+with local loggers (https://github.com/JuliaLang/julia/issues/48456).
+"""
+function withtestlogger(model::AgentBasedModel)
+    # copied together from https://github.com/JuliaLang/julia/blob/master/base/logging.jl
+    logstate = current_task().logstate
+    logstate == nothing ? model.logger = global_logger() : model.logger = logstate.logger
+    model
+end
+
 """
     saveinputfiles(model)
 
@@ -59,6 +66,8 @@ Copy all input files into the output directory, including the actual parameter
 settings used. This allows replicating a run in future.
 """
 function saveinputfiles(model::AgentBasedModel)
+    #XXX If this is a parallel run, we should save the global config to the top-level
+    # output directory
     @debug "Setting up output directory $(@param(core.outdir))."
     currentcommit = read(`git rev-parse HEAD`, String)[1:8]
     open(joinpath(@param(core.outdir), basename(@param(core.configfile))), "w") do f
@@ -72,7 +81,7 @@ function saveinputfiles(model::AgentBasedModel)
             println(f, "# WARNING: Your repository contains uncommitted changes. This may")
             println(f, "#          compromise the reproducibility of this simulation run.\n")
         end
-        TOML.print(f, expandTOML(model.settings))
+        TOML.print(f, prepareTOML(model.settings))
     end
     # Copy the map files to the output folder
     lcmap = @param(core.landcovermap)
@@ -85,17 +94,23 @@ function saveinputfiles(model::AgentBasedModel)
 end
 
 """
-    expandTOML(dict)
+    prepareTOML(dict)
 
 An internal utility function to re-convert the one-dimensional dict created
-by `flattenTOML()` into the two-dimensional dict needed by `TOML.print()`.
+by `flattenTOML()` into the two-dimensional dict needed by `TOML.print()`,
+and convert any data types into TOML-compatible types where necessary.
 """
-function expandTOML(settingsdict)
+function prepareTOML(settings)
+    # convert data types
+    settings["core.loglevel"] == Logging.Debug ? settings["core.loglevel"] = "debug" :
+        settings["core.loglevel"] == Logging.Warn ? settings["core.loglevel"] = "warn" :
+        settings["core.loglevel"] = "info"
+    # convert dict structure
     fulldict = Dict{String, Dict{String, Any}}()
-    for parameter in keys(settingsdict)
+    for parameter in keys(settings)
         domain, param = split(parameter, ".")
         !(domain in keys(fulldict)) && (fulldict[domain] = Dict{String,Any}())
-        fulldict[domain][param] = settingsdict[parameter]
+        fulldict[domain][param] = settings[parameter]
     end
     fulldict
 end

src/nature/nature.jl

@@ -187,6 +187,7 @@ macro trait(traitname)
     # (i.e. outside of a @phase block). Although this is specified in the documentation,
     # it is unexpected and liable to be overlooked. Can we add a third clause to
     # compensate for that?
+    #TODO replace with `animal.traitname` syntax using `getproperty()`/`setproperty!()`
     if traitname in fieldnames(Animal)
         :($(esc(:animal)).$(traitname))
     else

test/io_tests.jl

@@ -4,6 +4,7 @@
 ###
 
 @testset "Model configuration" begin
+    # Test the configuration file
     settings = Ps.getsettings(TESTPARAMETERS)
     properties = Dict{Symbol,Any}(:settings=>settings)
     space = GridSpace((10,10), periodic=false)
@@ -11,10 +12,20 @@
 
     @test @param(core.configfile) == basename(TESTPARAMETERS)
     @test @param(core.startdate) == Date(2022, 2, 1)
+    @test @param(core.loglevel) == Logging.Warn
     @test @param(nature.targetspecies) == ["Wolpertinger", "Wyvern"]
     @param(core.enddate) = Date(2022,1,3)
     @test @param(core.enddate) == Date(2022,1,3)
-    #TODO test commandline parameters
+    # Test the parsing of commandline parameters
+    #XXX ARGS not recognised immediately - redefining a constant is problematic anyway
+    # Base.ARGS = ["--configfile", "test.toml", "-s", "314",
+    #              "--outdir", "random_results", "-l", "info"]
+    # settings = Ps.getsettings(TESTPARAMETERS)
+    # @test @param(core.configfile) == "test.toml"
+    # @test @param(core.seed) == 314
+    # @test @param(core.outdir) == "random_results"
+    # @test @param(core.loglevel) == Logging.Info
+    # Base.ARGS = []
 end
 
 @testset "Output functions" begin
@@ -24,18 +35,20 @@ end
     model = AgentBasedModel(Animal, space, properties=properties, warn=false)
     # test that the output directory is created with all files
     outdir = @param(core.outdir)
+    Ps.createdatadir(outdir, @param(core.overwrite))
+    @test isdir(outdir)
+    logger = Ps.modellogger(@param(core.loglevel), outdir)
     @test_logs((:debug, "Setting up output directory results_testsuite."),
                min_level=Logging.Debug, match_mode=:any,
-               Ps.setupdatadir(model))
-    @test isdir(outdir)
+               Ps.saveinputfiles(model))
     @test isfile(joinpath(outdir, @param(core.landcovermap)))
     @test isfile(joinpath(outdir, @param(core.farmfieldsmap)))
     @test isfile(joinpath(outdir, @param(core.configfile)))
     @test isfile(joinpath(outdir, Ps.LOGFILE))
     # check whether the overwrite warning/protection works
     logstring = "Overwriting existing output directory $(outdir)."
-    @test_logs (:warn, logstring) match_mode=:any Ps.setupdatadir(model)
-    #TODO test overwrite protection (requires parameter mutability)
+    #TODO test overwrite protection
+    @test_logs (:warn, logstring) match_mode=:any Ps.createdatadir(outdir, @param(core.overwrite))
     rm(outdir, force=true, recursive=true)
     #TODO test that creating a DataOutput works, and outputs data with the required frequency
 end

test/landscape_tests.jl

@@ -15,7 +15,7 @@ Create a 6x6 landscape with three land cover types for testing:
     F F G G G G
     F F G G G G
 """
-function smalltestlandscape(agenttype::Type=Animal)
+function smalltestlandscape()
     landscape = Matrix{Pixel}(undef, 6, 6)
     for x in 1:6
         for y in 1:6
@@ -28,9 +28,10 @@ function smalltestlandscape(agenttype::Type=Animal)
     properties = Dict{Symbol,Any}(:date=>TESTSETTINGS["core.startdate"],
                                   :landscape=>landscape,
                                   :events=>Vector{FarmEvent}(),
+                                  :logger=>global_logger(),
                                   :dataoutputs=>Vector{DataOutput}(),
                                   :settings=>TESTSETTINGS)
-    return AgentBasedModel(agenttype, space, properties=properties,
+    return AgentBasedModel(Union{Farmer,Animal,FarmPlot}, space, properties=properties,
                            rng=StableRNG(TESTSETTINGS["core.seed"]), warn=false)
 end
 
@@ -62,11 +63,15 @@ end
     @test model.landscape[1,1].events == [Ps.tillage, Ps.sowing]
     @test model.landscape[2,1].events == [Ps.tillage]
     @test model.landscape[2,2].events == [Ps.sowing]
-    @test_logs (:info, "Simulating day 2022-02-01.") match_mode=:any stepsimulation!(model)
+    @test_logs((:info, "Simulating day 2022-02-01."),
+               match_mode=:any,
+               stepsimulation!(Ps.withtestlogger(model)))
     @test model.landscape[1,1].events == [Ps.sowing]
     @test model.landscape[2,1].events == []
     @test model.landscape[2,2].events == [Ps.sowing]
-    @test_logs (:info, "Simulating day 2022-02-02.") match_mode=:any stepsimulation!(model)
+    @test_logs((:info, "Simulating day 2022-02-02."),
+               match_mode=:any,
+               stepsimulation!(Ps.withtestlogger(model)))
     @test model.landscape[1,1].events == []
     @test model.landscape[2,1].events == []
     @test model.landscape[2,2].events == []

test/nature_tests.jl

@@ -5,7 +5,7 @@
 
 @testset "Habitat macros" begin
     # set up the testing landscape
-    model = smalltestlandscape(Union{Animal,FarmPlot})
+    model = smalltestlandscape()
     model.landscape[6,6] = Pixel(Ps.agriculture, 1, [])
     species::Dict{String,Any} = Dict("name"=>"test_animal")
     add_agent!((6,6), FarmPlot, model, [(6,6)], Ps.wheat, 1.2, 3.4)
@@ -68,7 +68,7 @@ end
 
 @testset "Species macros" begin
     # create a model landscape and a test species
-    model = smalltestlandscape(Union{Animal,Farmer,FarmPlot})
+    model = smalltestlandscape()
     
     @species Mermaid begin
         ageofmaturity = 2
@@ -80,7 +80,7 @@ end
             @respond Persephone.harvest @setphase(drought)
             @debug "Animal: $animal"
             if @trait(sex) == Persephone.female && @countanimals() < 3 &&
-                @trait(age) >= @trait(ageofmaturity) && @here(landcover) == Persephone.water
+                @trait(age) >= @trait(ageofmaturity) && @landcover() == Persephone.water
                 @reproduce()
             end
         end
@@ -107,19 +107,19 @@ end
     @test_logs((:debug, "Mermaid 1 is swimming happily in its pond."),
                (:debug, "Mermaid 2 is swimming happily in its pond."),
                min_level=Logging.Debug, match_mode=:any,
-               stepsimulation!(model))
+               stepsimulation!(Ps.withtestlogger(model)))
     @test model[1].age == 1
     @test model[2].traits["phase"] == "drought"
     createevent!(model, [pond], Ps.sowing)
     @test_logs((:debug, "Mermaid 1 is experiencing drought with 1 neighbour(s)."),
                (:debug, "Mermaid 2 is experiencing drought with 1 neighbour(s)."),
                min_level=Logging.Debug, match_mode=:any,
-               stepsimulation!(model))
+               stepsimulation!(Ps.withtestlogger(model)))
     @test_logs((:debug, "Mermaid 1 is swimming happily in its pond."),
                (:debug, "Mermaid 1 has reproduced."),
                (:debug, "Mermaid 2 is swimming happily in its pond."),
                min_level=Logging.Debug, match_mode=:any,
-               stepsimulation!(model))
+               stepsimulation!(Ps.withtestlogger(model)))
     @test Ps.countanimals(pond, model) == 3
     createevent!(model, [pond], Ps.pesticide)
     @test_logs((:debug, "Mermaid 1 is swimming happily in its pond."),
@@ -129,7 +129,7 @@ end
                (:debug, "Mermaid 3 is swimming happily in its pond."),
                (:debug, "Mermaid 3 has died from poisoning."),
                min_level=Logging.Debug, match_mode=:any,
-               stepsimulation!(model))
+               stepsimulation!(Ps.withtestlogger(model)))
     @test Ps.countanimals(pond, model) == 0
 
     # test @rand (this is done more easily outside of @species)

test/runtests.jl

@@ -9,6 +9,7 @@ Pkg.activate("..")
 using Agents
 using Dates
 using Logging
+using LoggingExtras
 using Persephone
 using Random
 using StableRNGs

test/simulation_tests.jl

@@ -9,6 +9,7 @@
     @test model.date == Date(2022,2,1)
     @test typeof(model.landscape) == Matrix{Pixel}
     @test typeof(model.dataoutputs) == Vector{DataOutput}
+    @test typeof(model.logger) == TeeLogger{Tuple{ConsoleLogger, ConsoleLogger}}
     @test length(model.dataoutputs) == 2
     @test model.events == Vector{FarmEvent}()
     @test nagents(model) == 2092+10+28
@@ -26,6 +27,7 @@ end
     scan = Ps.paramscan(settings, scanparams)
     outdirs = (s["core.outdir"] for s in scan)
     @test length(outdirs) == 12
+    #FIXME On worker 2: KeyError: key Persephone [039acd1d-2a07-4b33-b082-83a1ff0fd136] not found
     @test length(initialise(config)) == 12 #XXX This takes a long time
     for dir in testdirs
         @test dir in outdirs
@@ -51,7 +53,7 @@ end
     @test_logs((:info, "Simulating day 2022-02-01."),
                (:info, "Simulated 59 days."),
                min_level=Logging.Debug, match_mode=:any,
-               simulate!(model))
+               simulate!(Ps.withtestlogger(model)))
     @test model.date == Date(2022,4,1)
     @test rand() == rand1
 end

test/test_parameters.toml

@@ -10,6 +10,7 @@ farmfieldsmap = "fields_jena.tif" # location of the field geometry map
 outdir = "results_testsuite" # location and name of the output folder
 overwrite = true # overwrite the output directory? (true/false/"ask")
 loglevel = "warn" # verbosity level: "debug", "info", "warn"
+processors = 6 # number of processors to use on parallel runs
 seed = 1 # seed value for the RNG (0 -> random value)
 # dates to start and end the simulation
 startdate = 2022-02-01