Merge pull request #3408 from samsrabin/gddgen-log-changes

Logging improvements for GDD-generation workflow

Author: samsrabin

.git-blame-ignore-revs

@@ -70,3 +70,5 @@ cdf40d265cc82775607a1bf25f5f527bacc97405
 4ad46f46de7dde753b4653c15f05326f55116b73
 75db098206b064b8b7b2a0604d3f0bf8fdb950cc
 84609494b54ea9732f64add43b2f1dd035632b4c
+ac03492012837799b7111607188acff9f739044a
+d858665d799690d73b56bcb961684382551193f4

python/ctsm/crop_calendars/cropcal_module.py

@@ -13,6 +13,7 @@
 from ctsm.crop_calendars.cropcal_constants import DEFAULT_GDD_MIN
 from ctsm.crop_calendars.import_ds import import_ds
 from ctsm.utils import is_instantaneous
+from ctsm.ctsm_logging import log
 
 MISSING_RX_GDD_VAL = -1
 
@@ -49,11 +50,12 @@ def check_and_trim_years(year_1, year_n, ds_in):
     return ds_in
 
 
-def open_lu_ds(filename, year_1, year_n, existing_ds, ungrid=True):
+def open_lu_ds(filename, year_1, year_n, existing_ds, *, logger, ungrid=True):
     """
     Open land-use dataset
     """
     # Open and trim to years of interest
+    log(logger, f"Opening this_ds_gridded: {filename}")
     this_ds_gridded = xr.open_dataset(filename).sel(time=slice(year_1, year_n))
 
     # Assign actual lon/lat coordinates
@@ -347,14 +349,15 @@ def import_output(
     gdds_rx_ds=None,
     verbose=False,
     throw_errors=True,
+    logger=None,
 ):
     """
     Import CLM output
     """
     any_bad = False
 
     # Import
-    this_ds = import_ds(filename, my_vars=my_vars, my_vegtypes=my_vegtypes)
+    this_ds = import_ds(filename, my_vars=my_vars, my_vegtypes=my_vegtypes, logger=logger)
 
     # Trim to years of interest (do not include extra year needed for finishing last growing season)
     if year_1 and year_n:

python/ctsm/crop_calendars/generate_gdds.py

@@ -18,6 +18,7 @@
     os.path.dirname(os.path.realpath(__file__)), os.pardir, os.pardir, os.pardir, "python"
 )
 sys.path.insert(1, _CTSM_PYTHON)
+from ctsm.ctsm_logging import log, error  # pylint: disable=wrong-import-position
 import ctsm.crop_calendars.cropcal_module as cc  # pylint: disable=wrong-import-position
 import ctsm.crop_calendars.generate_gdds_functions as gddfn  # pylint: disable=wrong-import-position
 
