Updated logging capabilities

gusto/__init__.py

@@ -12,6 +12,7 @@
 from gusto.labels import *                           # noqa
 from gusto.limiters import *                         # noqa
 from gusto.linear_solvers import *                   # noqa
+from gusto.logging import *                          # noqa
 from gusto.meshes import *                           # noqa
 from gusto.physics import *                          # noqa
 from gusto.preconditioners import *                  # noqa
@@ -21,3 +22,5 @@
 from gusto.timeloop import *                         # noqa
 from gusto.transport_methods import *                # noqa
 from gusto.wrappers import *                         # noqa
+
+set_log_handler()

gusto/active_tracers.py

@@ -8,7 +8,8 @@
 """
 
 from enum import Enum
-from gusto.configuration import TransportEquationType, logger
+from gusto.configuration import TransportEquationType
+from gusto.logging import logger
 
 __all__ = ["TracerVariableType", "Phases", "ActiveTracer",
            "WaterVapour", "CloudWater", "Rain"]

gusto/configuration.py

@@ -1,35 +1,17 @@
 """Some simple tools for configuring the model."""
 from abc import ABCMeta, abstractproperty
+from datetime import datetime
 from enum import Enum
-import logging
-from logging import DEBUG, INFO, WARNING
 from firedrake import sqrt, Constant
+from gusto.logging import logger, WARNING
 
 
-__all__ = ["WARNING", "INFO", "DEBUG", "IntegrateByParts",
-           "TransportEquationType", "OutputParameters",
-           "CompressibleParameters", "ShallowWaterParameters",
-           "logger", "EmbeddedDGOptions", "RecoveryOptions", "SUPGOptions",
-           "SpongeLayerParameters", "DiffusionParameters"]
-
-logger = logging.getLogger("gusto")
-
-
-def set_log_handler(comm):
-    """
-    Sets the handler for logging.
-
-    Args:
-        comm (:class:`MPI.Comm`): MPI communicator.
-    """
-    handler = logging.StreamHandler()
-    handler.setFormatter(logging.Formatter(fmt="%(name)s:%(levelname)s %(message)s"))
-    if logger.hasHandlers():
-        logger.handlers.clear()
-    if comm.rank == 0:
-        logger.addHandler(handler)
-    else:
-        logger.addHandler(logging.NullHandler())
+__all__ = [
+    "IntegrateByParts", "TransportEquationType", "OutputParameters",
+    "CompressibleParameters", "ShallowWaterParameters",
+    "EmbeddedDGOptions", "RecoveryOptions", "SUPGOptions",
+    "SpongeLayerParameters", "DiffusionParameters"
+]
 
 
 class IntegrateByParts(Enum):
@@ -87,12 +69,15 @@ def __setattr__(self, name, value):
             AttributeError: if the :class:`Configuration` object does not have
                 this attribute pre-defined.
         """
+        if name == 'log_level':
+            logger.warning("Set log level with environemnt variables, see `logging.py` for details")
+            return
         if not hasattr(self, name):
             raise AttributeError("'%s' object has no attribute '%s'" % (type(self).__name__, name))
 
         # Almost all parameters should be Constants -- but there are some
         # specific exceptions which should be kept as integers
-        if type(value) in [float, int] and name not in ['dumpfreq', 'pddumpfreq', 'chkptfreq', 'log_level']:
+        if type(value) in [float, int] and name not in ['dumpfreq', 'pddumpfreq', 'chkptfreq']:
             object.__setattr__(self, name, Constant(value))
         else:
             object.__setattr__(self, name, value)
@@ -101,9 +86,6 @@ def __setattr__(self, name, value):
 class OutputParameters(Configuration):
     """Parameters for controlling outputting."""
 
-    #: log_level for logger, can be DEBUG, INFO or WARNING. Takes
-    #: default value "warning"
-    log_level = WARNING
     dump_vtus = True
     dump_nc = False
     dumpfreq = 1

gusto/coordinates.py

@@ -3,7 +3,7 @@
 Coordinate fields are stored in specified VectorFunctionSpaces.
 """
 
-from gusto.configuration import logger
+from gusto.logging import logger
 from firedrake import (SpatialCoordinate, sqrt, atan_2, asin, Function)
 import numpy as np
 

gusto/forcing.py

@@ -1,11 +1,15 @@
 """Discretisation of dynamic forcing terms, such as the pressure gradient."""
 
-from firedrake import (Function, TrialFunctions, DirichletBC,
-                       LinearVariationalProblem, LinearVariationalSolver)
-from gusto.configuration import logger, DEBUG
-from gusto.labels import (transport, diffusion, name, time_derivative,
-                          replace_subject, hydrostatic)
+from firedrake import (
+    Function, TrialFunctions, DirichletBC, LinearVariationalProblem,
+    LinearVariationalSolver
+)
 from gusto.fml.form_manipulation_labelling import drop
+from gusto.labels import (
+    transport, diffusion, name, time_derivative, replace_subject,
+    hydrostatic
+)
+from gusto.logging import logger, DEBUG
 
 
 __all__ = ["Forcing"]

gusto/initialisation_tools.py

@@ -9,7 +9,7 @@
     sin, cos, sqrt, asin, atan_2, as_vector, min_value, max_value, FunctionSpace, \
     errornorm, zero
 from gusto import thermodynamics
-from gusto.configuration import logger
+from gusto.logging import logger
 from gusto.recovery import Recoverer, BoundaryMethod
 
 

gusto/io.py

@@ -10,7 +10,7 @@
 from firedrake import (Function, functionspaceimpl, File,
                        DumbCheckpoint, FILE_CREATE, FILE_READ, CheckpointFile)
 import numpy as np
-from gusto.configuration import logger, set_log_handler
+from gusto.logging import logger
 
 __all__ = ["pick_up_mesh", "IO"]
 
@@ -222,10 +222,6 @@ def __init__(self, domain, output, diagnostics=None, diagnostic_fields=None):
         self.dumpfile = None
         self.to_pick_up = None
 
-        # setup logger
-        logger.setLevel(output.log_level)
-        set_log_handler(self.mesh.comm)
-
     def log_parameters(self, equation):
         """
         Logs an equation's physical parameters that take non-default values.

gusto/linear_solvers.py

@@ -15,7 +15,7 @@
 from pyop2.profiling import timed_function, timed_region
 
 from gusto.active_tracers import TracerVariableType
-from gusto.configuration import logger, DEBUG
+from gusto.logging import logger, DEBUG
 from gusto.labels import linearisation, time_derivative, hydrostatic
 from gusto import thermodynamics
 from gusto.fml.form_manipulation_labelling import Term, drop
