Add Logging

.en-custom.txt

@@ -365,6 +365,7 @@ Zhitenev
 3D
 3x2x1
 -
+-formatted
 -only
 -periodicity
 -valued

documentation/USAGE.rst

@@ -44,6 +44,50 @@ Python can be obtained from the :cite:`PythonReference`.
 As you gain experience, you may want to browse through the
 :ref:`FlagsAndEnvironmentVariables` that affect :term:`FiPy`.
 
+-------
+Logging
+-------
+
+Diagnostic information about a :term:`FiPy` run can be obtained using the
+:mod:`logging` module.  For example, at the beginning of your script, you
+can add::
+
+    >>> import logging
+    >>> log = logging.getLogger("fipy")
+    >>> console = logging.StreamHandler()
+    >>> console.setLevel(logging.INFO)
+    >>> log.addHandler(console)
+
+in order to see informational messages in the terminal.  To have more
+verbose debugging information save to a file::
+
+    >>> logfile = logging.FileHandler(filename="fipy.log")
+    >>> logfile.setLevel(logging.DEBUG)
+    >>> log.addHandler(logfile)
+
+    >>> log.setLevel(logging.DEBUG)
+
+To restrict logging to, e.g., information about the :term:`PETSc` solvers::
+
+    >>> petsc = logging.Filter('fipy.solvers.petsc')
+    >>> logfile.addFilter(petsc)
+
+More complex configurations can be specified by setting the
+:envvar:`FIPY_LOG_CONFIG` environment variable.  In this case, it is not
+necessary to add any logging instructions to your own script.  Example
+configuration files can be found in
+:file:`{FiPySource}/fipy/tools/logging/`.
+
+If `Solving in Parallel`_, the :mod:`mpilogging` package enables reporting
+which MPI rank each log entry comes from.  For example::
+
+    >>> from mpilogging import MPIScatteredFileHandler
+    >>> mpilog = MPIScatteredFileHandler(filepattern="fipy.%(mpirank)d_of_%(mpisize)d.log"
+    >>> mpilog.setLevel(logging.DEBUG)
+    >>> log.addHandler(mpilog)
+
+will generate a unique log file for each MPI rank.
+
 ------------
 Testing FiPy
 ------------
@@ -212,6 +256,12 @@ package.
    that produced a particular piece of :mod:`weave` C code. Useful
    for debugging.
 
+.. envvar:: FIPY_LOG_CONFIG
+
+   Specifies a :term:`JSON`-formatted logging configuration file, suitable
+   for passing to :func:`logging.config.dictConfig`.  Example configuration
+   files can be found in :file:`{FiPySource}/fipy/tools/logging/`.
+
 .. envvar:: FIPY_SOLVERS
 
    Forces the use of the specified suite of linear solvers.  Valid
@@ -220,8 +270,10 @@ package.
 
 .. envvar:: FIPY_VERBOSE_SOLVER
 
-   If present, causes the linear solvers to print a variety of diagnostic
-   information.
+   If present, causes the
+   :class:`~fipy.solvers.pyAMG.linearGeneralSolver.LinearGeneralSolver` to
+   print a variety of diagnostic information.  All other solvers should use
+   `Logging`_ and :envvar:`FIPY_LOG_CONFIG`.
 
 .. envvar:: FIPY_VIEWER
 

documentation/glossary.rst

@@ -50,6 +50,11 @@ Glossary
       An improved :term:`Python` shell that integrates nicely with
       :ref:`MATPLOTLIB`. See http://ipython.scipy.org/.
 
+   JSON
+      JavaScript Open Notation.  A text format suitable for storing
+      structured information such as :keyword:`dict` or :keyword:`list`.
+      See https://www.json.org/.
+
    linux
       An operating system.
       See http://www.linux.org.

fipy/__init__.py

@@ -35,8 +35,37 @@
 from builtins import input
 __docformat__ = 'restructuredtext'
 
+import os
+
+# configure logging before doing anything else, otherwise we'll miss things
+if 'FIPY_LOG_CONFIG' in os.environ:
+    import json
+    import logging.config
+    with open(os.environ['FIPY_LOG_CONFIG'], mode='r') as fp:
+        logging.config.dictConfig(json.load(fp))
+
+import logging
+
+_log = logging.getLogger(__name__)
+
+from ._version import get_versions
+__version__ = get_versions()['version']
+del get_versions
+
 import sys
 
+# log uncaught exceptions
+def excepthook(*args):
+  _log.error('Uncaught exception:', exc_info=args)
+
+sys.excepthook = excepthook
+
+from fipy.tools.logging import package_info
+
+_log.info(package_info())
+del package_info
+
+
 from fipy.boundaryConditions import *
 from fipy.meshes import *
 from fipy.solvers import *
@@ -143,7 +172,3 @@ def test(*args):
         import shutil
         shutil.rmtree(tmpDir)
         raise exitErr
-
-from ._version import get_versions
-__version__ = get_versions()['version']
-del get_versions

fipy/meshes/gmshMesh.py

@@ -7,13 +7,16 @@
 from builtins import str
 __docformat__ = 'restructuredtext'
 
+import logging
 import os
 from subprocess import Popen, PIPE
 import sys
 import tempfile
 from textwrap import dedent
 import warnings
 
+_log = logging.getLogger(__name__)
+
 from fipy.tools import numerix as nx
 from fipy.tools import parallelComm
 from fipy.tools import serialComm
@@ -47,11 +50,6 @@ def _checkForGmsh():
                  test=_checkForGmsh,
                  why="`gmsh` cannot be found on the $PATH")
 
