Merge pull request #1341 from pybamm-team/issue-1332-logging

#1332 add more logging levels

examples/scripts/cycling_ageing_yang.py

@@ -6,30 +6,40 @@
 model = pb.lithium_ion.DFN(options)
 experiment = pb.Experiment(
     [
-        "Charge at 1 C until 4.2 V",
-        "Hold at 4.2 V until C/10",
-        "Rest for 5 minutes",
-        "Discharge at 2 C until 2.8 V",
-        "Rest for 5 minutes",
+        (
+            "Charge at 1 C until 4.2 V",
+            "Hold at 4.2 V until C/10",
+            "Rest for 5 minutes",
+            "Discharge at 2 C until 2.8 V",
+            "Rest for 5 minutes",
+        ),
     ]
     * 2
     + [
-        "Charge at 1 C until 4.2 V",
-        "Hold at 4.2 V until C/20",
-        "Rest for 30 minutes",
-        "Discharge at C/3 until 2.8 V",
-        "Charge at 1 C until 4.2 V",
-        "Hold at 4.2 V until C/20",
-        "Rest for 30 minutes",
-        "Discharge at 1 C until 2.8 V",
-        "Charge at 1 C until 4.2 V",
-        "Hold at 4.2 V until C/20",
-        "Rest for 30 minutes",
-        "Discharge at 2 C until 2.8 V",
-        "Charge at 1 C until 4.2 V",
-        "Hold at 4.2 V until C/20",
-        "Rest for 30 minutes",
-        "Discharge at 3 C until 2.8 V",
+        (
+            "Charge at 1 C until 4.2 V",
+            "Hold at 4.2 V until C/20",
+            "Rest for 30 minutes",
+            "Discharge at C/3 until 2.8 V",
+        ),
+        (
+            "Charge at 1 C until 4.2 V",
+            "Hold at 4.2 V until C/20",
+            "Rest for 30 minutes",
+            "Discharge at 1 C until 2.8 V",
+        ),
+        (
+            "Charge at 1 C until 4.2 V",
+            "Hold at 4.2 V until C/20",
+            "Rest for 30 minutes",
+            "Discharge at 2 C until 2.8 V",
+        ),
+        (
+            "Charge at 1 C until 4.2 V",
+            "Hold at 4.2 V until C/20",
+            "Rest for 30 minutes",
+            "Discharge at 3 C until 2.8 V",
+        ),
     ]
 )
 sim = pb.Simulation(model, experiment=experiment, parameter_values=param)

pybamm/discretisations/discretisation.py

@@ -158,7 +158,7 @@ def process_model(self, model, inplace=True, check_model=True):
                     )
 
         # Set the y split for variables
-        pybamm.logger.info("Set variable slices for {}".format(model.name))
+        pybamm.logger.verbose("Set variable slices for {}".format(model.name))
         self.set_variable_slices(variables)
 
         # now add extrapolated external variables to the boundary conditions
@@ -167,9 +167,13 @@ def process_model(self, model, inplace=True, check_model=True):
         self.set_external_variables(model)
 
         # set boundary conditions (only need key ids for boundary_conditions)
-        pybamm.logger.info("Discretise boundary conditions for {}".format(model.name))
+        pybamm.logger.verbose(
+            "Discretise boundary conditions for {}".format(model.name)
+        )
         self.bcs = self.process_boundary_conditions(model)
-        pybamm.logger.info("Set internal boundary conditions for {}".format(model.name))
+        pybamm.logger.verbose(
+            "Set internal boundary conditions for {}".format(model.name)
+        )
         self.set_internal_boundary_conditions(model)
 
         # set up inplace vs not inplace
@@ -188,26 +192,26 @@ def process_model(self, model, inplace=True, check_model=True):
 
         model_disc.bcs = self.bcs
 
-        pybamm.logger.info("Discretise initial conditions for {}".format(model.name))
+        pybamm.logger.verbose("Discretise initial conditions for {}".format(model.name))
         ics, concat_ics = self.process_initial_conditions(model)
         model_disc.initial_conditions = ics
         model_disc.concatenated_initial_conditions = concat_ics
 
         # Discretise variables (applying boundary conditions)
         # Note that we **do not** discretise the keys of model.rhs,
         # model.initial_conditions and model.boundary_conditions
-        pybamm.logger.info("Discretise variables for {}".format(model.name))
+        pybamm.logger.verbose("Discretise variables for {}".format(model.name))
         model_disc.variables = self.process_dict(model.variables)
 
         # Process parabolic and elliptic equations
-        pybamm.logger.info("Discretise model equations for {}".format(model.name))
+        pybamm.logger.verbose("Discretise model equations for {}".format(model.name))
         rhs, concat_rhs, alg, concat_alg = self.process_rhs_and_algebraic(model)
         model_disc.rhs, model_disc.concatenated_rhs = rhs, concat_rhs
         model_disc.algebraic, model_disc.concatenated_algebraic = alg, concat_alg
 
         # Process events
         processed_events = []
-        pybamm.logger.info("Discretise events for {}".format(model.name))
+        pybamm.logger.verbose("Discretise events for {}".format(model.name))
         for event in model.events:
             pybamm.logger.debug("Discretise event '{}'".format(event.name))
             processed_event = pybamm.Event(
@@ -222,14 +226,14 @@ def process_model(self, model, inplace=True, check_model=True):
         ]
 
         # Create mass matrix
-        pybamm.logger.info("Create mass matrix for {}".format(model.name))
+        pybamm.logger.verbose("Create mass matrix for {}".format(model.name))
         model_disc.mass_matrix, model_disc.mass_matrix_inv = self.create_mass_matrix(
             model_disc
         )
 
         # Check that resulting model makes sense
         if check_model:
