Using fx_files for preprocessor fails in rare cases

[schlunma]

Describe the bug
@bettina-gier found a funny bug: In some cases, using fx files in preprocessors (e.g for landsea_fraction_weighting) fails.

This recipe works:

preprocessors:

  land_fraction_weighting: &land_fraction_weighting
    weighting_landsea_fraction: &weighting_options
      area_type: land


diagnostics:

  diag_mvi_tas:
    variables:
      tas: &var_tas
        preprocessor: land_fraction_weighting
        project: CMIP5
        mip: Amon
        exp: historical
        ensemble: r1i1p1
        start_year: 1901
        end_year: 2005
    additional_datasets: &tas_datasets
      # - {dataset: CRU, project: OBS, type: reanaly, version: TS4.02, tier: 2}
      - {dataset: bcc-csm1-1}
    scripts:
      null

  diag_two_vars_scatter:
    variables:
      cSoil:
        preprocessor: land_fraction_weighting
        project: CMIP5
        mip: Lmon
        exp: historical
        ensemble: r1i1p1
        start_year: 1986
        end_year: 2005
        additional_datasets:
          - {dataset: HWSD, project: OBS, type: reanaly, version: 1.2, tier: 3, start_year: 2000, end_year: 2000}
    scripts:
      null

This one

preprocessors:

  land_fraction_weighting: &land_fraction_weighting
    weighting_landsea_fraction: &weighting_options
      area_type: land


diagnostics:

  diag_mvi_tas:
    variables:
      tas: &var_tas
        preprocessor: land_fraction_weighting
        project: CMIP5
        mip: Amon
        exp: historical
        ensemble: r1i1p1
        start_year: 1901
        end_year: 2005
        reference_dataset: CRU
        plot_units: degC
    additional_datasets: &tas_datasets
      - {dataset: CRU, project: OBS, type: reanaly, version: TS4.02, tier: 2}
      - {dataset: bcc-csm1-1}
    scripts:
      null

  diag_two_vars_scatter:
    variables:
      cSoil:
        preprocessor: land_fraction_weighting
        project: CMIP5
        mip: Lmon
        exp: historical
        ensemble: r1i1p1
        start_year: 1986
        end_year: 2005
        reference_dataset: HWSD
        plot_units: PgC
        additional_datasets:
          - {dataset: HWSD, project: OBS, type: reanaly, version: 1.2, tier: 3, start_year: 2000, end_year: 2000}
    scripts:
      null

fails with

Traceback (most recent call last):
  File "ESMValCore/esmvalcore/_main.py", line 220, in run
    conf = main(args)
  File "ESMValCore/esmvalcore/_main.py", line 156, in main
    process_recipe(recipe_file=recipe, config_user=cfg)
  File "ESMValCore/esmvalcore/_main.py", line 202, in process_recipe
    recipe = read_recipe_file(recipe_file, config_user)
  File "ESMValCore/esmvalcore/_recipe.py", line 74, in read_recipe_file
    recipe_file=filename)
  File "ESMValCore/esmvalcore/_recipe.py", line 1032, in __init__
    self.tasks = self.initialize_tasks() if initialize_tasks else None
  File "ESMValCore/esmvalcore/_recipe.py", line 1379, in initialize_tasks
    task_name=task_name,
  File "ESMValCore/esmvalcore/_recipe.py", line 985, in _get_preprocessor_task
    name=task_name,
  File "ESMValCore/esmvalcore/_recipe.py", line 792, in _get_single_preprocessor_task
    config_user=config_user,
  File "ESMValCore/esmvalcore/_recipe.py", line 739, in _get_preprocessor_products
    config_user=config_user)
  File "ESMValCore/esmvalcore/_recipe.py", line 506, in _update_fx_settings
    fx_dict = _get_landsea_fraction_fx_dict(variable, config_user)
  File "ESMValCore/esmvalcore/_recipe.py", line 459, in _get_landsea_fraction_fx_dict
    fx_file, _ = _get_correct_fx_file(variable, fx_var, config_user)
  File "ESMValCore/esmvalcore/_recipe.py", line 424, in _get_correct_fx_file
    fx_files = _get_input_files(fx_variable, config_user)
  File "ESMValCore/esmvalcore/_recipe.py", line 551, in _get_input_files
    drs=config_user['drs'])
  File "ESMValCore/esmvalcore/_data_finder.py", line 264, in get_input_filelist
    variable['end_year'])
  File "ESMValCore/esmvalcore/_data_finder.py", line 111, in select_files
    start, end = get_start_end_year(filename)
  File "ESMValCore/esmvalcore/_data_finder.py", line 99, in get_start_end_year
    'not be read from the file'.format(filename)