@@ -85,11 +86,11 @@ def main(
                 raise RuntimeError(
                     "only_make_figs True but not all plotting modules are available"
                 ) from exc
-            gddfn.log(logger, "Not all plotting modules are available; disabling save_figs")
+            log(logger, "Not all plotting modules are available; disabling save_figs")
             save_figs = False
 
     # Print some info
-    gddfn.log(logger, f"Saving to {output_dir}")
+    log(logger, f"Saving to {output_dir}")
 
     # Parse list of crops to skip
     if "," in skip_crops:
@@ -107,7 +108,7 @@ def main(
         yr_1_import_str = f"{first_season+1}-01-01"
         yr_n_import_str = f"{last_season+2}-01-01"
 
-        gddfn.log(
+        log(
             logger,
             f"Importing netCDF time steps {yr_1_import_str} through {yr_n_import_str} "
             + "(years are +1 because of CTSM output naming)",
@@ -191,7 +192,7 @@ def main(
                 h1_instantaneous,
             )
 
-            gddfn.log(logger, f"   Saving pickle file ({pickle_file})...")
+            log(logger, f"   Saving pickle file ({pickle_file})...")
             with open(pickle_file, "wb") as file:
                 pickle.dump(
                     [
@@ -219,9 +220,10 @@ def main(
             [i for i, c in enumerate(gddaccum_yp_list) if not isinstance(c, type(None))]
         ]
 
-        gddfn.log(logger, "Done")
+        log(logger, "Done")
 
         if not h2_ds:
+            log(logger, f"Opening h2_ds: {h2_ds_file}")
             h2_ds = xr.open_dataset(h2_ds_file)
 
     ######################################################
@@ -236,7 +238,7 @@ def main(
             "s", sdates_rx, incl_patches1d_itype_veg, mxsowings, logger
         )
 
-        gddfn.log(logger, "Getting and gridding mean GDDs...")
+        log(logger, "Getting and gridding mean GDDs...")
         gdd_maps_ds = gddfn.yp_list_to_ds(
             gddaccum_yp_list, h2_ds, incl_vegtypes_str, sdates_rx, longname_prefix, logger
         )
@@ -247,10 +249,10 @@ def main(
         # Fill NAs with dummy values
         dummy_fill = -1
         gdd_maps_ds = gdd_maps_ds.fillna(dummy_fill)
-        gddfn.log(logger, "Done getting and gridding means.")
+        log(logger, "Done getting and gridding means.")
 
         # Add dummy variables for crops not actually simulated
-        gddfn.log(logger, "Adding dummy variables...")
+        log(logger, "Adding dummy variables...")
         # Unnecessary?
         template_ds = xr.open_dataset(sdates_file, decode_times=True)
         all_vars = [v.replace("sdate", "gdd") for v in template_ds if "sdate" in v]
@@ -278,9 +280,7 @@ def make_dummy(this_crop_gridded, addend):
 
         for var_index, this_var in enumerate(dummy_vars):
             if this_var in gdd_maps_ds:
-                gddfn.error(
-                    logger, f"{this_var} is already in gdd_maps_ds. Why overwrite it with dummy?"
-                )
+                error(logger, f"{this_var} is already in gdd_maps_ds. Why overwrite it with dummy?")
             dummy_gridded.name = this_var
             dummy_gridded.attrs["long_name"] = dummy_longnames[var_index]
             gdd_maps_ds[this_var] = dummy_gridded
@@ -294,14 +294,14 @@ def add_lonlat_attrs(this_ds):
         gdd_maps_ds = add_lonlat_attrs(gdd_maps_ds)
         gddharv_maps_ds = add_lonlat_attrs(gddharv_maps_ds)
 
-        gddfn.log(logger, "Done.")
+        log(logger, "Done.")
 
     ######################
     ### Save to netCDF ###
     ######################
 
     if not only_make_figs:
-        gddfn.log(logger, "Saving...")
+        log(logger, "Saving...")
 
         # Get output file path
         datestr = dt.datetime.now().strftime("%Y%m%d_%H%M%S")
@@ -336,7 +336,7 @@ def save_gdds(sdates_file, hdates_file, outfile, gdd_maps_ds, sdates_rx):
 
         save_gdds(sdates_file, hdates_file, outfile, gdd_maps_ds, sdates_rx)
 
-        gddfn.log(logger, "Done saving.")
+        log(logger, "Done saving.")
 
     ########################################
     ### Save things needed for mapmaking ###

python/ctsm/crop_calendars/generate_gdds_functions.py

@@ -6,12 +6,12 @@
 import warnings
 import os
 import glob
-import datetime as dt
 from importlib import util as importlib_util
 import numpy as np
 import xarray as xr
 
 from ctsm.utils import is_instantaneous
+from ctsm.ctsm_logging import log, error
 import ctsm.crop_calendars.cropcal_utils as utils
 import ctsm.crop_calendars.cropcal_module as cc
 from ctsm.crop_calendars.xr_flexsel import xr_flexsel
@@ -54,23 +54,6 @@
     CAN_PLOT = False
 
 
-def log(logger, string):
-    """
-    Simultaneously print INFO messages to console and to log file
-    """
-    print(string)
-    logger.info(string)
-
-
-def error(logger, string):
-    """
-    Simultaneously print ERROR messages to console and to log file
-    """
-    print(string)
-    logger.error(string)
-    raise RuntimeError(string)
-
-
 def check_sdates(dates_ds, sdates_rx, outdir_figs, logger, verbose=False):
     """
     Checking that input and output sdates match
@@ -271,7 +254,6 @@ def import_and_process_1yr(
     """
     save_figs = True
     log(logger, f"netCDF year {this_year}...")
-    log(logger, dt.datetime.now().strftime("%Y-%m-%d %H:%M:%S"))
 
     # Without dask, this can take a LONG time at resolutions finer than 2-deg
     if importlib_util.find_spec("dask"):
@@ -308,6 +290,7 @@ def import_and_process_1yr(
         my_vegtypes=crops_to_read,
         time_slice=slice(f"{slice_year}-01-01", f"{slice_year}-12-31"),
         chunks=chunks,
+        logger=logger,
     )
     for timestep in dates_ds["time"].values:
         print(timestep)
@@ -579,6 +562,7 @@ def import_and_process_1yr(
         my_vars=my_vars,
         my_vegtypes=crops_to_read,
         chunks=chunks,
+        logger=logger,
     )
 
     # Restrict to patches we're including
@@ -604,7 +588,7 @@ def import_and_process_1yr(
     incl_vegtype_indices = []
     for var, vegtype_str in enumerate(incl_vegtypes_str):
         if vegtype_str in skip_crops:
-            log(logger, f"      SKIPPING {vegtype_str}")
+            log(logger, f"SKIPPING {vegtype_str}")
             continue
 
         vegtype_int = utils.vegtype_str2int(vegtype_str)[0]
@@ -619,7 +603,7 @@ def import_and_process_1yr(
             check_gddharv = True
         if not this_crop_gddaccum_da.size:
             continue
-        log(logger, f"      {vegtype_str}...")
+        log(logger, f"{vegtype_str}...")
         incl_vegtype_indices = incl_vegtype_indices + [var]
 
         # Get prescribed harvest dates for these patches
@@ -1116,7 +1100,9 @@ def make_figures(
         if land_use_file:
             year_1_lu = year_1 if first_land_use_year is None else first_land_use_year
             year_n_lu = year_n if last_land_use_year is None else last_land_use_year
-            lu_ds = cc.open_lu_ds(land_use_file, year_1_lu, year_n_lu, gdd_maps_ds, ungrid=False)
+            lu_ds = cc.open_lu_ds(
+                land_use_file, year_1_lu, year_n_lu, gdd_maps_ds, logger=logger, ungrid=False
+            )
             lu_years_text = f" (masked by {year_1_lu}-{year_n_lu} area)"
             lu_years_file = f"_mask{year_1_lu}-{year_n_lu}"
         else: