RecursionError if loading ancillary variable raises KeyError

[gerritholl]

Describe the bug

In gerritholl@2cd971f, loading the ancillary variable vis_04_pixel_quality by loading vis_04 results in a RecursionError: maximum recursion depth exceeded when calling a Python object. This appears to happen due to FileYAMLReader.load calling FileYAMLReader._load_ancillary_variables and FileYAMLReader._load_ancillary_variables calling FileYAMLReader.load. It seems that:

1. FileYAMLReader.load find that ancillary variables are wanted and calls FileYAMLReader._load_ancillary_variables:

satpy/satpy/readers/yaml_reader.py

Line 848 in ef24f29

self._load_ancillary_variables(all_datasets)

2. FileYAMLReader._load_ancillary_variables calls FileYAMLReader.load for those variables:

https://github.com/pytroll/satpy/blob/ef24f29c25c08ead1024d608ecf3150c0fcd7051/satpy/readers/yaml_reader.py#L783https://github.com/pytroll/satpy/blob/ef24f29c25c08ead1024d608ecf3150c0fcd7051/satpy/readers/yaml_reader.py#L783

3. The file handler gets called, which happens to raise a KeyError.

4. The KeyError is caught by FileYAMLReader._load_dataset:

satpy/satpy/readers/yaml_reader.py

Lines 618 to 620 in ef24f29

	except KeyError:
	logger.warning("Failed to load {} from {}".format(dsid, fh),
	exc_info=True)

5. Another KeyError is raised by FileYAMLReader._load_dataset:

satpy/satpy/readers/yaml_reader.py

Lines 622 to 624 in ef24f29

	if failure:
	raise KeyError(
	"Could not load {} from any provided files".format(dsid))

6. This KeyError is caught by FileYAMLReader._load_dataset_with_area, which then returns None:

satpy/satpy/readers/yaml_reader.py

Lines 754 to 756 in ef24f29

	except (KeyError, ValueError) as err:
	logger.exception("Could not load dataset '%s': %s", dsid, str(err))
	return None

7. Finding that ds is None, FileYAMLReader.load leaves all_datasets untouched, therefore calling FileYAMLReader._load_ancillary_variables with the same all_datasets as before:

satpy/satpy/readers/yaml_reader.py

Line 848 in ef24f29

self._load_ancillary_variables(all_datasets)

To Reproduce

Unfortunately, I don't have a simple MCVE to trigger this. A full test case is necessary, but I want to note this issue before we have one. However, checking out gerritholl@2cd971f and then running pytest -k test_load_counts test_fci_l1c_fdhsi.py will trigger it, and the problem can also be observed at https://travis-ci.org/github/pytroll/satpy/jobs/683448062, a travis run that errored due to log length limits.

Expected behavior

I would like a log message at level WARNING or above, just like when the ancillary variable is not defined in the yaml file at all. The log message (see details below) contains both cases, because in this code I had defined the ancillary variable in the yaml file only for one channel but not for the others.

Actual results

In reality, Python crashes with a recursion error. See above for the steps of what appears to be happening inside Satpy, as far as I understand.

An excerpt from the recursive traceback:

  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary
_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary
_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary
_variables

Each time, the value of loadable_av_ids is:

ipdb> p loadable_av_ids
[DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=())]

and for all_datasets:

In : sorted([k.name for k in all_datasets.keys()])
['ir_105', 'ir_123', 'ir_133', 'ir_38', 'ir_87', 'ir_97', 'nir_13', 'nir_16', 'nir_22', 'vis_04', 'vis_05', 'vis_06', 'vis_08', 'vis_09', 'wv_63', 'wv_73']

Excerpts from the full output (shortened for sanity):

============================= test session starts ==============================
platform linux -- Python 3.8.2, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /home/gholl/checkouts/satpy
plugins: cov-2.8.1
collected 8 items / 7 deselected / 1 selected

test_fci_l1c_fdhsi.py F                                                  [100%]

