SegFaults in the sample data tests with `netCDF4=1.6.1`

[valeriupredoi]

@ESMValGroup/technical-lead-development-team I need your (rather quick) input here please: we have seen that the new netCDF4=1.6.1 is causing frequent segfaults in our CI tests, and we have pinned it to !=1.6.1 to brush the problem under the carpet for us. However, the good folk at Unidata/netCDF4 are scratching their heads and are wondering what the heck's going on, let's try and help them figure that out, even if we can provide a bit of a narrowed-down picture, it' still helpful. For that, I have opened

• Very frequent segfaults with the new netCDF4=1.6.1 Unidata/netcdf4-python#1192
• New netCDF4=1.6.1 (most probably) causing a fairly large number of Segmentation Faults conda-forge/netcdf4-feedstock#141

(have a read through the discussion there, it's a lot of paint thrown at a white wall)

and I have managed to isolate our side of the problem to the sample data testing. Simplifying the problem, this is how the toy model looks:

import iris
import numpy as np
import pickle
import platform
import pytest

TEST_REVISION = 1

def get_cache_key(value):
    """Get a cache key that is hopefully unique enough for unpickling.

    If this doesn't avoid problems with unpickling the cached data,
    manually clean the pytest cache with the command `pytest --cache-clear`.
    """
    py_version = platform.python_version()
    return (f'{value}_iris-{iris.__version__}_'
            f'numpy-{np.__version__}_python-{py_version}'
            f'rev-{TEST_REVISION}')


@pytest.fixture(scope="module")
def timeseries_cubes_month(request):
    """Load representative timeseries data."""
    # cache the cubes to save about 30-60 seconds on repeat use
    cache_key = get_cache_key("sample_data/monthly")
    data = request.config.cache.get(cache_key, None)
    cubes = pickle.loads(data.encode('latin1'))

    return cubes


# @pytest.mark.skip
def test_io_1(timeseries_cubes_month):
    cubes = timeseries_cubes_month
    _ = [c.data for c in cubes]  # this produces SegFaults


@pytest.mark.skip
def test_io_2(timeseries_cubes_month):
    cubes = timeseries_cubes_month
    loaded_cubes = []
    for i, c in enumerate(cubes):
        iris.save(c, str(i) + ".nc")
        lc = iris.load_cube(str(i) + ".nc")
        loaded_cubes.append(lc)
    _ = [c.data for c in loaded_cubes]  # this doesn't produce SegFaults

From my tests I found out test_io_1 has a tendency to produce segfaults at that listcomp step (can test with -n 0 or -n 2, doesn't really matter), whereas the other doesn't. Can we gauge anything from that without digging in the actual IO/threading (that is not our plot of land anyway)? Hive mind, folks! 🐝

UPDATE as of 20-Oct-2022 #1727 (comment)

[bouweandela]

Have you tried removing the cache to simplify the problem even further?

[valeriupredoi]

Have you tried removing the cache to simplify the problem even further?

indeed one thing I will test with in the next hour, bud! 🍺

[valeriupredoi]

OK so I've done some serious testing with the cache test and without (simply reading files off disk):

cached case

7% fail rate:

• 5% HDF crappe
  • always at second cube: saved it and accessed c.data on it 100 times - no issue
• 2% SegFaults

regular read off disk

no issues: 100% pass rate

So it is pretty clear that whatever happens when the cached sample data is read is the thing that causes 1.6.1 to produce SegFaults and stray HDF issues - what that exactly is, I have no idea? Any clues @bouweandela and maybe @stefsmeets ?

[bouweandela]

Does the problem persist if you clear the cache before testing?

[bouweandela]

https://docs.esmvaltool.org/projects/esmvalcore/en/latest/contributing.html#sample-data

[bouweandela]

If it goes away, we either need to add the netcdf and hdf5 library versions to the cache key, it get rid of pickle altogether and create the cache using e.g. iris.

[valeriupredoi]

@bouweandela cache clearing doesn't work for this test - it deletes the cache so the test fails since there is no data to run the test, I don't want to reconstruct the data while I am doing this because that is simply adding time to the test runs ie it fails once, then one needs to run the test without cache clearing, so we are in the same boat and we're just wasting time:

request = <SubRequest 'timeseries_cubes_month' for <Function test_io_1>>

    @pytest.fixture(scope="module")
    def timeseries_cubes_month(request):
        """Load representative timeseries data."""
        # cache the cubes to save about 30-60 seconds on repeat use
        cache_key = get_cache_key("sample_data/monthly")
        data = request.config.cache.get(cache_key, None)
>       cubes = pickle.loads(data.encode('latin1'))
E       AttributeError: 'NoneType' object has no attribute 'encode'

test_io_netcdf_2.py:27: AttributeError

[valeriupredoi]

OK running pytest --clear-cache once (running through the entire test suite, accounting for the failed test as above, all else passing) then running 100 instances of pytest -n 2 test_io_netcdf_2.py where that script is the one below (to have only the cached stuffs that fail) results in no issues at all! Good idea to test the cache clearing @bouweandela 🍺

mport iris
import numpy as np
import pickle
import platform
import pytest

TEST_REVISION = 1

def get_cache_key(value):
    """Get a cache key that is hopefully unique enough for unpickling.

    If this doesn't avoid problems with unpickling the cached data,
    manually clean the pytest cache with the command `pytest --cache-clear`.
    """
    py_version = platform.python_version()
    return (f'{value}_iris-{iris.__version__}_'
            f'numpy-{np.__version__}_python-{py_version}'
            f'rev-{TEST_REVISION}')


@pytest.fixture(scope="module")
def timeseries_cubes_month(request):
    """Load representative timeseries data."""
    # cache the cubes to save about 30-60 seconds on repeat use
    cache_key = get_cache_key("sample_data/monthly")
    data = request.config.cache.get(cache_key, None)
    cubes = pickle.loads(data.encode('latin1'))

    return cubes


def test_io_1(timeseries_cubes_month):
    cubes = timeseries_cubes_month
    print("YYY")
    for i, c in enumerate(cubes):
        print("XXX", i)
        try:
            c.data
        except RuntimeError:
            print(c)
            print("SHIT")
            raise

this same test was used here #1727 (comment) with results in the "cached case" section. It is something to do with the cache, and the new netcdf4, since this test has never failed in the CI until now. Ideas further?

[valeriupredoi]

OK I ran another set of 100 of those tests, just to be sure - bulletproof! No more issues after clearing the cache once

[valeriupredoi]

also let's keep an eye on the (hourly) tests this #1730 is running just to be sure the only problematic 1.6.1-related failure is the cache test one

[bouweandela]

If clearing the cache once solved the issue, then the solution is to either stop using pickling to store the cached cubes on disk or add the netcdf library version number to the cache key, so cached cubes are specific for each version of the library.

[bouweandela]

Remember #1058?