Consolidate cmor setups and logging

e3sm_to_cmip/__main__.py

@@ -21,8 +21,12 @@
 from tqdm import tqdm
 
 from e3sm_to_cmip import ROOT_HANDLERS_DIR, __version__, resources
-from e3sm_to_cmip._logger import _setup_logger, _setup_root_logger
+from datetime import datetime, timezone
+
+from e3sm_to_cmip._logger import _logger
+
 from e3sm_to_cmip.cmor_handlers.utils import (
+    instantiate_h_utils_logger,
     MPAS_REALMS,
     REALMS,
     Frequency,
@@ -32,7 +36,10 @@
     derive_handlers,
     load_all_handlers,
 )
+from e3sm_to_cmip.cmor_handlers.handler import instantiate_handler_logger
+
 from e3sm_to_cmip.util import (
+    instantiate_util_logger,
     FREQUENCIES,
     _get_table_info,
     get_handler_info_msg,
@@ -50,11 +57,6 @@
 warnings.filterwarnings("ignore")
 
 
-# Setup the root logger and this module's logger.
-log_filename = _setup_root_logger()
-logger = _setup_logger(__name__, propagate=True)
-
-
 @dataclass
 class CLIArguments:
     """A data class storing the command line arguments for e3sm_to_cmip.
@@ -97,9 +99,19 @@ class CLIArguments:
 
 class E3SMtoCMIP:
     def __init__(self, args: Optional[List[str]] = None):
+        # logger assignment is moved into __init__ AFTER the call to _parse_args
+        # to prevent the default logfile directory being created whenever a call
+        # to "--help" or "--version" is invoked.  Doing so, however, makes the
+        # logger unavailable to the functions in this class unless made global.
+        global logger
+
         # A dictionary of command line arguments.
         parsed_args = self._parse_args(args)
 
+        # Setup this module's logger AFTER args are parsed in __init__, so that
+        # default log file is NOT created for "--help" or "--version" calls.
+        logger = _logger(name=__name__, set_log_level="INFO", to_logfile=True)
+
         # NOTE: The order of these attributes align with class CLIArguments.
         # ======================================================================
         # Run Mode settings.
@@ -115,8 +127,6 @@ def __init__(self, args: Optional[List[str]] = None):
         self.debug: bool = parsed_args.debug
         self.timeout: int = parsed_args.timeout
 
-        # ======================================================================
-        # CMOR settings.
         # ======================================================================
         self.var_list: List[str] = self._get_var_list(parsed_args.var_list)
         self.realm: Union[Realm, MPASRealm] = parsed_args.realm
@@ -140,6 +150,9 @@ def __init__(self, args: Optional[List[str]] = None):
         if self.precheck_path is not None:
             self._run_precheck()
 
+        self.handlers = self._get_handlers()
+
+    def echo_settings(self):
         logger.info("--------------------------------------")
         logger.info("| E3SM to CMIP Configuration")
         logger.info("--------------------------------------")
@@ -149,9 +162,7 @@ def __init__(self, args: Optional[List[str]] = None):
         logger.info(f"    * precheck_path='{self.precheck_path}'")
         logger.info(f"    * freq='{self.freq}'")
         logger.info(f"    * realm='{self.realm}'")
-        logger.info(f"    * Writing log output file to: {log_filename}")
-
-        self.handlers = self._get_handlers()
+        # logger.info(f"    * Writing log output file to: {log_filename}")
 
     def run(self):
         # Setup logger information and print out e3sm_to_cmip CLI arguments.
@@ -161,17 +172,16 @@ def run(self):
                 self.output_path, "user_metadata.json"
             )
 
-        # Setup directories using the CLI argument paths (e.g., output dir).
-        # ======================================================================
-        if not self.info_mode:
-            self._setup_dirs_with_paths()
-
         # Run e3sm_to_cmip with info mode.
         # ======================================================================
         if self.info_mode:
             self._run_info_mode()
             sys.exit(0)
 
+        # Setup directories using the CLI argument paths (e.g., output dir).
+        # ======================================================================
+        self._setup_dirs_with_paths()
+
         # Run e3sm_to_cmip to CMORize serially or in parallel.
         # ======================================================================
         timer = None
@@ -306,7 +316,9 @@ def _parse_args(self, args: Optional[List[str]]) -> CLIArguments:
             sys.exit(1)
 
         # Parse the arguments and perform validation.
+        # NOTE: exits here if args == "-h" or "--help" or "--version", else validate
         parsed_args = argparser.parse_args(args_to_parse)
+
         self._validate_parsed_args(parsed_args)
 
         # Convert to this data class for type checking to work.
@@ -531,7 +543,7 @@ def _setup_argparser(self) -> argparse.ArgumentParser:
             "-h",
             "--help",
             action="help",
-            default=argparse.SUPPRESS,
+            # default=argparse.SUPPRESS,
             help="show this help message and exit",
         )
 
@@ -778,12 +790,17 @@ def _run_serial(self) -> int:  # noqa: C901
         int
             1 if an error occurs, else 0
         """
+
+        # TODO: Make this a command-line flag.
+        do_pbar = False
+
         try:
             num_handlers = len(self.handlers)
             num_success = 0
+            num_failure = 0
             name = None
 
-            if self.realm != "atm":
+            if self.realm != "atm" and do_pbar:
                 pbar = tqdm(total=len(self.handlers))
 
             for _, handler in enumerate(self.handlers):
@@ -838,17 +855,18 @@ def _run_serial(self) -> int:  # noqa: C901
                 except Exception as e:
                     print_debug(e)
 
-                if name is not None:
+                if name is not None and name is not "":
                     num_success += 1
-                    msg = f"Finished {name}, {num_success}/{num_handlers} jobs complete"
+                    msg = f"Finished {name}, {num_success}/{num_handlers} jobs complete (via run_serial)"
                     logger.info(msg)
                 else:
+                    num_failure += 1
                     msg = f"Error running handler {handler['name']}"
                     logger.info(msg)
 
-                if self.realm != "atm":
+                if self.realm != "atm" and do_pbar:
                     pbar.update(1)
-            if self.realm != "atm":
+            if self.realm != "atm" and do_pbar:
                 pbar.close()
 
         except Exception as error:
@@ -858,6 +876,8 @@ def _run_serial(self) -> int:  # noqa: C901
             msg = f"{num_success} of {num_handlers} handlers complete"
             logger.info(msg)
 
+            if num_failure > 0:
+                return 1
             return 0
 
     def _run_parallel(self) -> int:  # noqa: C901
@@ -872,6 +892,9 @@ def _run_parallel(self) -> int:  # noqa: C901
         pool_res = list()
         will_run = []
 
+        # TODO: Make this a command-line flag.
+        do_pbar = False
+
         for idx, handler in enumerate(self.handlers):
             handler_method = handler["method"]
             handler_variables = handler["raw_variables"]
@@ -926,8 +949,10 @@ def _run_parallel(self) -> int:  # noqa: C901
             pool_res.append(res)
 
         # wait for each result to complete
-        pbar = tqdm(total=len(pool_res))
+        if do_pbar:
+            pbar = tqdm(total=len(pool_res))
         num_success = 0
+        num_failure = 0
         num_handlers = len(self.handlers)
         finished_success = []
         for idx, res in enumerate(pool_res):
@@ -936,38 +961,52 @@ def _run_parallel(self) -> int:  # noqa: C901
                 finished_success.append(out)
                 if out:
                     num_success += 1
-                    msg = f"Finished {out}, {idx + 1}/{num_handlers} jobs complete"
+                    msg = f"Finished {out}, {idx + 1}/{num_handlers} jobs complete (via run_parallel)"
                 else:
+                    num_failure += 1
                     msg = f'Error running handler {self.handlers[idx]["name"]}'
                     logger.error(msg)
 
                 logger.info(msg)
             except Exception as e:
                 print_debug(e)
-            pbar.update(1)
+            if do_pbar:
+                pbar.update(1)
 
-        pbar.close()
+        if do_pbar:
+            pbar.close()
         pool.shutdown()
 
         msg = f"{num_success} of {num_handlers} handlers complete"
         logger.info(msg)
 
         failed = set(will_run) - set(finished_success)
-        if failed:
+        if failed or num_failure > 0:
             logger.error(f"{', '.join(list(failed))} failed to complete")
             logger.error(msg)
+            return 1
 
         return 0
 
     def _timeout_exit(self):
         print_message("Hit timeout limit, exiting")
         os.kill(os.getpid(), signal.SIGINT)
 
-
 def main(args: Optional[List[str]] = None):
+
     app = E3SMtoCMIP(args)
-    app.run()
+
+    # These calls allow module loggers that create default logfiles to avoid being 
+    # instantiated by arguments "--help" or "--version" upon import.
+    instantiate_util_logger()
+    instantiate_h_utils_logger()
+    instantiate_handler_logger()
+
+    app.echo_settings()
+    return app.run()
 
 
 if __name__ == "__main__":
+
+
     main()

e3sm_to_cmip/_logger.py

@@ -1,68 +1,75 @@
+import inspect
 import logging
 import os
-import time
-from datetime import datetime
+from datetime import datetime, timezone
 
-from pytz import UTC
 
+DEFAULT_LOG_LEVEL = logging.DEBUG
+DEFAULT_LOG_DIR = "e2c_logs"
+DEFAULT_LOG = f"{DEFAULT_LOG_DIR}/e2c_root_log-{datetime.now(timezone.utc).strftime('%Y%m%d_%H%M%S_%f')}.log"
 
-def _setup_root_logger() -> str:  # pragma: no cover
-    """Sets up the root logger.
+def _logger(name=None, logfilename=DEFAULT_LOG, set_log_level=None, to_console=False, to_logfile=False, propagate=False):
+    """ Return a root or named logger with variable configuration.
 
-    The logger module will write to a log file and stream the console
-    simultaneously.
-
-    The log files are saved in a `/logs` directory relative to where
-    `e3sm_to_cmip` is executed.
-
-    Returns
-    -------
-    str
-        The name of the logfile.
+    Parameters
+    ----------
+    name : str
+        The name displayed for the logger in messages.
+        If name == None or name == "__main__", the root logger is returned
+    logfilename : str
+        If logfile handling is requested, any logfile may be specified, or else
+        the default (e2c_logs/dflt_log-{datetime.now(timezone.utc).strftime('%Y%m%d_%H%M%S_%f')}.log) is used.
+    set_log_level : str
+        One of { "DEBUG" (default), "INFO", "WARNING", "ERROR", "CRITICAL" }
+    to_console : boolean
+        If True, a logging.StreamHandler is supplied.  Default = False
+    to_logfile : boolean
+        If True, a logging.FileHandler is supplied. Default = False.
+    propagate : boolean
+        If True, messages logged are propagated to the root logger.  Default = False.
     """
-    os.makedirs("logs", exist_ok=True)
-    filename = f'logs/{UTC.localize(datetime.utcnow()).strftime("%Y%m%d_%H%M%S_%f")}'
-    log_format = "%(asctime)s_%(msecs)03d:%(levelname)s:%(funcName)s:%(message)s"
+
+    if to_logfile:
+        dn = os.path.dirname(logfilename)
+        if len(dn) and not os.path.exists(dn):
+            os.makedirs(dn)
 
-    # Setup the logging module.
-    logging.basicConfig(
-        filename=filename,
-        format=log_format,
-        datefmt="%Y%m%d_%H%M%S",
-        level=logging.DEBUG,
-    )
-    logging.captureWarnings(True)
-    logging.Formatter.converter = time.gmtime
+    if name == None or name == "__main__":
+        logger = logger.root
+    else:
+        logger = logging.getLogger(name)
 
-    # Configure and add a console stream handler.
-    console_handler = logging.StreamHandler()
-    console_handler.setLevel(logging.INFO)
-    log_formatter = logging.Formatter(log_format)
-    console_handler.setFormatter(log_formatter)
-    logging.getLogger().addHandler(console_handler)
+    logger.propagate = propagate
 
-    return filename
+    if set_log_level == "None" or set_log_level == "DEBUG":
+        log_level = DEFAULT_LOG_LEVEL
+    elif set_log_level == "INFO":
+        log_level = logging.INFO
+    elif set_log_level == "WARNING":
+        log_level = logging.WARNING
+    elif set_log_level == "ERROR":
+        log_level = logging.ERROR
+    elif set_log_level == "CRITICAL":
+        log_level = logging.CRITICAL
+    else: log_level = DEFAULT_LOG_LEVEL
 
+    logger.setLevel(log_level)
 
-def _setup_logger(name, propagate=True) -> logging.Logger:
-    """Sets up a logger object.
+    logger.handlers = []
 
-    This function is intended to be used at the top-level of a module.
+    msgfmt = "%(asctime)s_%(msecs)03d:%(levelname)s:%(name)s:%(funcName)s:%(message)s"
+    datefmt = "%Y%m%d_%H%M%S"
 
-    Parameters
-    ----------
-    name : str
-        Name of the file where this function is called.
-    propagate : bool, optional
-        Propogate this logger module's messages to the root logger or not, by
-        default True.
+    if to_console:
+        logStreamHandler = logging.StreamHandler()
+        logStreamHandler.setFormatter(logging.Formatter(msgfmt, datefmt=datefmt))
+        logger.addHandler(logStreamHandler)
 
-    Returns
-    -------
-    logging.Logger
-        The logger.
-    """
-    logger = logging.getLogger(name)
-    logger.propagate = propagate
+    if to_logfile:
+        logFileHandler = logging.FileHandler(logfilename)
+        logFileHandler.setFormatter(logging.Formatter(msgfmt, datefmt=datefmt))
+        logger.addHandler(logFileHandler)
 
     return logger
+
+