From 29b71eea86727925089f1c808cadc269cfbb72e6 Mon Sep 17 00:00:00 2001 From: James Foucar Date: Mon, 24 Sep 2018 13:09:51 -0600 Subject: [PATCH] Add model-specific logging capability And use this capability to restore timing dumps in case_run. [BFB] --- cime/scripts/lib/CIME/case/case_run.py | 50 +++++++++++++------------- cime/scripts/lib/CIME/utils.py | 4 +++ 2 files changed, 29 insertions(+), 25 deletions(-) diff --git a/cime/scripts/lib/CIME/case/case_run.py b/cime/scripts/lib/CIME/case/case_run.py index 4c7b5ab3cf07..4824c8cdc7a4 100644 --- a/cime/scripts/lib/CIME/case/case_run.py +++ b/cime/scripts/lib/CIME/case/case_run.py @@ -3,7 +3,7 @@ '""" from CIME.XML.standard_module_setup import * from CIME.utils import gzip_existing_file, new_lid, run_and_log_case_status -from CIME.utils import run_sub_or_cmd, append_status, safe_copy +from CIME.utils import run_sub_or_cmd, append_status, safe_copy, model_log from CIME.get_timing import get_timing from CIME.provenance import save_prerun_provenance, save_postrun_provenance @@ -62,14 +62,14 @@ def _pre_run_check(case, lid, skip_pnl=False, da_cycle=0): # This needs to be done everytime the LID changes in order for log files to be set up correctly # The following also needs to be called in case a user changes a user_nl_xxx file OR an env_run.xml # variable while the job is in the queue - logger.debug("{} NAMELIST CREATION BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} NAMELIST CREATION BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) if skip_pnl: case.create_namelists(component='cpl') else: logger.info("Generating namelists for {}".format(caseroot)) case.create_namelists() - logger.debug("{} NAMELIST CREATION HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} NAMELIST CREATION HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) logger.info("-------------------------------------------------------------------------") logger.info(" - Prestage required restarts into {}".format(rundir)) @@ -81,9 +81,9 @@ def _pre_run_check(case, lid, skip_pnl=False, da_cycle=0): def _run_model_impl(case, lid, skip_pnl=False, da_cycle=0): ############################################################################### - logger.debug("{} PRE_RUN_CHECK BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} PRE_RUN_CHECK BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) _pre_run_check(case, lid, skip_pnl=skip_pnl, da_cycle=da_cycle) - logger.debug("{} PRE_RUN_CHECK HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} PRE_RUN_CHECK HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) model = case.get_value("MODEL") @@ -113,14 +113,14 @@ def _run_model_impl(case, lid, skip_pnl=False, da_cycle=0): while loop: loop = False - logger.debug("{} SAVE_PRERUN_PROVENANCE BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} SAVE_PRERUN_PROVENANCE BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) save_prerun_provenance(case) - logger.debug("{} SAVE_PRERUN_PROVENANCE HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} SAVE_PRERUN_PROVENANCE HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) - logger.debug("{} MODEL EXECUTION BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} MODEL EXECUTION BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) run_func = lambda: run_cmd(cmd, from_dir=rundir)[0] stat = run_and_log_case_status(run_func, "model execution", caseroot=case.get_value("CASEROOT")) - logger.debug("{} MODEL EXECUTION HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} MODEL EXECUTION HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) model_logfile = os.path.join(rundir, model + ".log." + lid) # Determine if failure was due to a failed node, if so, try to restart @@ -159,9 +159,9 @@ def _run_model_impl(case, lid, skip_pnl=False, da_cycle=0): # We failed and we're not restarting expect(False, "RUN FAIL: Command '{}' failed\nSee log file for details: {}".format(cmd, model_logfile)) - logger.debug("{} POST_RUN_CHECK BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} POST_RUN_CHECK BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) _post_run_check(case, lid) - logger.debug("{} POST_RUN_CHECK HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} POST_RUN_CHECK HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) return lid @@ -265,7 +265,7 @@ def _do_data_assimilation(da_script, caseroot, cycle, lid, rundir): ############################################################################### def case_run(self, skip_pnl=False, set_continue_run=False, submit_resubmits=False): ############################################################################### - logger.debug("{} CASE.RUN BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} CASE.RUN BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) # Set up the run, run the model, do the postrun steps prerun_script = self.get_value("PRERUN_SCRIPT") postrun_script = self.get_value("POSTRUN_SCRIPT") @@ -279,12 +279,12 @@ def case_run(self, skip_pnl=False, set_continue_run=False, submit_resubmits=Fals lid = new_lid() if prerun_script: - logger.debug("{} PRERUN_SCRIPT BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} PRERUN_SCRIPT BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) self.flush() _do_external(prerun_script, self.get_value("CASEROOT"), self.get_value("RUNDIR"), lid, prefix="prerun") self.read_xml() - logger.debug("{} PRERUN_SCRIPT HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} PRERUN_SCRIPT HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) for cycle in range(data_assimilation_cycles): # After the first DA cycle, runs are restart runs @@ -293,37 +293,37 @@ def case_run(self, skip_pnl=False, set_continue_run=False, submit_resubmits=Fals self.set_value("CONTINUE_RUN", self.get_value("RESUBMIT_SETS_CONTINUE_RUN")) - logger.debug("{} RUN_MODEL BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} RUN_MODEL BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) lid = _run_model(self, lid, skip_pnl, da_cycle=cycle) - logger.debug("{} RUN_MODEL HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} RUN_MODEL HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) if self.get_value("CHECK_TIMING") or self.get_value("SAVE_TIMING"): - logger.debug("{} GET_TIMING BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} GET_TIMING BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) get_timing(self, lid) # Run the getTiming script - logger.debug("{} GET_TIMING HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} GET_TIMING HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) if data_assimilation: - logger.debug("{} DO_DATA_ASSIMILATION BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} DO_DATA_ASSIMILATION BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) self.flush() _do_data_assimilation(data_assimilation_script, self.get_value("CASEROOT"), cycle, lid, self.get_value("RUNDIR")) self.read_xml() - logger.debug("{} DO_DATA_ASSIMILATION HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} DO_DATA_ASSIMILATION HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) _save_logs(self, lid) # Copy log files back to caseroot - logger.debug("{} SAVE_POSTRUN_PROVENANCE BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} SAVE_POSTRUN_PROVENANCE BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) save_postrun_provenance(self) - logger.debug("{} SAVE_POSTRUN_PROVENANCE HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} SAVE_POSTRUN_PROVENANCE HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) if postrun_script: - logger.debug("{} POSTRUN_SCRIPT BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} POSTRUN_SCRIPT BEGINS HERE".format(time.strftime("%Y-%m-%d %H:%M:%S"))) self.flush() _do_external(postrun_script, self.get_value("CASEROOT"), self.get_value("RUNDIR"), lid, prefix="postrun") self.read_xml() _save_logs(self, lid) - logger.debug("{} POSTRUN_SCRIPT HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} POSTRUN_SCRIPT HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) if set_continue_run: self.set_value("CONTINUE_RUN", @@ -333,6 +333,6 @@ def case_run(self, skip_pnl=False, set_continue_run=False, submit_resubmits=Fals if submit_resubmits: _resubmit_check(self) - logger.debug("{} CASE.RUN HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) + model_log("e3sm", logger, "{} CASE.RUN HAS FINISHED".format(time.strftime("%Y-%m-%d %H:%M:%S"))) return True diff --git a/cime/scripts/lib/CIME/utils.py b/cime/scripts/lib/CIME/utils.py index a310e2c74558..07722f5f2126 100644 --- a/cime/scripts/lib/CIME/utils.py +++ b/cime/scripts/lib/CIME/utils.py @@ -1756,3 +1756,7 @@ def run_bld_cmd_ensure_logging(cmd, arg_logger, from_dir=None): def get_batch_script_for_job(job): return job if "st_archive" in job else "." + job + +def model_log(model, arg_logger, msg): + if get_model() == model: + arg_logger.info(msg)