@@ -152,13 +152,8 @@ def __init__(self, equations, alpha=0.5,
             self.quadrature_degree = (5, 5)
 
         if logger.isEnabledFor(DEBUG):
-            # Set outer solver to FGMRES and turn on KSP monitor for the outer system
-            self.solver_parameters["ksp_type"] = "fgmres"
-            self.solver_parameters["mat_type"] = "aij"
-            self.solver_parameters["pmat_type"] = "matfree"
             self.solver_parameters["ksp_monitor_true_residual"] = None
-
-            # Turn monitor on for the trace system
+            # Turn monitor on for the trace system too
             self.solver_parameters["condensed_field"]["ksp_monitor_true_residual"] = None
 
         super().__init__(equations, alpha, solver_parameters,

gusto/logging.py

@@ -0,0 +1,101 @@
+import logging
+import sys
+import os
+
+from datetime import datetime
+from logging import NOTSET, DEBUG, INFO, WARNING, ERROR, CRITICAL  # noqa: F401
+
+from pyop2.mpi import COMM_WORLD
+
+__all__ = ["logger", "set_log_handler"]
+
+logging.captureWarnings(True)
+logger = logging.getLogger("gusto")
+
+# Set the log level based on environment variables
+log_level = os.environ.get("GUSTO_LOG_LEVEL", WARNING)
+logfile_level = os.environ.get("GUSTO_FILE_LOG_LEVEL", DEBUG)
+logconsole_level = os.environ.get("GUSTO_CONSOLE_LOG_LEVEL", INFO)
+log_level_list = [log_level, logfile_level, logconsole_level]
+log_levels = [
+    logging.getLevelNamesMapping().get(x) if isinstance(x, str)
+    else x
+    for x in log_level_list
+]
+logger.setLevel(min(log_levels))
+
+# Setup parallel logging based on environment variables
+parallel_log = os.environ.get("GUSTO_PARALLEL_LOG", None)
+options = ["CONSOLE", "FILE", "BOTH"]
+if parallel_log is not None:
+    parallel_log = parallel_log.upper()
+    if parallel_log.upper() not in options:
+        parallel_log = None
+
+
+def create_logfile_handler(path):
+    ''' Handler for logfiles
+
+    Args:
+        path: path to log file
+
+    '''
+    logfile = logging.FileHandler(filename=path, mode="w")
+    logfile.setLevel(logfile_level)
+    logfile_formatter = logging.Formatter(
+        '%(asctime)s %(levelname)-8s %(message)s'
+    )
+    logfile.setFormatter(logfile_formatter)
+    return logfile
+
+
+def create_console_handler(fmt):
+    ''' Handler for console logging
+
+    Args:
+        fmt: format string for log output
+    '''
+    console = logging.StreamHandler()
+    console.setLevel(logconsole_level)
+    console_formatter = logging.Formatter(fmt)
+    console.setFormatter(console_formatter)
+    return console
+
+
+def set_log_handler(comm=COMM_WORLD):
+    """
+    Set all handlers for logging.
+
+    Args:
+        comm (:class:`MPI.Comm`): MPI communicator.
+    """
+    # Set up logging
+    timestamp = datetime.now()
+    logfile_name = f"gusto-{timestamp.strftime('%Y-%m-%dT%H%M%S')}"
+    if parallel_log in ["FILE", "BOTH"]:
+        logfile_name += f"_{comm.rank}"
+    logfile_name += ".log"
+    if comm.rank == 0:
+        os.makedirs("results", exist_ok=True)
+    logfile_path = os.path.join("results", logfile_name)
+
+    console_format_str = ""
+    if parallel_log in ["CONSOLE", "BOTH"]:
+        console_format_str += f"[{comm.rank}] "
+    console_format_str += '%(levelname)-8s %(message)s'
+
+    if comm.rank == 0:
+        # Always log on rank 0
+        logger.addHandler(create_logfile_handler(logfile_path))
+        logger.addHandler(create_console_handler(console_format_str))
+    else:
+        # Only log on other ranks if enabled
+        if parallel_log in ["FILE", "BOTH"]:
+            logger.addHandler(create_logfile_handler(logfile_path))
+        if parallel_log in ["CONSOLE", "BOTH"]:
+            logger.addHandler(create_console_handler(console_format_str))
+        if not logger.handlers:
+            logger.addHandler(logging.NullHandler())
+
+    logger.info("Running %s" % " ".join(sys.argv))
+

gusto/physics.py

@@ -13,7 +13,7 @@
 from gusto.equations import CompressibleEulerEquations
 from gusto.fml import identity, Term
 from gusto.labels import subject, physics, transporting_velocity
-from gusto.configuration import logger
+from gusto.logging import logger
 from firedrake import (Interpolator, conditional, Function, dx,
                        min_value, max_value, Constant, pi, Projector)
 from gusto import thermodynamics

gusto/time_discretisation.py

@@ -6,14 +6,21 @@
 """
 
 from abc import ABCMeta, abstractmethod, abstractproperty
-from firedrake import (Function, TestFunction, NonlinearVariationalProblem,
-                       NonlinearVariationalSolver, DirichletBC)
+
+from firedrake import (
+    Function, TestFunction, NonlinearVariationalProblem,
+    NonlinearVariationalSolver, DirichletBC
+)
 from firedrake.formmanipulation import split_form
 from firedrake.utils import cached_property
-from gusto.configuration import (logger, DEBUG, EmbeddedDGOptions, RecoveryOptions)
-from gusto.labels import (time_derivative, prognostic, physics,
-                          replace_subject, replace_test_function)
+
+from gusto.configuration import EmbeddedDGOptions, RecoveryOptions
 from gusto.fml.form_manipulation_labelling import Term, all_terms, drop
+from gusto.labels import (
+    time_derivative, prognostic, physics, replace_subject,
+    replace_test_function
+)
+from gusto.logging import logger, DEBUG
 from gusto.wrappers import *
 
 

gusto/timeloop.py

@@ -3,14 +3,14 @@
 from abc import ABCMeta, abstractmethod, abstractproperty
 from firedrake import Function, Projector, Constant, split
 from pyop2.profiling import timed_stage
-from gusto.configuration import logger
 from gusto.equations import PrognosticEquationSet
-from gusto.forcing import Forcing
+from gusto.fields import TimeLevelFields, StateFields
 from gusto.fml.form_manipulation_labelling import drop, Label, Term
+from gusto.forcing import Forcing
 from gusto.labels import (transport, diffusion, time_derivative, linearisation,
                           prognostic, physics, transporting_velocity)
 from gusto.linear_solvers import LinearTimesteppingSolver
-from gusto.fields import TimeLevelFields, StateFields
+from gusto.logging import logger
 from gusto.time_discretisation import ExplicitTimeDiscretisation
 from gusto.transport_methods import TransportMethod
 import ufl

gusto/transport_methods.py

@@ -5,9 +5,10 @@
 from firedrake import (dx, dS, dS_v, dS_h, ds_t, ds_b, ds_v, dot, inner, outer,
                        jump, grad, div, FacetNormal, Function, sign, avg, cross,
                        curl)
-from gusto.configuration import IntegrateByParts, TransportEquationType, logger
+from gusto.configuration import IntegrateByParts, TransportEquationType
 from gusto.fml import Term, keep, drop
 from gusto.labels import prognostic, transport, transporting_velocity, ibp_label
+from gusto.logging import logger
 from gusto.spatial_methods import SpatialMethod
 
 __all__ = ["DefaultTransport", "DGUpwind"]