Log CMOR check and generic fix output to separate file (#2361)

Co-authored-by: Valeriu Predoi <valeriu.predoi@gmail.com>

esmvalcore/_main.py

@@ -455,6 +455,13 @@ def _run(self, recipe: Path, session) -> None:
             process_recipe(recipe_file=recipe, session=session)
 
         self._clean_preproc(session)
+
+        if session.cmor_log.read_text(encoding='utf-8'):
+            logger.warning(
+                "Input data is not (fully) CMOR-compliant, see %s for details",
+                session.cmor_log,
+            )
+
         logger.info("Run was successful")
 
     @staticmethod

esmvalcore/cmor/_fixes/fix.py

@@ -33,6 +33,7 @@
     from esmvalcore.config import Session
 
 logger = logging.getLogger(__name__)
+generic_fix_logger = logging.getLogger(f'{__name__}.genericfix')
 
 
 class Fix:
@@ -397,12 +398,12 @@ def _msg_suffix(cube: Cube) -> str:
     def _debug_msg(self, cube: Cube, msg: str, *args) -> None:
         """Print debug message."""
         msg += self._msg_suffix(cube)
-        logger.debug(msg, *args)
+        generic_fix_logger.debug(msg, *args)
 
     def _warning_msg(self, cube: Cube, msg: str, *args) -> None:
         """Print debug message."""
         msg += self._msg_suffix(cube)
-        logger.warning(msg, *args)
+        generic_fix_logger.warning(msg, *args)
 
     @staticmethod
     def _set_range_in_0_360(array: np.ndarray) -> np.ndarray:

esmvalcore/config/_config_object.py

@@ -291,6 +291,7 @@ class Session(ValidatedConfig):
     relative_run_dir = Path('run')
     relative_main_log = Path('run', 'main_log.txt')
     relative_main_log_debug = Path('run', 'main_log_debug.txt')
+    relative_cmor_log = Path('run', 'cmor_log.txt')
     _relative_fixed_file_dir = Path('preproc', 'fixed_files')
 
     def __init__(self, config: dict, name: str = 'session'):
@@ -347,6 +348,11 @@ def main_log_debug(self):
         """Return main log debug file."""
         return self.session_dir / self.relative_main_log_debug
 
+    @property
+    def cmor_log(self):
+        """Return CMOR log file."""
+        return self.session_dir / self.relative_cmor_log
+
     @property
     def _fixed_file_dir(self):
         """Return fixed file directory."""

esmvalcore/config/_logging.py

@@ -4,12 +4,36 @@
 import logging.config
 import os
 import time
+from collections.abc import Iterable
 from pathlib import Path
-from typing import Optional, Union
+from typing import Literal, Optional, Union
 
 import yaml
 
 
+class FilterMultipleNames():
+    """Only allow/Disallow events from loggers with specific names."""
+
+    def __init__(
+        self,
+        names: Iterable[str],
+        mode: Literal['allow', 'disallow'],
+    ) -> None:
+        """Initialize filter."""
+        self.names = names
+        if mode == 'allow':
+            self.starts_with_name = True
+        else:
+            self.starts_with_name = False
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        """Filter events."""
+        for name in self.names:
+            if record.name.startswith(name):
+                return self.starts_with_name
+        return not self.starts_with_name
+
+
 def _purge_file_handlers(cfg: dict) -> None:
     """Remove handlers with filename set.
 

esmvalcore/config/config-logging.yml

@@ -10,24 +10,42 @@ formatters:
     format: '%(levelname)-7s [%(process)d] %(message)s'
   debug:
     format: '%(asctime)s UTC [%(process)d] %(levelname)-7s %(name)s:%(lineno)s %(message)s'
+filters:
+  only_cmor:  # only events from CMOR check and generic fixes
+    (): esmvalcore.config._logging.FilterMultipleNames
+    names: [esmvalcore.cmor.check, esmvalcore.cmor._fixes.fix.genericfix]
+    mode: allow
+  no_cmor:  # no events from CMOR check and generic fixes
+    (): esmvalcore.config._logging.FilterMultipleNames
+    names: [esmvalcore.cmor.check, esmvalcore.cmor._fixes.fix.genericfix]
+    mode: disallow
 handlers:
   console:
     class: logging.StreamHandler
     level: INFO
     formatter: console
     stream: ext://sys.stdout
+    filters: [no_cmor]
   simple_log_file:
     class: logging.FileHandler
     level: INFO
     formatter: brief
     filename: main_log.txt
     mode: w
+    filters: [no_cmor]
   debug_log_file:
     class: logging.FileHandler
     level: DEBUG
     formatter: debug
     filename: main_log_debug.txt
     mode: w
+  cmor_log:  # only contains output from CMOR check and generic fixes
+    class: logging.FileHandler
+    level: INFO
+    formatter: brief
+    filename: cmor_log.txt
+    mode: w
+    filters: [only_cmor]
 root:
   level: DEBUG
-  handlers: [console, simple_log_file, debug_log_file]
+  handlers: [console, simple_log_file, debug_log_file, cmor_log]

esmvalcore/experimental/recipe_output.py

@@ -247,8 +247,9 @@ def _log_ssh_html_info(self):
         )
         logger.info(
             "It looks like you are connected to a remote machine via SSH. To "
-            "show the output html file, you can try the following command:"
-            "\n%s\nThen visit http://localhost:%s in your browser",
+            "show the output html file, you can try the following command on "
+            "your local machine:\n%s\nThen visit http://localhost:%s in your "
+            "browser",
             command,
             port,
         )

tests/unit/main/test_esmvaltool.py

@@ -84,6 +84,7 @@ def test_run(mocker, session, search_esgf):
     session['config_file'] = '/path/to/config-user.yml'
     session['remove_preproc_dir'] = True
     session['save_intermediary_cubes'] = False
+    session.cmor_log.read_text.return_value = 'WARNING: attribute not present'
 
     recipe = Path('/recipe_dir/recipe_test.yml')
 

tests/unit/test_logging.py

@@ -5,7 +5,7 @@
 
 import pytest
 
-from esmvalcore.config._logging import configure_logging
+from esmvalcore.config._logging import FilterMultipleNames, configure_logging
 
 
 @pytest.mark.parametrize('level', (None, 'INFO', 'DEBUG'))
@@ -36,3 +36,31 @@ def test_logging_log_level_invalid():
     """Test failure condition for invalid level specification."""
     with pytest.raises(ValueError):
         configure_logging(console_log_level='FAIL')
+
+
+@pytest.mark.parametrize(
+    'names,mode,output',
+    [
+        (['test'], 'allow', False),
+        (['test'], 'disallow', True),
+        (['test', 'another.test'], 'allow', False),
+        (['test', 'another.test'], 'disallow', True),
+        (['test', 'm.a.b.c'], 'allow', False),
+        (['test', 'm.a.b.c'], 'disallow', True),
+        (['a.b.c'], 'allow', True),
+        (['a.b.c'], 'disallow', False),
+        (['a'], 'allow', True),
+        (['a'], 'disallow', False),
+        (['a.b', 'test'], 'allow', True),
+        (['a.b', 'test'], 'disallow', False),
+        (['a.b', 'a.b.c'], 'allow', True),
+        (['a.b', 'a.b.c'], 'disallow', False),
+    ]
+)
+def test_filter_multiple_names(names, mode, output):
+    """Test `FilterMultipleNames`."""
+    filter = FilterMultipleNames(names, mode)
+    record = logging.LogRecord(
+        'a.b.c', 'level', 'path', 'lineno', 'msg', [], 'exc_info'
+    )
+    assert filter.filter(record) is output