Merge pull request #125 from rl-institut/feature/logging

logging

data/examples/ebus_toolbox.cfg

@@ -87,6 +87,15 @@ default_buffer_time_opps = 0
 # Options: HV, HV/MV, MV, MV/LV, LV (default: MV)
 default_voltage_level = "MV"
 
+##### LOGGING #####
+# minimum log level. Allowed/useful: DEBUG, INFO, WARN, ERROR
+# INFO includes INFO, WARN and ERROR but excludes DEBUG
+loglevel = INFO
+# log file name. Placed in output directory
+# set to null to disable logfile creation
+# leave empty to have default [timestamp].log
+logfile =
+
 ##### SIMULATION PARAMETERS #####
 # Maximum number of days to simulate, if not set simulate entire schedule
 #days = 10

ebus_toolbox/__main__.py

@@ -1,4 +1,5 @@
 from datetime import datetime
+import logging
 from pathlib import Path
 import shutil
 
@@ -7,9 +8,8 @@
 if __name__ == '__main__':
     args = util.get_args()
 
-    args.output_directory = Path(args.output_directory) / (
-        datetime.now().strftime("%Y-%m-%d-%H-%M-%S") + "_eBus_results")
-
+    time_str = datetime.now().strftime("%Y-%m-%d-%H-%M-%S")
+    args.output_directory = Path(args.output_directory) / (time_str + "_eBus_results")
     # create subfolder for specific sim results with timestamp.
     # if folder doesnt exists, create folder.
     # needs to happen after set_options_from_config since
@@ -29,5 +29,10 @@
         shutil.copy(c_file, args.output_directory_input / c_file.name)
 
     util.save_version(args.output_directory_input / "program_version.txt")
+    util.setup_logging(args, time_str)
 
-    simulate.simulate(args)
+    try:
+        simulate.simulate(args)
+    except Exception as e:
+        logging.error(e)
+        raise

ebus_toolbox/consumption.py

