Diagnose source of duplicated Iris warnings

[trexfeathers]

Steps

• Diagnose
• Write up
• Discuss with Iris devs to decide on next steps to fix

Possible causes:

• Once per file
• Once per NetCDF variable
• Once per Dask worker
  E.g. Some work happens within a NetCDFDataProxy, and there is one of these per chunk
• Use of generators

Finding examples

• Try loading some of the iris-test-data files
• Read the Iris CI output (example)
• Get a list of warnings generated by Iris, then check them with users for familiar 'culprits'

[acchamber]

out.txt

Took the warning summary from a recent Pytest run to take a look at this.

15717 warnings in total, 882 lines in the file. A few highlights

• 8 unique external Deprecation Warnings (30 total)
• 9 unique internal IrisDeprecation warnings
• 69 separate UserWarnings, although some of these are almost the same warning (warning for x coord vs y coord for example)
• 42 Seperate instances of the FutureWarning about netCDF load datum.

[bjlittle]

After conducting some experiments, I'm now of the conclusion that iris isn't doing anything wrong in the way that it is using the builtin Python warnings module.

I used the following simple script as the basis of the investigation:

import iris

dname = "/home/h05/itwl/projects/git/iris-test-data/test_data/NetCDF/mercator"
fnames = ["false_east_north_merc.nc", "non_unit_scale_factor_merc.nc", "toa_brightness_temperature.nc"]

for fname in fnames:
    print(fname)
    _ = iris.load_cube(f"{dname}/{fname}")

(Note that, this script was call with python -Wd warnings.py for the normal default warnings behaviour, and python -Wo warnings.py for the once warnings behaviour)

Which should generate the following single warning to the console, but instead it occurs 3 times, once for each netCDF file loaded:

FutureWarning: Ignoring a datum in netCDF load for consistency with existing behaviour. In a future version of Iris, this datum will be applied. To apply the datum when loading, use the iris.FUTURE.datum_support flag.

This warning is generated as part of the iris load pipeline in iris.fileformats._nc_load_rules.helpers._get_ellipsoid

The approach taken was to reduce the functionality within the iris load pipeline to the point where the duplicate warnings generation stopped, hence attempting to identify the root cause of the issue.

Initial "hunches" of culprits revolved around:

• the use of the threading module for iris futures support
• using the generators pattern throughout the loading pipeline
• use of itertools

i.e., this is all seeded by the statement in the warnings documentation that the warnings.catch_warnings context manager is not thread safe.

Note that, the warnings module as part of its implementation injects the __warningregistry__ dictionary into the global namespace of the executing process. This dictionary keep the state of issued warning by the client and is used by warnings to filter warnings as part of its advertised behaviour.

It was observed that the ID object instance of the __warningregistry__ did not change during loading runs, but the contents of the registry was reset; a cause for concern and perhaps an explanation of the behaviour that we're witnessing in iris.

Essentially, I was able to eventually able to incrementally turn-off all of the iris loading pipeline but still maintain the high level call tree and witness the same duplicate warning behaviour by injecting new warnings at different stages of the loading pipeline call tree.

In essence, we see duplicate warnings and yet not call any of the iris loading infrastructure code; confusing and concerning.

Stripping the problem right back to the bare bones, the following script behaves as expected generating only 1 warning for both -Wd and -Wo:

import warnings

for _ in range(5):
    import iris
    warnings.warn("oops!", category=UserWarning)

However, the following pattern generates 2 warnings for both -Wd and -Wo:

import warnings

for _ in range(5):
    warnings.warn("oops", category=UserWarning)
    import iris

i.e., importing iris after generating a warning causes this behaviour.

Note that, this behaviour is also observed when importing matplotlib, numpy, cartopy and netCDF4 instead of iris.

However, this is not the case when importing dask. Odd.

Conclusion

@stephenworsley Has in parallel uncovered that this type of behaviour is a know bug with warnings (he can write his findings up to support this)

The behaviour that I've witnessed through this investigation leads me to the conclusion that iris isn't doing anything wrong per se, but though our heavy use of warnings we are exposing this bug with the side-effect of generating duplicate warnings messages to the console.

My recommendation is to now investigate community work arounds, assess those, and choose the best workaround for iris; one which we are willing to support and maintain in the code base.

[stephenworsley]

A probable source for this issue appears to be a bug with the warnings.catch_warnings context manager in python python/cpython#73858 .

Looking through responses to this issue, it appears that there exists a relatively simple workaround using functools.lru_cache as demonstrated here:
karlicoss/promnesia@78e7d73#diff-d29a3e5d675970f57a9788e5104d7f47831449ac62ff7441dddfd6491a4ddcdaR80

[stephenworsley]

Also worth noting, when I stepped through loading code, this appears to be where the context manager gets called in iris code:

iris/lib/iris/fileformats/_nc_load_rules/helpers.py

Lines 417 to 431 in b6e39d7

	with warnings.catch_warnings(record=True) as warning_records:
	cube.cell_methods = parse_cell_methods(nc_att_cell_methods)
	# Filter to get the warning we are interested in.
	warning_records = [
	record
	for record in warning_records
	if issubclass(record.category, UnknownCellMethodWarning)
	]
	if len(warning_records) > 0:
	# Output an enhanced warning message.
	warn_record = warning_records[0]
	name = "{}".format(cf_var.cf_name)
	msg = warn_record.message.args[0]
	msg = msg.replace("variable", "variable {!r}".format(name))
	warnings.warn(message=msg, category=UnknownCellMethodWarning)