ValueError: File /mnt/lustre02/work/bd0854/DATA/ESMValTool2/OBS/Tier3/HWSD/OBS_HWSD_reanaly_1.2_fx_sftlf.nc dates do not match a recognized pattern and time can not be read from the file

Note the additional OBS dataset in the second case.

I will try to address this in #439. I think this bug was introduced in #432. @valeriupredoi

[valeriupredoi]

that should not happen if the variable's frequency is fx as it should be, due to the condition in _data_finder.py/l.262

[schlunma]

That's exactly the problem. In _add_fxvar_keys the frequency gets set to mon even if the mip is fx, and the reason for this is that reading the CMOR_TABLE suddenly gives a frequency of mon instead of fx. So at some point in the code the CMOR_TABLE object get changed, but I still don't know where...

[valeriupredoi]

I don't see where the problem is - i used master and ran the second bit of the recipe no problemo - I think @bettina-gier is using an older copy of master or some custom branch since the code line numbers differ as well

[valeriupredoi]

aha! If you run the second bit only all goes well - if you run diag mvi and diag scatter I get that exact error

[valeriupredoi]

so if you run only the first diag group it fails with Failed to run weighting_landsea_fraction(air_temperature... coz I got no sftlf/of files - if you run only the second diagnostic group, that goes well, if you run them both you get Tina's error - it smells to me of assignigning a var frequency from one diag and keeping it for the second which is highly illegal 😁

[schlunma]

Found the problem:

The problem appears when we call the the function get_variable of the CMOR table to check if the fx variable is in the table mip:

ESMValCore/esmvalcore/_recipe.py

Line 404 in bc7c117

fx_variable = cmor_table.get_variable(fx_mip, fx_varname)

I though that this returns always None if the variable is not in the table, e.g. for sftlf and Amon. However, for the OBS project (which is not cmor_strict), this is NOT true since the get_variable also checks the other mips:

ESMValCore/esmvalcore/cmor/table.py

Lines 677 to 713 in bc7c117

	def get_variable(self, table, short_name, derived=False):
	"""
	Search and return the variable info.
	Parameters
	----------
	table: basestring
	Table name
	short_name: basestring
	Variable's short name
	derived: bool, optional
	Variable is derived. Info retrieval is less strict
	Returns
	-------
	VariableInfo
	Return the VariableInfo object for the requested variable if
	found, returns None if not
	"""
	var_info = self.tables.get(table, {}).get(short_name, None)
	if var_info:
	return var_info
	if not self.strict:
	for table_vars in sorted(self.tables.values()):
	if short_name in table_vars:
	var_info = table_vars[short_name]
	break
	if not var_info and (derived or not self.strict):
	var_info = self.default.get_variable(table, short_name)
	if var_info:
	mip_info = self.get_table(table)
	var_info.copy()
	if mip_info:
	var_info.frequency = mip_info.frequency
	return var_info

L. 712 causes the trouble: It overwrites the frequency of the original fx table with the the frequency of the Amon table. I guess this behavior is not intended, since l. 710 already has a var_info.copy(), but the line needs to be

var_info = var_info.copy()

to work correctly. If I do that, the bug disappears. Is that replacement correct or is this frequency change an intended behavior, @jvegasbsc ?

[valeriupredoi]

Great work, Inspector Poirot! I am fairly sure that's a bug - but waiting for @jvegasbsc to confirm 🍺

[valeriupredoi]

Prob best if you opened a PR with that fix Manu, so we see if all tests pass and give Javi a ready made platform to make changes, if needed 🍺

[schlunma]

All right, will do after #439 is merged

[jvegreg]

Is that replacement correct or is this frequency change an intended behavior, @jvegasbsc ?

You are right, @schlunma, it is not intended. In fact, the other copy call was introduced to solve a similar error.

[bouweandela]

All right, will do after #439 is merged

@schlunma Why is #439 needed to solve this issue? Is this a bug in the master branch or in an unmerged branch?