=================================== FAILURES ===================================
________________ TestFCIL1CFDHSIReaderGoodData.test_load_counts ________________
Traceback (most recent call last):
  File "/home/gholl/checkouts/satpy/satpy/tests/reader_tests/test_fci_l1c_fdhsi.py", line 304, in test_load_counts
    res = reader.load(
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 783, in _load_ancillary_variables
    self.load(loadable_av_ids, previous_datasets=datasets)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 848, in load
    self._load_ancillary_variables(all_datasets)

...

  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 843, in load
    ds = self._load_dataset_with_area(dsid, coords, **kwargs)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 750, in _load_dataset_with_area
    area = self._load_dataset_area(dsid, file_handlers, coords, **kwargs)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 732, in _load_dataset_area
    return self._load_area_def(dsid, file_handlers, **kwargs)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 661, in _load_area_def
    return _load_area_def(dsid, file_handlers)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 859, in _load_area_def
    final_area = StackedAreaDefinition(*area_defs)
  File "/data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/pyresample/geometry.py", line 2148, in __init__
    self.append(definition)
  File "/data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/pyresample/geometry.py", line 2196, in append
    self.defs[-1] = concatenate_area_defs(self.defs[-1], definition)
  File "/data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/pyresample/geometry.py", line 2123, in concatenate_area_defs
    area_extent = combine_area_extents_vertical(area1, area2)
  File "/data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/pyresample/geometry.py", line 2093, in combine_area_extents_vertical
    if np.isclose(area1.area_extent[1], area2.area_extent[3]):
  File "<__array_function__ internals>", line 5, in isclose
  File "/data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/numpy/core/numeric.py", line 2259, in isclose
    if all(xfin) and all(yfin):
  File "<__array_function__ internals>", line 5, in all
  File "/data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/numpy/core/fromnumeric.py", line 2398, in all
    return _wrapreduction(a, np.logical_and, 'all', axis, None, out, keepdims=keepdims)
  File "/data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/numpy/core/fromnumeric.py", line 88, in _wrapreduction
    return reduction(axis=axis, out=out, **passkwargs)
  File "/data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/numpy/core/_methods.py", line 48, in _all
    return umr_all(a, axis, dtype, out, keepdims)
RecursionError: maximum recursion depth exceeded while calling a Python object
------------------------------ Captured log call -------------------------------
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset vis_05_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset vis_06_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset vis_08_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset vis_09_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset nir_13_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset nir_16_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset nir_22_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset ir_38_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset wv_63_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset wv_73_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset ir_87_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset ir_97_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset ir_105_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset ir_123_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:775 Can't load ancillary dataset ir_133_pixel_quality
WARNING  satpy.readers.yaml_reader:yaml_reader.py:619 Failed to load DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from <FCIFDHSIFileHandler: 'W_XX-EUMETSAT-Darmstadt,IMG+SAT,MTI1+FCI-1C-RRAD-
FDHSI-FD--CHK-BODY--L2P-NC4E_C_EUMT_20170410114434_GTT_DEV_20170410113925_20170410113934_N__C_0070_0067.nc'>
Traceback (most recent call last):
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 614, in _load_dataset
    projectable = fh.get_dataset(dsid, ds_info)
  File "/home/gholl/checkouts/satpy/satpy/readers/fci_l1c_fdhsi.py", line 132, in get_dataset
    data = self[measured + "/effective_radiance"]
  File "/home/gholl/checkouts/satpy/satpy/readers/netcdf_utils.py", line 182, in __getitem__
    val = self.file_content[key]
KeyError: 'data/vis_04_pixel_quality/measured/effective_radiance'
WARNING  satpy.readers.yaml_reader:yaml_reader.py:619 Failed to load DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from <FCIFDHSIFileHandler: 'W_XX-EUMETSAT-Darmstadt,IMG+SAT,MTI1+FCI-1C-RRAD-
FDHSI-FD--CHK-BODY--L2P-NC4E_C_EUMT_20170410114442_GTT_DEV_20170410113934_20170410113942_N__C_0070_0068.nc'>
Traceback (most recent call last):
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 614, in _load_dataset
    projectable = fh.get_dataset(dsid, ds_info)
  File "/home/gholl/checkouts/satpy/satpy/readers/fci_l1c_fdhsi.py", line 132, in get_dataset
    data = self[measured + "/effective_radiance"]
  File "/home/gholl/checkouts/satpy/satpy/readers/netcdf_utils.py", line 182, in __getitem__
    val = self.file_content[key]
KeyError: 'data/vis_04_pixel_quality/measured/effective_radiance'
ERROR    satpy.readers.yaml_reader:yaml_reader.py:755 Could not load dataset 'DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=())': "Could not load DatasetID(name='vis_04_pixel_quality', wavelength=
None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from any provided files"
Traceback (most recent call last):
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 753, in _load_dataset_with_area
    ds = self._load_dataset_data(file_handlers, dsid, **kwargs)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 638, in _load_dataset_data
    proj = self._load_dataset(dsid, ds_info, file_handlers, **kwargs)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 623, in _load_dataset
    raise KeyError(
KeyError: "Could not load DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from any provided files"
WARNING  satpy.readers.yaml_reader:yaml_reader.py:619 Failed to load DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from <FCIFDHSIFileHandler: 'W_XX-EUMETSAT-Darmstadt,IMG+SAT,MTI1+FCI-1C-RRAD-
FDHSI-FD--CHK-BODY--L2P-NC4E_C_EUMT_20170410114434_GTT_DEV_20170410113925_20170410113934_N__C_0070_0067.nc'>
Traceback (most recent call last):
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 614, in _load_dataset
    projectable = fh.get_dataset(dsid, ds_info)
  File "/home/gholl/checkouts/satpy/satpy/readers/fci_l1c_fdhsi.py", line 132, in get_dataset
    data = self[measured + "/effective_radiance"]
  File "/home/gholl/checkouts/satpy/satpy/readers/netcdf_utils.py", line 182, in __getitem__
    val = self.file_content[key]
KeyError: 'data/vis_04_pixel_quality/measured/effective_radiance'
WARNING  satpy.readers.yaml_reader:yaml_reader.py:619 Failed to load DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from <FCIFDHSIFileHandler: 'W_XX-EUMETSAT-Darmstadt,IMG+SAT,MTI1+FCI-1C-RRAD-
FDHSI-FD--CHK-BODY--L2P-NC4E_C_EUMT_20170410114442_GTT_DEV_20170410113934_20170410113942_N__C_0070_0068.nc'>

...

WARNING  satpy.readers.yaml_reader:yaml_reader.py:619 Failed to load DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from <FCIFDHSIFileHandler: 'W_XX-EUMETSAT-Darmstadt,IMG+SAT,MTI1+FCI-1C-RRAD-
FDHSI-FD--CHK-BODY--L2P-NC4E_C_EUMT_20170410114442_GTT_DEV_20170410113934_20170410113942_N__C_0070_0068.nc'>
Traceback (most recent call last):
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 614, in _load_dataset
    projectable = fh.get_dataset(dsid, ds_info)
  File "/home/gholl/checkouts/satpy/satpy/readers/fci_l1c_fdhsi.py", line 132, in get_dataset
    data = self[measured + "/effective_radiance"]
  File "/home/gholl/checkouts/satpy/satpy/readers/netcdf_utils.py", line 182, in __getitem__
    val = self.file_content[key]
KeyError: 'data/vis_04_pixel_quality/measured/effective_radiance'
ERROR    satpy.readers.yaml_reader:yaml_reader.py:755 Could not load dataset 'DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=())': "Could not load DatasetID(name='vis_04_pixel_quality', wavelength=
None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from any provided files"
Traceback (most recent call last):
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 753, in _load_dataset_with_area
    ds = self._load_dataset_data(file_handlers, dsid, **kwargs)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 638, in _load_dataset_data
    proj = self._load_dataset(dsid, ds_info, file_handlers, **kwargs)
  File "/home/gholl/checkouts/satpy/satpy/readers/yaml_reader.py", line 623, in _load_dataset
    raise KeyError(
KeyError: "Could not load DatasetID(name='vis_04_pixel_quality', wavelength=None, resolution=1000, polarization=None, calibration=None, level=None, modifiers=()) from any provided files"
=============================== warnings summary ===============================
satpy/tests/reader_tests/test_fci_l1c_fdhsi.py::TestFCIL1CFDHSIReaderGoodData::test_load_counts
satpy/tests/reader_tests/test_fci_l1c_fdhsi.py::TestFCIL1CFDHSIReaderGoodData::test_load_counts
  /data/gholl/miniconda3/envs/py38/lib/python3.8/site-packages/pyproj/crs/crs.py:543: UserWarning: You will likely lose important projection information when converting to a PROJ string from another format. See: https://proj.org/faq.html#what-is-the-best-format-for-describing-coord
inate-reference-systems
    proj_string = self.to_proj4()

-- Docs: https://docs.pytest.org/en/latest/warnings.html
=========================== short test summary info ============================
FAILED test_fci_l1c_fdhsi.py::TestFCIL1CFDHSIReaderGoodData::test_load_counts
================= 1 failed, 7 deselected, 2 warnings in 1.45s ==================

Environment Info:

• OS: openSUSE 15.0
• Satpy Version: 0.21.1.dev37+gef24f29c.d20200505

Additional context
I found this when working on #1177 but it's not specific to the implementation there.

[gerritholl]

Possibly related: #1140

[gerritholl]

This appears to happen when raising KeyError, ValueError, or their subclasses. When a different exception is raised (tested with AttributeError) the recursion problem does not occur. Perhaps if the KeyError raised in line 623 is replaced by a dedicated exception, and only this exception is caught in line 754, the problem will cease, except that line 754 also catches ValueError (I don't know why).

[djhoese]

The problem in #1140 is similar, but more about the CF writer specifically.

The problem is not with what exceptions are raised but with the design of the recursion between the two methods at play here. We need to add something to the ancillary variables method or move part of it out to the load method so that we know what datasets we've already tried to load but couldn't find/load.