-def parprint(str):
-    if DEBUG:
-        if parallelComm.procID == 0:
-            print(str, file=sys.stderr)
-
 class GmshException(Exception):
     pass
 
@@ -241,7 +239,7 @@ def openMSHFile(name, dimensions=None, coordDimensions=None, communicator=parall
 
                 gmshOutput = gmshOutput.decode('ascii')
 
-                parprint("gmsh out: %s" % gmshOutput)
+                _log.debug("gmsh out: %s" % gmshOutput)
             else:
                 mshFile = None
                 gmshOutput = ""
@@ -798,7 +796,7 @@ def read(self):
             else:
                 raise GmshException("Mesh has fewer than 2 or more than 3 dimensions")
 
-            parprint("Parsing elements.")
+            _log.debug("Parsing elements.")
             (cellsData,
              ghostsData,
              facesData) = self._parseElementFile()
@@ -818,15 +816,15 @@ def read(self):
                 errStr += "\n\nGmsh output:\n%s" % "".join(self.gmshOutput).rstrip()
                 raise GmshException(errStr)
 
-            parprint("Recovering coords.")
-            parprint("numcells %d" % numCellsTotal)
+            _log.debug("Recovering coords.")
+            _log.debug("numcells %d" % numCellsTotal)
             vertexCoords, vertIDtoIdx = self._vertexCoordsAndMap(cellsToGmshVerts)
 
             # translate Gmsh IDs to `vertexCoord` indices
             cellsToVertIDs = self._translateNodesToVertices(cellsToGmshVerts,
                                                             vertIDtoIdx)
 
-            parprint("Building cells and faces.")
+            _log.debug("Building cells and faces.")
             (facesToV,
              cellsToF,
              facesDict) = self._deriveCellsAndFaces(cellsToVertIDs,
@@ -870,7 +868,7 @@ def read(self):
         cellsToVertIDs = [nx.concatenate((v, nx.array([-1] * (maxVerts-len(v)), dtype=nx.INT_DTYPE))) for v in cellsToVertIDs]
         cellsToVertIDs = nx.MA.masked_equal(cellsToVertIDs, value=-1).swapaxes(0, 1)
 
-        parprint("Done with cells and faces.")
+        _log.debug("Done with cells and faces.")
         return (vertexCoords, facesToV, cellsToF,
                 cellsData.idmap, ghostsData.idmap,
                 cellsToVertIDs)
@@ -1626,8 +1624,8 @@ def __init__(self,
 
         if communicator.Nproc > 1:
             self.globalNumberOfCells = communicator.sum(len(self.cellGlobalIDs))
-            parprint("  I'm solving with %d cells total." % self.globalNumberOfCells)
-            parprint("  Got global number of cells")
+            _log.debug("  I'm solving with %d cells total." % self.globalNumberOfCells)
+            _log.debug("  Got global number of cells")
 
         Mesh2D.__init__(self, vertexCoords=verts,
                               faceVertexIDs=faces,
@@ -1644,7 +1642,7 @@ def __init__(self,
 
         del self.mshFile
 
-        parprint("Exiting Gmsh2D")
+        _log.debug("Exiting Gmsh2D")
 
     def __setstate__(self, state):
         super(Gmsh2D, self).__setstate__(state)

fipy/solvers/__init__.py

@@ -1,5 +1,10 @@
 from __future__ import unicode_literals
 from builtins import str
+
+import logging
+
+_log = logging.getLogger(__name__)
+
 import os
 from importlib import import_module
 
@@ -169,3 +174,11 @@ def _import_mesh_matrices(suite):
                  why="the PyAMGX solver is being used.",
                  skipWarning=True)
 del register_skipper
+
+_log.info("Solver suite is %s", solver)
+_log.debug("DefaultSolver is %s", DefaultSolver)
+_log.debug("DefaultAsymmetricSolver is %s", DefaultAsymmetricSolver)
+_log.debug("DummySolver is %s", DummySolver)
+_log.debug("GeneralSolver is %s", GeneralSolver)
+_log.debug("serialComm is %s", serialComm)
+_log.debug("parallelComm is %s", parallelComm)

fipy/solvers/petsc/__init__.py

@@ -1,3 +1,7 @@
+import logging
+
+_log = logging.getLogger(__name__)
+
 from fipy.solvers.petsc.linearLUSolver import *
 from fipy.solvers.petsc.linearPCGSolver import *
 from fipy.solvers.petsc.linearGMRESSolver import *

fipy/solvers/petsc/linearLUSolver.py

@@ -3,8 +3,6 @@
 from past.utils import old_div
 __docformat__ = 'restructuredtext'
 
-import os
-
 from petsc4py import PETSc
 
 from fipy.solvers.petsc.petscSolver import PETScSolver
@@ -58,12 +56,7 @@ def _solve_(self, L, x, b):
             ksp.solve(errorVector, xError)
             x -= xError
 
-        if 'FIPY_VERBOSE_SOLVER' in os.environ:
-            from fipy.tools.debug import PRINT
-#             L.view()
-#             b.view()
-            PRINT('solver:', ksp.type)
-            PRINT('precon:', ksp.getPC().type)
-            PRINT('iterations: %d / %d' % (iteration+1, self.iterations))
-            PRINT('residual:', errorVector.norm(1))
-
+        self._log.debug('solver: %s', ksp.type)
+        self._log.debug('precon: %s', ksp.getPC().type)
+        self._log.debug('iterations: %d / %d', iteration+1, self.iterations)
+        self._log.debug('residual: %s', errorVector.norm(1))

fipy/solvers/petsc/petscKrylovSolver.py

@@ -1,7 +1,5 @@
 __docformat__ = 'restructuredtext'
 
-import os
-
 from petsc4py import PETSc
 
 from fipy.solvers.petsc.petscSolver import PETScSolver
@@ -63,13 +61,9 @@ def _solve_(self, L, x, b):
         ksp.setFromOptions()
         ksp.solve(b, x)
 
-        if 'FIPY_VERBOSE_SOLVER' in os.environ:
-            from fipy.tools.debug import PRINT
-#             L.view()
-#             b.view()
-            PRINT('solver:', ksp.type)
-            PRINT('precon:', ksp.getPC().type)
-            PRINT('convergence: %s' % _reason[ksp.reason])
-            PRINT('iterations: %d / %d' % (ksp.its, self.iterations))
-            PRINT('norm:', ksp.norm)
-            PRINT('norm_type:', ksp.norm_type)
+        self._log.debug('solver: %s', ksp.type)
+        self._log.debug('precon: %s', ksp.getPC().type)
+        self._log.debug('convergence: %s', _reason[ksp.reason])
+        self._log.debug('iterations: %d / %d', ksp.its, self.iterations)
+        self._log.debug('norm: %s', ksp.norm)
+        self._log.debug('norm_type: %s', ksp.norm_type)

fipy/solvers/pyAMG/__init__.py

@@ -1,4 +1,9 @@
 from __future__ import unicode_literals
+
+import logging
+
+_log = logging.getLogger(__name__)
+
 from fipy.solvers.pyAMG.linearGMRESSolver import *
 from fipy.solvers.pyAMG.linearCGSSolver import *
 from fipy.solvers.pyAMG.linearPCGSolver import *

fipy/solvers/pyamgx/__init__.py

@@ -1,4 +1,9 @@
 from __future__ import unicode_literals
+
+import logging
+
+_log = logging.getLogger(__name__)
+
 import atexit
 
 import pyamgx

fipy/solvers/pysparse/__init__.py

@@ -1,4 +1,9 @@
 from __future__ import unicode_literals
+
+import logging
+
+_log = logging.getLogger(__name__)
+
 from fipy.solvers.pysparse.linearCGSSolver import *
 from fipy.solvers.pysparse.linearPCGSolver import *
 from fipy.solvers.pysparse.linearGMRESSolver import *

fipy/solvers/pysparse/linearLUSolver.py

@@ -4,15 +4,11 @@
 from builtins import range
 __docformat__ = 'restructuredtext'
 
-import os
-
 from pysparse.direct import superlu
 
 from fipy.solvers.pysparse.pysparseSolver import PysparseSolver
 from fipy.tools import numerix
 
-DEBUG = False
-
 __all__ = ["LinearLUSolver"]
 from future.utils import text_to_native_str
 __all__ = [text_to_native_str(n) for n in __all__]
@@ -60,10 +56,6 @@ def _solve_(self, L, x, b):
 
         LU = superlu.factorize(L.matrix.to_csr())
 
-        if DEBUG:
-            import sys
-            print(L.matrix, file=sys.stderr)
-
         error0 = numerix.sqrt(numerix.sum((L * x - b)**2))
 
         for iteration in range(self.iterations):
@@ -76,7 +68,5 @@ def _solve_(self, L, x, b):
             LU.solve(errorVector, xError)
             x[:] = x - xError
 
-        if 'FIPY_VERBOSE_SOLVER' in os.environ:
-            from fipy.tools.debug import PRINT
-            PRINT('iterations: %d / %d' % (iteration+1, self.iterations))
-            PRINT('residual:', numerix.sqrt(numerix.sum(errorVector**2)))
+        self._log.debug('iterations: %d / %d', iteration+1, self.iterations)
+        self._log.debug('residual: %s', numerix.sqrt(numerix.sum(errorVector**2)))