Merge pull request #1185 from MetOffice/simplify_logging

Simplify logging

Author: jfrost-mo

src/CSET/__init__.py

@@ -187,42 +187,42 @@ def setup_logging(verbosity: int):
     logging.captureWarnings(True)
 
     # Calculate logging level.
-    try:
-        name_to_level = logging.getLevelNamesMapping()
-    except AttributeError:
-        # logging.getLevelNamesMapping() is python 3.11 or newer. Using
-        # implementation detail for older versions.
-        name_to_level = logging._nameToLevel
     # Level from CLI flags.
     if verbosity >= 2:
         cli_loglevel = logging.DEBUG
     elif verbosity == 1:
         cli_loglevel = logging.INFO
     else:
         cli_loglevel = logging.WARNING
-    # Level from environment variable.
+
+    # Level from $LOGLEVEL environment variable.
+    try:
+        name_to_level = logging.getLevelNamesMapping()
+    except AttributeError:
+        # logging.getLevelNamesMapping() is python 3.11 or newer. Using
+        # implementation detail for older versions.
+        name_to_level = logging._nameToLevel
     env_loglevel = name_to_level.get(os.getenv("LOGLEVEL"), logging.ERROR)
+
+    # Logging verbosity is the most verbose of CLI and environment setting.
     loglevel = min(cli_loglevel, env_loglevel)
 
     # Configure the root logger.
     logger = logging.getLogger()
-    # Record everything at least INFO for the log file.
-    logger.setLevel(min(loglevel, logging.INFO))
+    # Set logging level.
+    logger.setLevel(loglevel)
+
     # Hide matplotlib's many font messages.
-    logger.addFilter(
-        lambda record: not (
-            isinstance(record, str) and record.msg.startswith("findfont:")
-        )
-    )
+    class NoFontMessageFilter(logging.Filter):
+        def filter(self, record):
+            return not record.getMessage().startswith("findfont:")
+
+    logging.getLogger("matplotlib.font_manager").addFilter(NoFontMessageFilter())
+
     stderr_log = logging.StreamHandler()
-    # Filter stderr log to just what is requested.
-    stderr_log.addFilter(lambda record: record.levelno >= loglevel)
-    stderr_log.addFilter(
-        lambda record: not (
-            isinstance(record, str) and record.msg.startswith("findfont:")
-        )
+    stderr_log.setFormatter(
+        logging.Formatter("%(asctime)s %(name)s %(levelname)s %(message)s")
     )
-    stderr_log.setFormatter(logging.Formatter("%(asctime)s %(levelname)s %(message)s"))
     logger.addHandler(stderr_log)
 
 

src/CSET/_workflow_utils/run_cset_recipe.py

@@ -108,14 +108,9 @@ def run_recipe_steps():
 
     logging.info("Running %s", " ".join(command))
     try:
-        subprocess.run(command, check=True, env=subprocess_env(), capture_output=True)
+        subprocess.run(command, check=True, env=subprocess_env())
     except subprocess.CalledProcessError as err:
-        logging.exception(
-            "cset bake exited with non-zero code %s.\nstdout: %s\nstderr: %s",
-            err.returncode,
-            err.stdout.decode(sys.stdout.encoding),
-            err.stderr.decode(sys.stderr.encoding),
-        )
+        logging.exception("cset bake exited with non-zero code %s.", err.returncode)
         raise
     create_diagnostic_archive(output_directory())
 

src/CSET/operators/__init__.py

@@ -168,9 +168,8 @@ def _run_steps(
         diagnostic_log = logging.FileHandler(
             filename="CSET.log", mode="w", encoding="UTF-8"
         )
-        diagnostic_log.addFilter(lambda record: record.levelno >= logging.INFO)
         diagnostic_log.setFormatter(
-            logging.Formatter("%(asctime)s %(levelname)s %(message)s")
+            logging.Formatter("%(asctime)s %(name)s %(levelname)s %(message)s")
         )
         logger.addHandler(diagnostic_log)
         # Create metadata file used by some steps.

tests/test_cli.py

@@ -56,9 +56,9 @@ def test_argument_parser():
 def test_setup_logging():
     """Tests the logging setup at various verbosity levels."""
     root_logger = logging.getLogger()
-    # Log level gets pinned at a minimum of INFO for file output.
+    # Log has a minimum of WARNING.
     CSET.setup_logging(0)
-    assert root_logger.level == logging.INFO
+    assert root_logger.level == logging.WARNING
     # -v
     CSET.setup_logging(1)
     assert root_logger.level == logging.INFO