@@ -74,31 +74,31 @@ def calculate_consumption(self, time, distance, vehicle_type, charging_type, tem
         if temp is None:
             try:
                 temp = self.temperatures_by_hour[time.hour]
-            except AttributeError:
-                print("Neither of these conditions is met:\n"
-                      "1. Temperature data is available for every trip through the trips file "
-                      "or a temperature over day file.\n"
-                      f"2. A constant mileage for the vehicle: "
-                      f"{vehicle_info['name']} - is provided.")
-                raise AttributeError
-            except KeyError:
-                print(f"No temperature data for the hour {time.hour} is provided")
-                raise KeyError
+            except AttributeError as e:
+                raise AttributeError(
+                    "Neither of these conditions is met:\n"
+                    "1. Temperature data is available for every trip through the trips file "
+                    "or a temperature over day file.\n"
+                    f"2. A constant mileage for the vehicle "
+                    f"{vehicle_info['mileage']} is provided."
+                ) from e
+            except KeyError as e:
+                raise KeyError(f"No temperature data for the hour {time.hour} is provided") from e
 
         # if no specific LoL is given, lookup temperature
         if level_of_loading is None:
             try:
                 level_of_loading = self.lol_by_hour[time.hour]
-            except AttributeError:
-                print("Neither of these conditions is met:\n"
-                      "1. Level of loading data is available for every trip through the trips file "
-                      "or a level of loading over day file.\n"
-                      f"2. A constant mileage for the vehicle: "
-                      f"{vehicle_info['name']} - is provided.")
-                raise AttributeError
-            except KeyError:
-                print(f"No level of loading data for the hour {time.hour} is provided")
-                raise KeyError
+            except AttributeError as e:
+                raise AttributeError(
+                    "Neither of these conditions is met:\n"
+                    "1. Level of loading data is available for every trip through the trips file "
+                    "or a level of loading over day file.\n"
+                    f"2. A constant mileage for the vehicle "
+                    f"{vehicle_info['mileage']} is provided."
+                ) from e
+            except KeyError as e:
+                raise KeyError(f"No level of loading for the hour {time.hour} is provided") from e
 
         # load consumption csv
         consumption_path = str(vehicle_info["mileage"])

ebus_toolbox/costs.py

@@ -1,3 +1,4 @@
+import logging
 import warnings
 
 from spice_ev.costs import calculate_costs as calc_costs_spice_ev
@@ -190,11 +191,11 @@ def calculate_costs(c_params, scenario, schedule, args):
     for key, v in costs.items():
         costs[key] = round(v, 2)
 
-    print("\n"
-          "Total costs: \n"
-          f"Investment cost: {costs['c_invest']} €. \n"
-          f"Annual investment costs: {costs['c_invest_annual']} €/a. \n"
-          f"Annual maintenance costs: {costs['c_maint_annual']} €/a. \n"
-          f"Annual costs for electricity: {costs['c_el_annual']} €/a.\n")
+    logging.info(
+        "\nTotal costs:\n"
+        f"Investment cost: {costs['c_invest']} €. \n"
+        f"Annual investment costs: {costs['c_invest_annual']} €/a. \n"
+        f"Annual maintenance costs: {costs['c_maint_annual']} €/a. \n"
+        f"Annual costs for electricity: {costs['c_el_annual']} €/a.\n")
 
     setattr(scenario, "costs", costs)

ebus_toolbox/optimization.py

@@ -1,17 +1,8 @@
 """ Collection of procedures optimizing arbitrary parameters of a bus schedule or infrastructure.
 """
-
 from copy import deepcopy
 import datetime
-
 import logging
-import sys
-logger = logging.getLogger(__name__)
-if "pytest" not in sys.modules:
-    logger.setLevel(logging.DEBUG)
-    sh = logging.StreamHandler(sys.stdout)
-    sh.setLevel(logging.DEBUG)
-    logger.addHandler(sh)
 
 
 def service_optimization(schedule, scenario, args):
@@ -34,7 +25,7 @@ def service_optimization(schedule, scenario, args):
 
     # single out negative rotations. Try to run these with common non-negative rotations
     negative_rotations = schedule.get_negative_rotations(scenario)
-    logger.info(f"Initially, rotations {sorted(negative_rotations)} have neg. SoC.")
+    logging.info(f"Initially, rotations {sorted(negative_rotations)} have neg. SoC.")
 
     if not negative_rotations:
         return {
@@ -48,8 +39,8 @@ def service_optimization(schedule, scenario, args):
         rotation = schedule.rotations.pop(rot_key)
         if rotation.charging_type != "oppb":
             # only oppb rotations are optimized -> skip others
-            logger.warn(f"Rotation {rot_key} should be optimized, "
-                        f"but is of type {rotation.charging_type}.")
+            logging.warning(f"Rotation {rot_key} should be optimized, "
+                            f"but is of type {rotation.charging_type}.")
             continue
         # oppb: build non-interfering sets of negative rotations
         # (these include the dependent non-negative rotations)
@@ -67,7 +58,7 @@ def service_optimization(schedule, scenario, args):
                 dependent_station.update({r2: t2 for r2, t2
                                           in common_stations[r].items() if t2 <= t})
             elif r.charging_type != "obbp":
-                logger.warn(f"Rotation {rot_key} depends on negative non-oppb rotation")
+                logging.warning(f"Rotation {rot_key} depends on negative non-oppb rotation")
 
         negative_sets[rot_key] = s
 
@@ -80,18 +71,18 @@ def service_optimization(schedule, scenario, args):
     ignored = []
     for i, (rot, s) in enumerate(negative_sets.items()):
         schedule.rotations = {r: original[0].rotations[r] for r in s}
-        logger.debug(f"{i+1} / {len(negative_sets)} negative schedules: {rot}")
+        logging.debug(f"{i+1} / {len(negative_sets)} negative schedules: {rot}")
         scenario = schedule.run(args)
         if scenario.negative_soc_tracker:
             # still fail: try just the negative rotation
             schedule.rotations = {rot: original[0].rotations[rot]}
             scenario = schedule.run(args)
             if scenario.negative_soc_tracker:
                 # no hope, this just won't work
-                logger.info(f"Rotation {rot} will stay negative")
+                logging.info(f"Rotation {rot} will stay negative")
             else:
                 # works alone with other non-negative rotations
-                logger.info(f"Rotation {rot} works alone")
+                logging.info(f"Rotation {rot} works alone")
             ignored.append(rot)
 
     negative_sets = {k: v for k, v in negative_sets.items() if k not in ignored}
@@ -100,7 +91,7 @@ def service_optimization(schedule, scenario, args):
     # try to combine them
     possible = [(a, b) for a in negative_sets for b in negative_sets if a != b]
     while possible:
-        logger.debug(f"{len(possible)} combinations remain")
+        logging.debug(f"{len(possible)} combinations remain")
         r1, r2 = possible.pop()
         combined = negative_sets[r1].union(negative_sets[r2])
         schedule.rotations = {r: original[0].rotations[r] for r in combined}
@@ -115,7 +106,7 @@ def service_optimization(schedule, scenario, args):
             if optimal is None or len(scenario[0].rotations) > len(optimal[0].rotations):
                 optimal = (deepcopy(schedule), deepcopy(scenario))
 
-    logger.info(negative_sets)
+    logging.info("Service optimization finished")
 
     return {
         "original": original,

ebus_toolbox/report.py

@@ -2,8 +2,9 @@
 """
 import csv
 import datetime
-import warnings
+import logging
 import matplotlib.pyplot as plt
+import warnings
 from spice_ev.report import aggregate_global_results, plot, generate_reports
 
 
@@ -95,6 +96,29 @@ def generate_gc_overview(schedule, scenario, args):
                                  *use_factors])
 
 
+def generate_plots(scenario, args):
+    """Save plots as png and pdf.
+
+    :param scenario: Scenario to plot.
+    :type scenario: spice_ev.Scenario
+    :param args: Configuration. Uses results_directory and show_plots.
+    :type args: argparse.Namespace
+    """
+    aggregate_global_results(scenario)
+    # disable DEBUG logging from matplotlib
+    logging.disable(logging.INFO)
+    with plt.ion():  # make plotting temporarily interactive, so plt.show does not block
+        plt.clf()
+        plot(scenario)
+        plt.gcf().set_size_inches(10, 10)
+        plt.savefig(args.results_directory / "run_overview.png")
+        plt.savefig(args.results_directory / "run_overview.pdf")
+    if args.show_plots:
+        plt.show()
+    # revert logging override
+    logging.disable(logging.NOTSET)
+
+
 def generate(schedule, scenario, args):
     """Generates all output files/ plots and saves them in the output directory.
 
@@ -125,15 +149,7 @@ def generate(schedule, scenario, args):
     generate_gc_overview(schedule, scenario, args)
 
     # save plots as png and pdf
-    aggregate_global_results(scenario)
-    with plt.ion():     # make plotting temporarily interactive, so plt.show does not block
-        plt.clf()
-        plot(scenario)
-        plt.gcf().set_size_inches(10, 10)
-        plt.savefig(args.results_directory / "run_overview.png")
-        plt.savefig(args.results_directory / "run_overview.pdf")
-    if args.show_plots:
-        plt.show()
+    generate_plots(scenario, args)
 
     # calculate SOCs for each rotation
     rotation_infos = []
@@ -194,10 +210,10 @@ def generate(schedule, scenario, args):
         rotation_socs[id][start_idx:end_idx] = rotation_soc_ts
 
     if incomplete_rotations:
-        warnings.warn("SpiceEV stopped before simulation of the these rotations were completed:\n"
-                      f"{', '.join(incomplete_rotations)}\n"
-                      "Omit parameter <days> to simulate entire schedule.",
-                      stacklevel=100)
+        logging.warning(
+            "SpiceEV stopped before simulation of the these rotations were completed:\n"
+            f"{', '.join(incomplete_rotations)}\n"
+            "Omit parameter <days> to simulate entire schedule.")
 
     if rotation_infos:
         with open(args.results_directory / "rotation_socs.csv", "w", newline='') as f:
@@ -226,4 +242,4 @@ def generate(schedule, scenario, args):
                 else:
                     csv_writer.writerow([key, round(value, 2), "€"])
 
-    print("Plots and output files saved in", args.results_directory)
+    logging.info(f"Plots and output files saved in {args.results_directory}")

ebus_toolbox/schedule.py

@@ -1,8 +1,9 @@
 import csv
-import random
 import datetime
-import warnings
+import logging
 from pathlib import Path
+import random
+import warnings
 
 from ebus_toolbox import util
 from ebus_toolbox.rotation import Rotation
@@ -121,7 +122,7 @@ def from_csv(cls, path_to_csv, vehicle_types, stations, **kwargs):
                 with open(kwargs["output_directory"] / "inconsistent_rotations.csv", "w") as f:
                     for rot_id, e in inconsistent_rotations.items():
                         f.write(f"Rotation {rot_id}: {e}\n")
-                        print(f"Rotation {rot_id}: {e}")
+                        logging.error(f"Rotation {rot_id}: {e}")
                         if kwargs.get("skip_inconsistent_rotations"):
                             # remove this rotation from schedule
                             del schedule.rotations[rot_id]
@@ -186,12 +187,12 @@ def run(self, args):
 
         scenario = self.generate_scenario(args)
 
-        print("Running Spice EV...")
+        logging.info("Running SpiceEV...")
         with warnings.catch_warnings():
             warnings.simplefilter('ignore', UserWarning)
             scenario.run('distributed', vars(args).copy())
         assert scenario.step_i == scenario.n_intervals, \
-            'spiceEV simulation aborted, see above for details'
+            'SpiceEV simulation aborted, see above for details'
         return scenario
 
     def set_charging_type(self, ct, rotation_ids=None):
@@ -349,7 +350,7 @@ def get_common_stations(self, only_opps=True):
 
     def get_negative_rotations(self, scenario):
         """
-        Get rotations with negative soc from spice_ev outputs
+        Get rotations with negative soc from SpiceEV outputs
 
         :param scenario: Simulation scenario containing simulation results
                          including the SoC of all vehicles over time
@@ -421,13 +422,13 @@ def rotation_filter(self, args, rf_list=[]):
             self.rotations = {k: v for k, v in self.rotations.items() if k in rf_list}
 
     def generate_scenario(self, args):
-        """ Generate scenario.json for spiceEV
+        """ Generate scenario.json for SpiceEV
 
         :param args: Command line arguments and/or arguments from config file.
         :type args: argparse.Namespace
-        :return: A spiceEV Scenario instance that can be run and also collects all
+        :return: A SpiceEV Scenario instance that can be run and also collects all
                  simulation outputs.
-        :rtype:  spice_ev.Scenario
+        :rtype:  SpiceEV.Scenario
         """
 
         interval = datetime.timedelta(minutes=args.interval)
@@ -683,9 +684,9 @@ def generate_scenario(self, args):
                 events['energy_price_from_csv'] = options
                 price_csv_path = args.output_directory / filename
                 if not price_csv_path.exists():
-                    print("Warning: price csv file '{}' does not exist yet".format(price_csv_path))
+                    logging.warning(f"Price csv file '{price_csv_path}' does not exist yet")
 
-        # reformat vehicle types for spiceEV
+        # reformat vehicle types for SpiceEV
         vehicle_types_spiceev = {
             f'{vehicle_type}_{charging_type}': body
             for vehicle_type, subtypes in self.vehicle_types.items()