diff --git a/pyproject.toml b/pyproject.toml index dddebd96..e2335644 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -67,6 +67,7 @@ classifiers = [ dependencies = [ "numpy>=1.14.5", "scipy>=1.5.0", + "click==8.1.3", ] [project.optional-dependencies] diff --git a/src/spotpy/algorithms/_algorithm.py b/src/spotpy/algorithms/_algorithm.py index afba441c..9a20d247 100644 --- a/src/spotpy/algorithms/_algorithm.py +++ b/src/spotpy/algorithms/_algorithm.py @@ -11,7 +11,7 @@ import numpy as np -from spotpy import database, parameter +from spotpy import database, parameter, spotpylogging try: from queue import Queue @@ -36,15 +36,18 @@ class _RunStatistic(object): def __init__(self, repetitions, algorithm_name, optimization_direction, parnames): self.optimization_direction = optimization_direction # grid, mazimize, minimize - print( - "Initializing the ", algorithm_name, " with ", repetitions, " repetitions" + + self.logger = spotpylogging.get_logger("RunStatistic(%s)" % algorithm_name) + + self.logger.info( + "Initializing the %s with %s repetitions", algorithm_name, repetitions ) if optimization_direction == "minimize": self.compare = self.minimizer - print("The objective function will be minimized") + self.logger.info("The objective function will be minimized") if optimization_direction == "maximize": self.compare = self.maximizer - print("The objective function will be maximized") + self.logger.info("The objective function will be maxiimized") if optimization_direction == "grid": self.compare = self.grid @@ -131,46 +134,54 @@ def print_status(self): timestr, ) - print(text) + self.logger.info(text) self.last_print = time.time() def print_status_final(self): - print("\n*** Final SPOTPY summary ***") - print( - "Total Duration: " - + str(round((time.time() - self.starttime), 2)) - + " seconds" + self.logger.info("") + self.logger.info("*** Final SPOTPY summary ***") + self.logger.info( + "Total Duration: %s seconds" % str(round((time.time() - self.starttime), 2)) ) - print("Total Repetitions:", self.rep) + self.logger.info("Total Repetitions: %s", self.rep) if self.optimization_direction == "minimize": - print("Minimal objective value: %g" % (self.objectivefunction_min)) - print("Corresponding parameter setting:") + self.logger.info( + "Minimal objective value: %g" % (self.objectivefunction_min) + ) + self.logger.info("Corresponding parameter setting:") for i in range(self.parameters): text = "%s: %g" % (self.parnames[i], self.params_min[i]) - print(text) + self.logger.info(text) if self.optimization_direction == "maximize": - print("Maximal objective value: %g" % (self.objectivefunction_max)) - print("Corresponding parameter setting:") + self.logger.info( + "Maximal objective value: %g" % (self.objectivefunction_max) + ) + self.logger.info("Corresponding parameter setting:") for i in range(self.parameters): text = "%s: %g" % (self.parnames[i], self.params_max[i]) - print(text) + self.logger.info(text) if self.optimization_direction == "grid": - print("Minimal objective value: %g" % (self.objectivefunction_min)) - print("Corresponding parameter setting:") + self.logger.info( + "Minimal objective value: %g" % (self.objectivefunction_min) + ) + self.logger.info("Corresponding parameter setting:") for i in range(self.parameters): text = "%s: %g" % (self.parnames[i], self.params_min[i]) - print(text) + self.logger.info(text) - print("Maximal objective value: %g" % (self.objectivefunction_max)) - print("Corresponding parameter setting:") + self.logger.info( + "Maximal objective value: %g" % (self.objectivefunction_max) + ) + self.logger.info("Corresponding parameter setting:") for i in range(self.parameters): text = "%s: %g" % (self.parnames[i], self.params_max[i]) - print(text) + self.logger.info(text) - print("******************************\n") + self.logger.info("******************************") + self.logger.info("") def __repr__(self): return "Min objectivefunction: %g \n Max objectivefunction: %g" % ( @@ -241,8 +252,16 @@ def __init__( random_state=None, optimization_direction="grid", algorithm_name="", + quiet=False, + logfile=None, + logdir=None, ): + # Instatiate logging + self.logger = spotpylogging.instantiate_logger( + self.__class__.__name__, quiet, logfile, logdir + ) + # Initialize the user defined setup class self.setup = spot_setup param_info = parameter.get_parameters_array( @@ -292,11 +311,11 @@ def __init__( self._return_all_likes = False # allows multi-objective calibration if set to True, is set by the algorithm if breakpoint == "read" or breakpoint == "readandwrite": - print("Reading backupfile") + self.logger.info("Reading backupfile") try: open(self.dbname + ".break") except FileNotFoundError: - print("Backupfile not found") + self.logger.info("Backupfile not found") self.dbappend = True # Now a repeater (ForEach-object) is loaded @@ -370,7 +389,7 @@ def final_call(self): def _init_database(self, like, randompar, simulations): if self.dbinit: - print("Initialize database...") + self.logger.info("Initialize database...") self.datawriter = database.get_datawriter( self.dbformat, @@ -495,7 +514,7 @@ def getfitness(self, simulation, params): Calls the user defined spot_setup objectivefunction """ try: - # print('Using parameters in fitness function') + # self.logger.info('Using parameters in fitness function') return self.setup.objectivefunction( evaluation=self.evaluation, simulation=simulation, @@ -505,7 +524,7 @@ def getfitness(self, simulation, params): except ( TypeError ): # Happens if the user does not allow to pass parameter in the spot_setup.objectivefunction - # print('Not using parameters in fitness function') + # self.logger.info('Not using parameters in fitness function') return self.setup.objectivefunction( evaluation=self.evaluation, simulation=simulation ) diff --git a/src/spotpy/algorithms/abc.py b/src/spotpy/algorithms/abc.py index f0f67b85..4003c5b6 100644 --- a/src/spotpy/algorithms/abc.py +++ b/src/spotpy/algorithms/abc.py @@ -78,8 +78,8 @@ def sample( sets the limit """ self.set_repetiton(repetitions) - print( - "Starting the ABC algotrithm with " + str(repetitions) + " repetitions..." + self.logger.info( + "Starting the ABC algotrithm with %s repetitions...", repetitions ) # Initialize ABC parameters: randompar = self.parameter()["random"] @@ -106,7 +106,7 @@ def sample( work.append([like, randompar, like, randompar, c, p]) icall += 1 if self.status.stop: - print("Stopping sampling") + self.logger.debug("Stopping sampling") break while icall < repetitions and gnrng > peps: @@ -141,7 +141,7 @@ def sample( work[rep][4] = work[rep][4] + 1 icall += 1 if self.status.stop: - print("Stopping samplig") + self.logger.debug("Stopping samplig") break # Probability distribution for roulette wheel selection bn = [] for i, val in enumerate(work): @@ -191,7 +191,7 @@ def sample( work[rep][4] = work[rep][4] + 1 icall += 1 if self.status.stop: - print("Stopping samplig") + self.logger.debug("Stopping samplig") break # Scout bee phase for i, val in enumerate(work): @@ -205,18 +205,18 @@ def sample( work[i][0] = clike icall += 1 if self.status.stop: - print("Stopping samplig") + self.logger.debug("Stopping samplig") break gnrng = -self.status.objectivefunction_max if icall >= repetitions: - print("*** OPTIMIZATION SEARCH TERMINATED BECAUSE THE LIMIT") - print("ON THE MAXIMUM NUMBER OF TRIALS ") - print(repetitions) - print("HAS BEEN EXCEEDED.") + self.logger.info("*** OPTIMIZATION SEARCH TERMINATED BECAUSE THE LIMIT") + self.logger.info("ON THE MAXIMUM NUMBER OF TRIALS ") + self.logger.info(repetitions) + self.logger.info("HAS BEEN EXCEEDED.") if gnrng < peps: - print( + self.logger.info( "THE POPULATION HAS CONVERGED TO A PRESPECIFIED SMALL PARAMETER SPACE AT RUN" ) - print(icall) + self.logger.info(icall) self.final_call() diff --git a/src/spotpy/algorithms/dds.py b/src/spotpy/algorithms/dds.py index fe5c31d0..e67cfcce 100644 --- a/src/spotpy/algorithms/dds.py +++ b/src/spotpy/algorithms/dds.py @@ -281,8 +281,8 @@ def sample(self, repetitions, trials=1, x_initial=np.array([])): self.parameter()["minbound"], self.parameter()["maxbound"], ) - print( - "Starting the DDS algotrithm with " + str(repetitions) + " repetitions..." + self.logger.info( + "Starting the DDS algotrithm with %s repetitions...", repetitions ) number_of_parameters = ( @@ -334,12 +334,10 @@ def sample(self, repetitions, trials=1, x_initial=np.array([])): self.params_max = list(x_curr) self.params_max = self.fix_status_params_format(self.params_max) - print( - "Best solution found has obj function value of " - + str(objectivefunction_max) - + " at " - + str(repitionno_best) - + "\n\n" + self.logger.debug( + "Best solution found has obj function value of %s at %s\n\n", + objectivefunction_max, + repitionno_best, ) debug_results.append( { @@ -370,12 +368,10 @@ def calc_initial_para_configuration( # by trying which randomized generated input matches best # initial_iterations is the number of function evaluations to initialize the DDS algorithm solution if initial_iterations > 1: - print( - "Finding best starting point for trial " - + str(trial + 1) - + " using " - + str(initial_iterations) - + " random samples." + self.logger.debug( + "Finding best starting point for trial %s using %s random samples.", + trial + 1, + initial_iterations, ) repetions_left = ( repetitions - initial_iterations diff --git a/src/spotpy/algorithms/demcz.py b/src/spotpy/algorithms/demcz.py index b3fef8fa..fe081afb 100644 --- a/src/spotpy/algorithms/demcz.py +++ b/src/spotpy/algorithms/demcz.py @@ -7,6 +7,8 @@ import numpy as np +from spotpy import spotpylogging + from . import _algorithm @@ -104,7 +106,9 @@ def check_par_validity(self, par): if par[i] > self.max_bound[i]: par[i] = self.max_bound[i] else: - print("ERROR Bounds have not the same lenghts as Parameterarray") + self.logger.error( + "ERROR Bounds have not the same lenghts as Parameterarray" + ) return par def sample( @@ -143,8 +147,8 @@ def sample( """ self.set_repetiton(repetitions) - print( - "Starting the DEMCz algotrithm with " + str(repetitions) + " repetitions..." + self.logger.info( + "Starting the DEMCz algotrithm with %s repetitions...", repetitions ) self.min_bound, self.max_bound = ( @@ -220,9 +224,9 @@ def sample( # 3) and we have not done more than the maximum number of iterations while cur_iter < maxChainDraws: - print(cur_iter, burnIn) + self.logger.debug("%s, %s", cur_iter, burnIn) if cur_iter == burnIn: - print("starting") + self.logger.debug("starting") history.start_sampling() # every5th iteration allow a big jump @@ -349,7 +353,7 @@ def sample( covConvergence.update(history, "interest") if all(grConvergence.R < convergenceCriteria): cur_iter = maxChainDraws - print( + self.logger.info( "All chains fullfil the convergence criteria. Sampling stopped." ) cur_iter += 1 @@ -362,8 +366,8 @@ def sample( self.iter = cur_iter self.burnIn = burnIn self.R = grConvergence.R - text = "Gelman Rubin R=" + str(self.R) - print(text) + + self.logger.info("Gelman Rubin R=%s", self.R) self.status.rep = self.status.repetitions self.final_call() @@ -561,9 +565,11 @@ def rv(relevantHistory): try: projection = np.dot(np.linalg.inv(basis1), basis2) - except np.linalg.linalg.LinAlgError: + except np.linalg.linalg.LinAlgError as e: projection = np.array(basis1) * np.nan - print("Exception happend!") + spotpylogging.get_logger("_CovarianceConvergence()").logger.debug( + "Exception happend!\nExcpetion:%s", e + ) # find the releative size in each of the basis1 directions return np.log(np.sum(projection**2, axis=0) ** 0.5) diff --git a/src/spotpy/algorithms/fast.py b/src/spotpy/algorithms/fast.py index 4bc82719..0221258e 100644 --- a/src/spotpy/algorithms/fast.py +++ b/src/spotpy/algorithms/fast.py @@ -131,14 +131,14 @@ def matrix(self, bounds, N, M=4): def analyze(self, problem, Y, D, parnames, M=4, print_to_console=False): if len(Y.shape) > 1: Y = Y.flatten() - print(Y.size) + self.logger.info(Y.size) if Y.size % (D) == 0: N = int(Y.size / D) elif Y.size > D: N = int(Y.size / D) rest = Y.size - N * D - print( + self.logger.info( """ We can not use """ + str(rest) @@ -149,7 +149,7 @@ def analyze(self, problem, Y, D, parnames, M=4, print_to_console=False): """ ) else: - print( + self.logger.error( """ Error: Number of samples in model output file must be a multiple of D, where D is the number of parameters in your parameter file. @@ -169,14 +169,14 @@ def analyze(self, problem, Y, D, parnames, M=4, print_to_console=False): # Calculate and Output the First and Total Order Values if print_to_console: - print("Parameter First Total") + self.logger.info("Parameter First Total") Si = dict((k, [None] * D) for k in ["S1", "ST"]) for i in range(D): l = np.arange(i * N, (i + 1) * N) Si["S1"][i] = self.compute_first_order(Y[l], N, M, omega[0]) Si["ST"][i] = self.compute_total_order(Y[l], N, omega[0]) if print_to_console: - print("%s %f %f" % (parnames[i], Si["S1"][i], Si["ST"][i])) + self.logger.info("%s %f %f" % (parnames[i], Si["S1"][i], Si["ST"][i])) return Si def compute_first_order(self, outputs, N, M, omega): @@ -203,10 +203,11 @@ def sample(self, repetitions, M=4): Maximum number of runs. """ self.set_repetiton(repetitions) - print( + self.logger.info( "Starting the FAST algotrithm with " + str(repetitions) + " repetitions..." ) - print("Creating FAST Matrix") + + self.logger.debug("Creating FAST Matrix") # Get the names of the parameters to analyse names = self.parameter()["name"] # Get the minimum and maximum value for each parameter from the diff --git a/src/spotpy/algorithms/fscabc.py b/src/spotpy/algorithms/fscabc.py index 03aec53a..1c92e1bf 100644 --- a/src/spotpy/algorithms/fscabc.py +++ b/src/spotpy/algorithms/fscabc.py @@ -86,7 +86,7 @@ def sample(self, repetitions, eb=48, a=(1 / 10), peps=0.0001, kpow=4, limit=None sets the limit for scout bee phase """ self.set_repetiton(repetitions) - print( + self.logger.info( "Starting the FSCABC algotrithm with " + str(repetitions) + " repetitions..." @@ -134,7 +134,7 @@ def sample(self, repetitions, eb=48, a=(1 / 10), peps=0.0001, kpow=4, limit=None icall += 1 if self.status.stop: # icall = repetitions - print("Stopping samplig") + self.logger.debug("Stopping sampling") break # Bee Phases @@ -174,7 +174,7 @@ def sample(self, repetitions, eb=48, a=(1 / 10), peps=0.0001, kpow=4, limit=None work[rep][4] = work[rep][4] + 1 icall += 1 if self.status.stop: - print("Stopping samplig") + self.logger.debug("Stopping samplig") break # Fitness scaling @@ -223,7 +223,7 @@ def sample(self, repetitions, eb=48, a=(1 / 10), peps=0.0001, kpow=4, limit=None work[rep][4] = work[rep][4] + 1 icall += 1 if self.status.stop: - print("Stopping samplig") + self.logger.debug("Stopping samplig") break # Scout bee phase for i, val in enumerate(work): @@ -239,7 +239,7 @@ def sample(self, repetitions, eb=48, a=(1 / 10), peps=0.0001, kpow=4, limit=None work[i][0] = clike icall += 1 if self.status.stop: - print("Stopping samplig") + self.logger.debug("Stopping samplig") break gnrng = -self.status.objectivefunction_max @@ -252,13 +252,13 @@ def sample(self, repetitions, eb=48, a=(1 / 10), peps=0.0001, kpow=4, limit=None self.write_breakdata(self.dbname, savework) lastbackup = icall if icall >= repetitions: - print("*** OPTIMIZATION SEARCH TERMINATED BECAUSE THE LIMIT") - print("ON THE MAXIMUM NUMBER OF TRIALS ") - print(repetitions) - print("HAS BEEN EXCEEDED.") + self.logger.info("*** OPTIMIZATION SEARCH TERMINATED BECAUSE THE LIMIT") + self.logger.info("ON THE MAXIMUM NUMBER OF TRIALS ") + self.logger.info(repetitions) + self.logger.info("HAS BEEN EXCEEDED.") if gnrng < peps: - print( + self.logger.info( "THE POPULATION HAS CONVERGED TO A PRESPECIFIED SMALL PARAMETER SPACE" ) self.final_call() diff --git a/src/spotpy/algorithms/lhs.py b/src/spotpy/algorithms/lhs.py index 998857fd..72285b96 100644 --- a/src/spotpy/algorithms/lhs.py +++ b/src/spotpy/algorithms/lhs.py @@ -61,10 +61,10 @@ def sample(self, repetitions): maximum number of function evaluations allowed during optimization """ self.set_repetiton(repetitions) - print( + self.logger.info( "Starting the LHS algotrithm with " + str(repetitions) + " repetitions..." ) - print("Creating LatinHyperCube Matrix") + self.logger.debug("Creating LatinHyperCube Matrix") # Get the names of the parameters to analyse names = self.parameter()["name"] # Define the jump size between the parameter diff --git a/src/spotpy/algorithms/list_sampler.py b/src/spotpy/algorithms/list_sampler.py index 8f386e2a..0da3bfb0 100644 --- a/src/spotpy/algorithms/list_sampler.py +++ b/src/spotpy/algorithms/list_sampler.py @@ -68,7 +68,9 @@ def sample(self, repetitions=None): self.set_repetiton(repetitions) # Initialization - print("Starting the List sampler with " + str(repetitions) + " repetitions...") + self.logger.info( + "Starting the List sampler with " + str(repetitions) + " repetitions..." + ) param_generator = ( (rep, list(parameters[rep])) for rep in range(int(repetitions)) ) diff --git a/src/spotpy/algorithms/mc.py b/src/spotpy/algorithms/mc.py index 171ac155..edc4547c 100644 --- a/src/spotpy/algorithms/mc.py +++ b/src/spotpy/algorithms/mc.py @@ -61,7 +61,9 @@ def sample(self, repetitions): Maximum number of runs. """ self.set_repetiton(repetitions) - print("Starting the MC algorithm with {} repetitions...".format(repetitions)) + self.logger.info( + "Starting the MC algorithm with %s repetitions...", repetitions + ) # A generator that produces parametersets if called param_generator = ( (rep, self.parameter()["random"]) for rep in range(int(repetitions)) diff --git a/src/spotpy/algorithms/mcmc.py b/src/spotpy/algorithms/mcmc.py index 04078c68..d60440f2 100644 --- a/src/spotpy/algorithms/mcmc.py +++ b/src/spotpy/algorithms/mcmc.py @@ -63,7 +63,9 @@ def check_par_validity(self, par): if par[i] > self.max_bound[i]: par[i] = self.max_bound[i] else: - print("ERROR: Bounds have not the same lenghts as Parameterarray") + self.logger.error( + "ERROR: Bounds have not the same lenghts as Parameterarray" + ) return par def check_par_validity_reflect(self, par): @@ -81,7 +83,9 @@ def check_par_validity_reflect(self, par): if par[i] > self.max_bound[i]: par[i] = self.max_bound[i] else: - print("ERROR: Bounds have not the same lenghts as Parameterarray") + self.logger.error( + "ERROR: Bounds have not the same lenghts as Parameterarray" + ) return par def get_new_proposal_vector(self, old_par): @@ -97,7 +101,7 @@ def update_mcmc_status(self, par, like, sim, cur_chain): def sample(self, repetitions, nChains=1): self.set_repetiton(repetitions) - print( + self.logger.info( "Starting the MCMC algotrithm with " + str(repetitions) + " repetitions..." ) # Prepare storing MCMC chain as array of arrays. @@ -117,7 +121,7 @@ def sample(self, repetitions, nChains=1): self.parameter()["minbound"], self.parameter()["maxbound"], ) - print("Initialize ", self.nChains, " chain(s)...") + self.logger.debug("Initialize ", self.nChains, " chain(s)...") self.iter = 0 param_generator = ( (curChain, self.parameter()["random"]) @@ -132,7 +136,7 @@ def sample(self, repetitions, nChains=1): self.iter += 1 intervaltime = time.time() - print("Beginn of Random Walk") + self.logger.debug("Beginn of Random Walk") # Walk through chains while self.iter <= repetitions - self.burnIn: param_generator = ( @@ -167,6 +171,6 @@ def sample(self, repetitions, nChains=1): ) * 100 ).strip("array([])") - print(text) + self.logger.debug(text) intervaltime = time.time() self.final_call() diff --git a/src/spotpy/algorithms/mle.py b/src/spotpy/algorithms/mle.py index 62bc1a82..3e6da1b7 100644 --- a/src/spotpy/algorithms/mle.py +++ b/src/spotpy/algorithms/mle.py @@ -59,12 +59,14 @@ def check_par_validity(self, par): if par[i] > self.max_bound[i]: par[i] = self.max_bound[i] else: - print("ERROR Bounds have not the same lenghts as Parameterarray") + self.logger.error( + "ERROR Bounds have not the same lenghts as Parameterarray" + ) return par def sample(self, repetitions): self.set_repetiton(repetitions) - print( + self.logger.info( "Starting the MLE algotrithm with " + str(repetitions) + " repetitions..." ) # Define stepsize of MLE @@ -79,7 +81,7 @@ def sample(self, repetitions): likes = [] pars = [] sims = [] - print("burnIn...") + self.logger.debug("burnIn...") for i in range(burnIn): randompar = self.parameter()["random"] pars.append(randompar) @@ -90,7 +92,7 @@ def sample(self, repetitions): old_like = max(likes) old_par = pars[likes.index(old_like)] - print("Beginn Random Walk") + self.logger.debug("Beginn Random Walk") for rep in range(repetitions - burnIn): # Suggest new candidate from Gaussian proposal distribution. # Use stepsize provided for every dimension. diff --git a/src/spotpy/algorithms/padds.py b/src/spotpy/algorithms/padds.py index ce35b7e4..860d3f4b 100644 --- a/src/spotpy/algorithms/padds.py +++ b/src/spotpy/algorithms/padds.py @@ -231,10 +231,10 @@ def sample( # every iteration a map of all relevant values is stored, only for debug purpose. # Spotpy will not need this values. debug_results = [] - print( + self.logger.info( "Starting the PADDS algotrithm with " + str(repetitions) + " repetitions..." ) - print( + self.logger.info( "WARNING: THE PADDS algorithm as implemented in SPOTPY is in an beta stage and not ready for production use!" ) self.set_repetiton(repetitions) @@ -292,7 +292,7 @@ def sample( self.parameter_current, ) - print( + self.logger.debug( "Best solution found has obj function value of " + str(self.best_value.best_obj_val) + " at " diff --git a/src/spotpy/algorithms/rope.py b/src/spotpy/algorithms/rope.py index 88f60224..12a4f2d0 100644 --- a/src/spotpy/algorithms/rope.py +++ b/src/spotpy/algorithms/rope.py @@ -106,7 +106,7 @@ def sample( # Takes ways´to long for npar >8 # wenn mehr parameter produziert werden sollen als reingehen, rechnet er sich tot (ngen>n) # Subsets < 5 führt manchmal zu Absturz - print( + self.logger.info( "Starting the ROPE algotrithm with " + str(repetitions) + " repetitions..." ) self.set_repetiton(repetitions) @@ -122,7 +122,7 @@ def sample( repetitions_following_runs = int((repetitions - first_run) / (subsets - 1)) # Needed to avoid an error in integer division somewhere in depth function if repetitions_following_runs % 2 != 0: - print( + self.logger.info( "Warning: Burn-in samples and total number of repetions are not compatible.\n" "SPOTPY will automatically adjust the number of total repetitions." ) @@ -172,7 +172,7 @@ def sample( first_run, self.status.objectivefunction_max, ) - print(text) + self.logger.debug(text) intervaltime = time.time() for subset in range(subsets - 1): @@ -209,7 +209,7 @@ def sample( likes.append(like) pars.append(ropepar) if self.status.stop: - print("Stopping samplig") + self.logger.debug("Stopping sampling") break # Progress bar @@ -223,7 +223,7 @@ def sample( repetitions_following_runs, self.status.objectivefunction_max, ) - print(text) + self.logger.debug(text) intervaltime = time.time() if self.status.stop: break @@ -235,10 +235,10 @@ def programm_depth(self, pars, runs): N, NP = X.shape text = str(N) + " input vectors with " + str(NP) + " parameters" - print(text) + self.logger.debug(text) Ngen = int(runs) # int(N*(1/self.percentage)) - print(("Generating " + str(Ngen) + " parameters:")) + self.logger.debug(("Generating " + str(Ngen) + " parameters:")) NPOSI = Ngen # Number of points to generate @@ -270,7 +270,7 @@ def programm_depth(self, pars, runs): if LNDEP[L] >= 1: CL = np.vstack((CL, TL[L, :])) IPOS = IPOS + 1 - print((IPOS, ITRY)) + self.logger.info((IPOS, ITRY)) CL = np.delete(CL, 0, 0) CL = CL[:NPOSI] diff --git a/src/spotpy/algorithms/sa.py b/src/spotpy/algorithms/sa.py index ba787fae..c4a0315c 100644 --- a/src/spotpy/algorithms/sa.py +++ b/src/spotpy/algorithms/sa.py @@ -62,7 +62,9 @@ def check_par_validity(self, par): if par[i] > self.max_bound[i]: par[i] = self.max_bound[i] else: - print("ERROR: Bounds have not the same lenghts as Parameterarray") + self.logger.error( + "ERROR: Bounds have not the same lenghts as Parameterarray" + ) return par def sample(self, repetitions, Tini=80, Ntemp=50, alpha=0.99): @@ -75,7 +77,9 @@ def sample(self, repetitions, Tini=80, Ntemp=50, alpha=0.99): Maximum number of runs. """ self.set_repetiton(repetitions) - print("Starting the SA algotrithm with " + str(repetitions) + " repetitions...") + self.logger.info( + "Starting the SA algotrithm with " + str(repetitions) + " repetitions..." + ) self.min_bound, self.max_bound = ( self.parameter()["minbound"], self.parameter()["maxbound"], diff --git a/src/spotpy/algorithms/sceua.py b/src/spotpy/algorithms/sceua.py index a0841b5c..3bf906d4 100644 --- a/src/spotpy/algorithms/sceua.py +++ b/src/spotpy/algorithms/sceua.py @@ -174,6 +174,10 @@ def sample( Number of loops executed at max in this function call """ self.set_repetiton(repetitions) + self.logger.info( + "Starting the SCEUA algotrithm with " + str(repetitions) + " repetitions..." + ) + # Initialize SCE parameters: self.ngs = ngs randompar = self.parameter()["random"] @@ -206,7 +210,7 @@ def sample( icall = 0 xf = np.zeros(npt) - print("Starting burn-in sampling...") + self.logger.debug("Starting burn-in sampling...") # Burn in param_generator = ((rep, x[rep]) for rep in range(int(npt))) @@ -216,7 +220,7 @@ def sample( xf[rep] = like icall += 1 if self.status.stop: - print( + self.logger.debug( "Stopping samplig. Maximum number of repetitions reached already during burn-in" ) proceed = False @@ -258,15 +262,15 @@ def sample( # Check for convergency; if self.status.rep >= repetitions: - print("*** OPTIMIZATION SEARCH TERMINATED BECAUSE THE LIMIT") - print("ON THE MAXIMUM NUMBER OF TRIALS ") - print(repetitions) - print("HAS BEEN EXCEEDED. SEARCH WAS STOPPED AT TRIAL NUMBER:") - print(self.status.rep) - print("OF THE INITIAL LOOP!") + self.logger.debug("*** OPTIMIZATION SEARCH TERMINATED BECAUSE THE LIMIT") + self.logger.debug("ON THE MAXIMUM NUMBER OF TRIALS ") + self.logger.debug(repetitions) + self.logger.debug("HAS BEEN EXCEEDED. SEARCH WAS STOPPED AT TRIAL NUMBER:") + self.logger.debug(self.status.rep) + self.logger.debug("OF THE INITIAL LOOP!") if gnrng < peps: - print( + self.logger.debug( "THE POPULATION HAS CONVERGED TO A PRESPECIFIED SMALL PARAMETER SPACE" ) @@ -297,7 +301,7 @@ def sample( and proceed == True ): nloop += 1 - print("ComplexEvo loop #%d in progress..." % nloop) + self.logger.debug("ComplexEvo loop #%d in progress..." % nloop) # Loop on complexes (sub-populations); cx = np.zeros((self.npg, self.nopt)) cf = np.zeros((self.npg)) @@ -336,7 +340,7 @@ def sample( i, pars[i], sims[i], chains=i + 1, save_run=False ) self.discarded_runs += 1 - print("Skipping saving") + self.logger.debug("Skipping saving") if ( self.breakpoint == "write" @@ -378,20 +382,22 @@ def sample( # Check for convergency; if self.status.rep >= repetitions: - print("*** OPTIMIZATION SEARCH TERMINATED BECAUSE THE LIMIT") - print("ON THE MAXIMUM NUMBER OF TRIALS ") - print(repetitions) - print("HAS BEEN EXCEEDED.") + self.logger.debug( + "*** OPTIMIZATION SEARCH TERMINATED BECAUSE THE LIMIT" + ) + self.logger.debug("ON THE MAXIMUM NUMBER OF TRIALS ") + self.logger.debug(repetitions) + self.logger.debug("HAS BEEN EXCEEDED.") elif gnrng < peps: - print( + self.logger.debug( "THE POPULATION HAS CONVERGED TO A PRESPECIFIED SMALL PARAMETER SPACE" ) elif ( nloop >= kstop ): # necessary so that the area of high posterior density is visited as much as possible - print( + self.logger.debug( "Objective function convergence criteria is now being updated and assessed..." ) absolute_change = ( @@ -402,13 +408,15 @@ def sample( criter_change_pcent = 0.0 else: criter_change_pcent = absolute_change / denominator - print("Updated convergence criteria: %f" % criter_change_pcent) + self.logger.debug( + "Updated convergence criteria: %f" % criter_change_pcent + ) if criter_change_pcent <= pcento: - print( + self.logger.debug( "THE BEST POINT HAS IMPROVED IN LAST %d LOOPS BY LESS THAN THE USER-SPECIFIED THRESHOLD %f" % (kstop, pcento) ) - print( + self.logger.debug( "CONVERGENCY HAS ACHIEVED BASED ON OBJECTIVE FUNCTION CRITERIA!!!" ) elif self.status.stop: @@ -418,14 +426,16 @@ def sample( # stop, if max number of loop iteration was reached elif max_loop_inc and nloop >= max_loop_inc: proceed = False - print("THE MAXIMAL NUMBER OF LOOPS PER EXECUTION WAS REACHED") + self.logger.debug( + "THE MAXIMAL NUMBER OF LOOPS PER EXECUTION WAS REACHED" + ) break # End of the Outer Loops - print("SEARCH WAS STOPPED AT TRIAL NUMBER: %d" % self.status.rep) - print("NUMBER OF DISCARDED TRIALS: %d" % self.discarded_runs) - print("NORMALIZED GEOMETRIC RANGE = %f" % gnrng) - print( + self.logger.debug("SEARCH WAS STOPPED AT TRIAL NUMBER: %d" % self.status.rep) + self.logger.debug("NUMBER OF DISCARDED TRIALS: %d" % self.discarded_runs) + self.logger.debug("NORMALIZED GEOMETRIC RANGE = %f" % gnrng) + self.logger.debug( "THE BEST POINT HAS IMPROVED IN LAST %d LOOPS BY %f PERCENT" % (kstop, criter_change_pcent) ) diff --git a/src/spotpy/cli.py b/src/spotpy/cli.py index 9c0e4385..64470d6d 100644 --- a/src/spotpy/cli.py +++ b/src/spotpy/cli.py @@ -84,6 +84,23 @@ def cli(): is_flag=True, help="Print only the configuration, can be used to create a config file with your_model.py > spotpy.conf", ) +@click.option( + "--quiet", + "-q", + is_flag=True, + help="Suppress any logging messages to stdout during computation", +) +@click.option( + "--logfile", + type=click.Path(dir_okay=False), + help="Logging messages will be written to this file. If already exists, " + "contents are appended. A default filename is created with a current timestamp", +) +@click.option( + "--logdir", + type=click.Path(file_okay=False), + help='Logging files will be written to this directory. Default is "."', +) def run(ctx, **kwargs): """ Runs a sampler for automatic calibration diff --git a/src/spotpy/database/__init__.py b/src/spotpy/database/__init__.py index 89ed286f..6e2f6aa0 100644 --- a/src/spotpy/database/__init__.py +++ b/src/spotpy/database/__init__.py @@ -1,5 +1,9 @@ from importlib import import_module +from spotpy.spotpylogging import get_logger + +logger = get_logger("database.__init__") + def __dir__(): """ @@ -19,7 +23,7 @@ def __dir__(): def __getattr__(name): names = __dir__() - print(names) + logger.info(names) if name in names: try: db_module = import_module("." + name, __name__) diff --git a/src/spotpy/database/base.py b/src/spotpy/database/base.py index 5e64b149..cd31b146 100644 --- a/src/spotpy/database/base.py +++ b/src/spotpy/database/base.py @@ -16,6 +16,8 @@ import numpy as np +from spotpy import spotpylogging + class database(object): """ @@ -36,6 +38,9 @@ def __init__( **kwargs, ): # Just needed for the first line in the database + + self.logger = spotpylogging.get_logger(self.__class__.__name__) + self.chains = chains self.dbname = dbname self.like = like @@ -87,15 +92,15 @@ def _empty_list(self, obj): return [] def _scalar_to_list(self, obj): - # print('scalar') + # self.logger.info('scalar') return [obj] def _iterable_to_list(self, obj): - # print('iterable') + # self.logger.info('iterable') return list(obj) def _array_to_list(self, obj): - # print('array') + # self.logger.info('array') values = [] for val in obj: values.append(val) @@ -103,13 +108,13 @@ def _array_to_list(self, obj): # return obj.flatten().tolist() def _nestediterable_to_list(self, obj): - # print('nested') + # self.logger.info('nested') values = [] for nestedlist in obj: - # print(len(nestedlist)) + # self.logger.info(len(nestedlist)) for val in nestedlist: values.append(val) - # print(len(values)) + # self.logger.info(len(values)) return values # return np.array(obj).flatten().tolist() diff --git a/src/spotpy/database/csv.py b/src/spotpy/database/csv.py index 008f1f34..6ec414fa 100644 --- a/src/spotpy/database/csv.py +++ b/src/spotpy/database/csv.py @@ -18,14 +18,16 @@ def __init__(self, *args, **kwargs): super(csv, self).__init__(*args, **kwargs) # store init item only if dbinit if kwargs.get("dbappend", False) is False: - print("* Database file '{}.csv' created.".format(self.dbname)) + self.logger.info("* Database file '{}.csv' created.".format(self.dbname)) # Create a open file, which needs to be closed after the sampling mode = "w" self.db = io.open(self.dbname + ".csv", mode) # write header line self.db.write(str(",".join(self.header) + "\n")) else: - print("* Appending to database file '{}.csv'.".format(self.dbname)) + self.logger.info( + "* Appending to database file '{}.csv'.".format(self.dbname) + ) # Continues writing file mode = "a" self.db = io.open(self.dbname + ".csv", mode) diff --git a/src/spotpy/database/hdf5.py b/src/spotpy/database/hdf5.py index a4a4153a..e96fd248 100644 --- a/src/spotpy/database/hdf5.py +++ b/src/spotpy/database/hdf5.py @@ -12,12 +12,14 @@ import numpy as np +from spotpy import spotpylogging + from .base import database try: import tables except ImportError: - print( + spotpylogging.get_logger("hdf5").info( "ImportError: Pytables is not correctly installed. Please also make sure you", "installed the hdf5 extension (https://www.hdfgroup.org/downloads/hdf5/)", ) diff --git a/src/spotpy/objectivefunctions.py b/src/spotpy/objectivefunctions.py index 47de88ff..d2828ae4 100644 --- a/src/spotpy/objectivefunctions.py +++ b/src/spotpy/objectivefunctions.py @@ -9,12 +9,11 @@ This tool holds functions for statistic analysis. It takes Python-lists and returns the objective function value of interest. """ - -import logging - import numpy as np -logging.basicConfig(format="%(levelname)s: %(module)s.%(funcName)s(): %(message)s") +from spotpy import spotpylogging + +logger = spotpylogging.get_logger("objective_functions") def bias(evaluation, simulation): @@ -41,9 +40,7 @@ def bias(evaluation, simulation): return float(bias) else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -70,9 +67,7 @@ def pbias(evaluation, simulation): return 100 * (float(np.nansum(sim - obs)) / float(np.nansum(obs))) else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -105,9 +100,7 @@ def nashsutcliffe(evaluation, simulation): return 1 - (numerator / denominator) else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -140,9 +133,7 @@ def lognashsutcliffe(evaluation, simulation, epsilon=0): / sum((np.log(e) - np.mean(np.log(e))) ** 2) ) else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -167,9 +158,7 @@ def log_p(evaluation, simulation): normpdf = -(y**2) / 2 - np.log(np.sqrt(2 * np.pi)) return np.mean(normpdf) else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -194,9 +183,7 @@ def correlationcoefficient(evaluation, simulation): correlation_coefficient = np.corrcoef(evaluation, simulation)[0, 1] return correlation_coefficient else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -220,9 +207,7 @@ def rsquared(evaluation, simulation): if len(evaluation) == len(simulation): return correlationcoefficient(evaluation, simulation) ** 2 else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -249,9 +234,7 @@ def mse(evaluation, simulation): mse = np.nanmean((obs - sim) ** 2) return mse else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -275,7 +258,7 @@ def rmse(evaluation, simulation): if len(evaluation) == len(simulation) > 0: return np.sqrt(mse(evaluation, simulation)) else: - logging.warning("evaluation and simulation lists do not have the same length.") + logger.warning("evaluation and simulation lists do not have the same length.") return np.nan @@ -301,9 +284,7 @@ def mae(evaluation, simulation): mae = np.mean(np.abs(sim - obs)) return mae else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -329,9 +310,7 @@ def rrmse(evaluation, simulation): rrmse = rmse(evaluation, simulation) / np.mean(evaluation) return rrmse else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -366,9 +345,7 @@ def agreementindex(evaluation, simulation): ) return Agreement_index else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -395,9 +372,7 @@ def covariance(evaluation, simulation): covariance = np.mean((obs - obs_mean) * (sim - sim_mean)) return covariance else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -434,9 +409,7 @@ def decomposed_mse(evaluation, simulation): return decomposed_mse else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -464,9 +437,7 @@ def kge(evaluation, simulation, return_all=False): else: return kge else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -536,9 +507,7 @@ def kge_non_parametric(evaluation, simulation, return_all=False): else: return kge else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -556,9 +525,7 @@ def rsr(evaluation, simulation): rsr = rmse(evaluation, simulation) / np.std(evaluation) return rsr else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan @@ -589,9 +556,7 @@ def volume_error(evaluation, simulation): ve = np.sum(simulation - evaluation) / np.sum(evaluation) return float(ve) else: - logging.warning( - "evaluation and simulation lists does not have the same length." - ) + logger.warning("evaluation and simulation lists does not have the same length.") return np.nan diff --git a/src/spotpy/spotpylogging.py b/src/spotpy/spotpylogging.py new file mode 100644 index 00000000..588ab987 --- /dev/null +++ b/src/spotpy/spotpylogging.py @@ -0,0 +1,70 @@ +# -*- coding: utf-8 -*- +""" +Defines a standard logger for the main application, which every child can + derive from. Also it's possible to use the logger for the main + application. +""" + +import logging +from datetime import datetime +from pathlib import PurePath + +# Standard defintion of main logger +spotpy_logger = logging.getLogger("spotpy") + +path_to_logfile = None +handler_stdout = None +handler_file = None + +formatter_file = logging.Formatter( + "%(asctime)s %(name)-12s %(levelname)-8s %(message)s" +) +formatter_stdout = logging.Formatter("%(message)s") + + +def instantiate_logger(name, quiet=None, logfile=None, logdir=None): + """ + Instantiate the logger, + if already instantiated returns a new child of the main logger + """ + + path_to_logdir = PurePath() # current directory is assumed + path_to_logfile = PurePath( + "{}-spotpy.log".format(datetime.isoformat(datetime.now())) + ) + + if not spotpy_logger.handlers: + # create the handlers and call logger.addHandler(logging_handler) + # Add logging to stdout + handler_stdout = logging.StreamHandler() + + handler_stdout.setFormatter(formatter_stdout) + spotpy_logger.addHandler(handler_stdout) + + if quiet: + handler_stdout.setLevel(logging.ERROR) + + # Add logging to file + if logdir is not None: + path_to_logdir = logdir + if logfile is not None: + path_to_logfile = logfile + path_to_logfile = PurePath(path_to_logdir, path_to_logfile) + + handler_file = logging.FileHandler(path_to_logfile) + handler_file.setFormatter(formatter_file) + spotpy_logger.addHandler(handler_file) + + spotpy_logger.setLevel(logging.INFO) + spotpy_logger.info("Write logging output to file '%s'", + path_to_logfile) + + return get_logger(name) + + +def get_logger(name): + """Returns a new child logger for the main spotpy application logging. + + Use this logger to return new childs of the main logger""" + + return spotpy_logger.getChild(name)