-            pybamm.logger.info("Performing model checks for {}".format(model.name))
+            pybamm.logger.verbose("Performing model checks for {}".format(model.name))
             self.check_model(model_disc)
 
         pybamm.logger.info("Finish discretising {}".format(model.name))

pybamm/logger.py

@@ -1,5 +1,10 @@
 #
 # Logging class for PyBaMM
+# Includes additional logging levels inspired by verboselogs
+# https://pypi.org/project/verboselogs/#overview-of-logging-levels
+#
+# Implementation from stackoverflow
+# https://stackoverflow.com/questions/2183233/how-to-add-a-custom-loglevel-to-pythons-logging-facility
 #
 import logging
 
@@ -15,6 +20,45 @@ def set_logging_level(level):
 logging.basicConfig(format=format)
 logging.Formatter(datefmt="%Y-%m-%d %H:%M:%S", fmt="%(asctime)s.%(msecs)03d")
 
+# Additional levels inspired by verboselogs
+SPAM_LEVEL_NUM = 5
+logging.addLevelName(SPAM_LEVEL_NUM, "SPAM")
+
+VERBOSE_LEVEL_NUM = 15
+logging.addLevelName(VERBOSE_LEVEL_NUM, "VERBOSE")
+
+NOTICE_LEVEL_NUM = 25
+logging.addLevelName(NOTICE_LEVEL_NUM, "NOTICE")
+
+SUCCESS_LEVEL_NUM = 35
+logging.addLevelName(SUCCESS_LEVEL_NUM, "SUCCESS")
+
+
+def spam(self, message, *args, **kws):
+    if self.isEnabledFor(SPAM_LEVEL_NUM):
+        self._log(SPAM_LEVEL_NUM, message, args, **kws)
+
+
+def verbose(self, message, *args, **kws):
+    if self.isEnabledFor(VERBOSE_LEVEL_NUM):
+        self._log(VERBOSE_LEVEL_NUM, message, args, **kws)
+
+
+def notice(self, message, *args, **kws):
+    if self.isEnabledFor(NOTICE_LEVEL_NUM):
+        self._log(NOTICE_LEVEL_NUM, message, args, **kws)
+
+
+def success(self, message, *args, **kws):
+    if self.isEnabledFor(SUCCESS_LEVEL_NUM):
+        self._log(SUCCESS_LEVEL_NUM, message, args, **kws)
+
+
+logging.Logger.spam = spam
+logging.Logger.verbose = verbose
+logging.Logger.notice = notice
+logging.Logger.success = success
+
 # Create a custom logger
 logger = logging.getLogger(__name__)
 set_logging_level("WARNING")

pybamm/models/full_battery_models/base_battery_model.py

@@ -629,7 +629,7 @@ def build_model(self):
                 `model.update` instead."""
             )
 
-        pybamm.logger.info("Building {}".format(self.name))
+        pybamm.logger.info("Start building {}".format(self.name))
 
         if self._built_fundamental_and_external is False:
             self.build_fundamental_and_external()
@@ -656,6 +656,7 @@ def build_model(self):
                 self.variables.update(var)
 
         self._built = True
+        pybamm.logger.info("Finish building {}".format(self.name))
 
     def new_empty_copy(self):
         "See :meth:`pybamm.BaseModel.new_empty_copy()`"

pybamm/parameters/parameter_values.py

@@ -371,21 +371,23 @@ def process_model(self, unprocessed_model, inplace=True):
 
         new_rhs = {}
         for variable, equation in unprocessed_model.rhs.items():
-            pybamm.logger.debug("Processing parameters for {!r} (rhs)".format(variable))
+            pybamm.logger.verbose(
+                "Processing parameters for {!r} (rhs)".format(variable)
+            )
             new_rhs[variable] = self.process_symbol(equation)
         model.rhs = new_rhs
 
         new_algebraic = {}
         for variable, equation in unprocessed_model.algebraic.items():
-            pybamm.logger.debug(
+            pybamm.logger.verbose(
                 "Processing parameters for {!r} (algebraic)".format(variable)
             )
             new_algebraic[variable] = self.process_symbol(equation)
         model.algebraic = new_algebraic
 
         new_initial_conditions = {}
         for variable, equation in unprocessed_model.initial_conditions.items():
-            pybamm.logger.debug(
+            pybamm.logger.verbose(
                 "Processing parameters for {!r} (initial conditions)".format(variable)
             )
             new_initial_conditions[variable] = self.process_symbol(equation)
@@ -395,15 +397,15 @@ def process_model(self, unprocessed_model, inplace=True):
 
         new_variables = {}
         for variable, equation in unprocessed_model.variables.items():
-            pybamm.logger.debug(
+            pybamm.logger.verbose(
                 "Processing parameters for {!r} (variables)".format(variable)
             )
             new_variables[variable] = self.process_symbol(equation)
         model.variables = new_variables
 
         new_events = []
         for event in unprocessed_model.events:
-            pybamm.logger.debug(
+            pybamm.logger.verbose(
                 "Processing parameters for event '{}''".format(event.name)
             )
             new_events.append(
@@ -413,7 +415,7 @@ def process_model(self, unprocessed_model, inplace=True):
             )
 
         for event in self.parameter_events:
-            pybamm.logger.debug(
+            pybamm.logger.verbose(
                 "Processing parameters for event '{}''".format(event.name)
             )
             new_events.append(
@@ -458,7 +460,7 @@ def process_boundary_conditions(self, model):
             for side in sides:
                 try:
                     bc, typ = bcs[side]
-                    pybamm.logger.debug(
+                    pybamm.logger.verbose(
                         "Processing parameters for {!r} ({} bc)".format(variable, side)
                     )
                     processed_bc = (self.process_symbol(bc), typ)