Repository: pybamm-team/PyBaMM

Issue:
Logging
Use the [logging](https://docs.python.org/3/library/logging.html) module to give (optional) command-line updates about the progress of a simulation, e.g.
```
Creating Single Particle Model ... done
Parametrising Single Particle Model ... done
Discretising Single Particle Model ... done
Solving Single Particle Model ... 
   Simplifying ... done
   Calculating jacobian ... done
   Solving ... done
```

Discussion:

Patch:
diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md
index b34266dce..a96a29c6c 100644
--- a/CONTRIBUTING.md
+++ b/CONTRIBUTING.md
@@ -233,6 +233,10 @@ Figuring out where to start the debugger is the real challenge. Some good ways t
   You can then step through the expression tree, using the `children` attribute, to pinpoint exactly where a bug is coming from. For example, if `expression_tree.jac(y)` is failing, you can check `expression_tree.children[0].jac(y)`, then `expression_tree.children[0].children[0].jac(y)`, etc.
 3. To isolate whether a bug is in a model, its jacobian or its simplified version, you can set the `use_jacobian` and/or `use_simplify` attributes of the model to `False` (they are both `True` by default for most models).
 4. If a model isn't giving the answer you expect, you can try comparing it to other models. For example, you can investigate parameter limits in which two models should give the same answer by setting some parameters to be small or zero. The `StandardOutputComparison` class can be used to compare some standard outputs from battery models.
+5. To get more information about what is going on under the hood, and hence understand what is causing the bug, you can set the [logging](https://realpython.com/python-logging/) level to `DEBUG` by adding the following line to your test or script:
+```python3
+pybamm.set_logging_level("DEBUG")
+```
 
 ### Profiling
 
diff --git a/examples/scripts/compare_lead_acid.py b/examples/scripts/compare_lead_acid.py
index 5cf1c3e47..abc815415 100644
--- a/examples/scripts/compare_lead_acid.py
+++ b/examples/scripts/compare_lead_acid.py
@@ -1,5 +1,7 @@
-import pybamm
 import numpy as np
+import pybamm
+
+pybamm.set_logging_level("INFO")
 
 # load models
 models = [
diff --git a/pybamm/__init__.py b/pybamm/__init__.py
index 4dd9daf4d..4da92c650 100644
--- a/pybamm/__init__.py
+++ b/pybamm/__init__.py
@@ -44,6 +44,7 @@ ABSOLUTE_PATH = os.path.join(os.path.split(script_path)[0], "..")
 from .util import Timer
 from .util import profile
 from .util import load_function
+from .logger import logger, set_logging_level
 
 #
 # Classes for the Expression Tree
@@ -100,7 +101,12 @@ from .expression_tree.independent_variable import (
 from .expression_tree.independent_variable import t
 from .expression_tree.vector import Vector, StateVector
 
-from .expression_tree.exceptions import DomainError, ModelError, SolverError, ModelWarning
+from .expression_tree.exceptions import (
+    DomainError,
+    ModelError,
+    SolverError,
+    ModelWarning,
+)
 from .expression_tree.simplify import (
     simplify,
     simplify_if_constant,
diff --git a/pybamm/discretisations/discretisation.py b/pybamm/discretisations/discretisation.py
index 321a0801e..bd0d5cb54 100644
--- a/pybamm/discretisations/discretisation.py
+++ b/pybamm/discretisations/discretisation.py
@@ -62,6 +62,8 @@ class Discretisation(object):
             ``inplace`` is False, model != model_disc
 
         """
+        pybamm.logger.info("Start discretising {}".format(model.name))
+
         # Prepare discretisation
         # set variables (we require the full variable not just id)
         variables = list(model.rhs.keys()) + list(model.algebraic.keys())
@@ -108,6 +110,8 @@ class Discretisation(object):
         # Check that resulting model makes sense
         self.check_model(model_disc)
 
+        pybamm.logger.info("Finish discretising {}".format(model.name))
+
         return model_disc
 
     def set_variable_slices(self, variables):
@@ -349,6 +353,8 @@ class Discretisation(object):
             Discretised symbol
 
         """
+        pybamm.logger.debug("Discretise {!s}".format(symbol))
+
         if isinstance(symbol, pybamm.BinaryOperator):
             # Pre-process children
             left, right = symbol.children
diff --git a/pybamm/expression_tree/simplify.py b/pybamm/expression_tree/simplify.py
index e72a03708..77e6a0f6f 100644
--- a/pybamm/expression_tree/simplify.py
+++ b/pybamm/expression_tree/simplify.py
@@ -142,8 +142,9 @@ def simplify_addition_subtraction(myclass, left, right):
     # simplify identical terms
     i = 0
     while i < len(numerator) - 1:
-        if isinstance(numerator[i], pybamm.Multiplication) and \
-                isinstance(numerator[i].children[0], pybamm.Scalar):
+        if isinstance(numerator[i], pybamm.Multiplication) and isinstance(
+            numerator[i].children[0], pybamm.Scalar
+        ):
             term_i = numerator[i].orphans[1]
             term_i_count = numerator[i].children[0].evaluate()
         else:
@@ -151,8 +152,9 @@ def simplify_addition_subtraction(myclass, left, right):
             term_i_count = 1
 
         # loop through rest of numerator counting up and deleting identical terms
-        for j, (term_j, typ_j) in \
-                enumerate(zip(numerator[i + 1:], numerator_types[i + 1:])):
+        for j, (term_j, typ_j) in enumerate(
+            zip(numerator[i + 1 :], numerator_types[i + 1 :])
+        ):
             if term_i.id == term_j.id:
                 if typ_j == pybamm.Addition:
                     term_i_count += 1
@@ -542,6 +544,8 @@ def simplify(symbol):
     :class:`pybamm.Symbol`
         Simplified symbol
     """
+    pybamm.logger.debug("Simplify {!s}".format(symbol))
+
     if isinstance(symbol, pybamm.BinaryOperator):
         left, right = symbol.children
         # process children
diff --git a/pybamm/logger.py b/pybamm/logger.py
new file mode 100644
index 000000000..6d6de2a82
--- /dev/null
+++ b/pybamm/logger.py
@@ -0,0 +1,17 @@
+#
+# Logging class for PyBaMM
+#
+import logging
+
+format = (
+    "%(asctime)s - [%(levelname)s] %(module)s.%(funcName)s(%(lineno)d): "
+    + "%(message)s"
+)
+logging.basicConfig(format=format, datefmt="%Y-%m-%d %H:%M:%S")
+
+# Create a custom logger
+logger = logging.getLogger(__name__)
+
+
+def set_logging_level(level):
+    logger.setLevel(level)
diff --git a/pybamm/models/base_models.py b/pybamm/models/base_models.py
index 2e37a660d..57f8e2e1e 100644
--- a/pybamm/models/base_models.py
+++ b/pybamm/models/base_models.py
@@ -40,6 +40,9 @@ class BaseModel(object):
     """
 
     def __init__(self):
+        # Default name
+        self.name = "Unnamed Model"
+
         # Initialise empty model
         self._rhs = {}
         self._algebraic = {}
@@ -327,9 +330,7 @@ class BaseModel(object):
             warnings.warn(
                 "the standard output variable(s) '{}' have not been supplied. "
                 "These may be required for testing or comparison with other "
-                "models.".format(
-                    missing_vars
-                ),
+                "models.".format(missing_vars),
                 pybamm.ModelWarning,
                 stacklevel=2,
             )
diff --git a/pybamm/parameters/parameter_values.py b/pybamm/parameters/parameter_values.py
index c10c0a063..1b2a7b5ef 100644
--- a/pybamm/parameters/parameter_values.py
+++ b/pybamm/parameters/parameter_values.py
@@ -2,7 +2,6 @@
 # Dimensional and dimensionless parameter values, and scales
 #
 import pybamm
-
 import pandas as pd
 
 
@@ -75,6 +74,8 @@ class ParameterValues(dict):
             model (update the value of any Scalars in the expression tree.)
 
         """
+        pybamm.logger.info("Start setting parameters for {}".format(model.name))
+
         if processing == "process":
             processing_function = self.process_symbol
         elif processing == "update":
@@ -106,6 +107,8 @@ class ParameterValues(dict):
         for idx, equation in enumerate(model.events):
             model.events[idx] = processing_function(equation)
 
+        pybamm.logger.info("Finish setting parameters for {}".format(model.name))
+
     def update_model(self, model, disc):
         """Process a discretised model.
         Currently inplace, could be changed to return a new model.
@@ -161,6 +164,8 @@ class ParameterValues(dict):
             Symbol with Parameter instances replaced by Value
 
         """
+        pybamm.logger.debug("Set parameters for {!s}".format(symbol))
+
         if isinstance(symbol, pybamm.Parameter):
             value = self[symbol.name]
             # Scalar inherits name (for updating parameters) and domain (for Broadcast)
diff --git a/pybamm/solvers/dae_solver.py b/pybamm/solvers/dae_solver.py
index 0c6b94220..f77d8d583 100644
--- a/pybamm/solvers/dae_solver.py
+++ b/pybamm/solvers/dae_solver.py
@@ -52,6 +52,7 @@ class DaeSolver(pybamm.BaseSolver):
             The times at which to compute the solution
 
         """
+        pybamm.logger.info("Start solving {}".format(model.name))
 
         # create simplified rhs algebraic and event expressions
         concatenated_rhs = model.concatenated_rhs
@@ -63,6 +64,9 @@ class DaeSolver(pybamm.BaseSolver):
             events = [event.simplify() for event in events]
 
         def residuals(t, y, ydot):
+            pybamm.logger.debug(
+                "Evaluating residuals for {} at t={}".format(model.name, t)
+            )
             rhs_eval, known_evals = concatenated_rhs.evaluate(t, y, known_evals={})
             # reuse known_evals
             concat_evals = concatenated_algebraic.evaluate(
@@ -115,6 +119,8 @@ class DaeSolver(pybamm.BaseSolver):
             jacobian=jacobian,
         )
 
+        pybamm.logger.info("Finish solving {}".format(model.name))
+
     def calculate_consistent_initial_conditions(self, rhs, algebraic, y0_guess):
         """
         Calculate consistent initial conditions for the algebraic equations through
diff --git a/pybamm/solvers/ode_solver.py b/pybamm/solvers/ode_solver.py
index 2a04dcfbe..d33e88ae2 100644
--- a/pybamm/solvers/ode_solver.py
+++ b/pybamm/solvers/ode_solver.py
@@ -29,6 +29,7 @@ class OdeSolver(pybamm.BaseSolver):
             The times at which to compute the solution
 
         """
+        pybamm.logger.info("Start solving {}".format(model.name))
 
         concatenated_rhs = model.concatenated_rhs
         events = model.events
@@ -38,6 +39,7 @@ class OdeSolver(pybamm.BaseSolver):
             events = [event.simplify() for event in events]
 
         def dydt(t, y):
+            pybamm.logger.debug("Evaluating RHS for {} at t={}".format(model.name, t))
             return concatenated_rhs.evaluate(t, y, known_evals={})[0]
 
         # Create event-dependent function to evaluate events
@@ -73,6 +75,8 @@ class OdeSolver(pybamm.BaseSolver):
             jacobian=jacobian,
         )
 
+        pybamm.logger.info("Finish solving {}".format(model.name))
+
     def integrate(
         self, derivs, y0, t_eval, events=None, mass_matrix=None, jacobian=None
     ):


Test patch:
diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py
new file mode 100644
index 000000000..5698a29d2
--- /dev/null
+++ b/tests/unit/test_logger.py
@@ -0,0 +1,24 @@
+#
+# Tests the logger class.
+#
+import pybamm
+import unittest
+
+
+class TestLogger(unittest.TestCase):
+    def test_logger(self):
+        logger = pybamm.logger
+        self.assertEqual(logger.level, 0)
+        pybamm.set_logging_level("INFO")
+        self.assertEqual(logger.level, 20)
+        pybamm.set_logging_level("WARNING")
+        self.assertEqual(logger.level, 30)
+
+
+if __name__ == "__main__":
+    print("Add -v for more debug output")
+    import sys
+
+    if "-v" in sys.argv:
+        debug = True
+    unittest.main()