Odd race condition in test suite

[t00sa]

Testing a recent change, I've discovered a problem with the TestCleanupPrebuilds.test_clean routine that results in intermittent failures in certain cases. When I unpacked the test and checked the conditions, I found the failures were caused by a changes to the atimes of the temporary files created by the test.

I'm unable to find an obvious reason for these changes, but I suspect the cause may be a race condition between the test and some other piece of software - e.g. a malware scanner - that touches files on local temporary storage. The problem goes away if I use the NFS home file system. Ultimately, I think this is likely to be a local OS configuration issue but I'm documenting it here for posterity in case it impacts anyone else.

My testcase is a trimmed down version of the fab test:

import os
from datetime import datetime
from pathlib import Path
import time
import pytest


def test_create(tmp_path):

    # create several versions of the same artefact
    artefacts = [
        ('a.123.foo', datetime(2022, 10, 31)),
        ('a.234.foo', datetime(2022, 10, 21)),
        ('a.345.foo', datetime(2022, 10, 11)),
        ('a.456.foo', datetime(2022, 10, 1)),
    ]

    targets = []

    for a, t in artefacts:
        path = tmp_path / a
        targets.append(path)
        path.touch(exist_ok=False)
        os.utime(path, (t.timestamp(), t.timestamp()))
        print(path, datetime.fromtimestamp(path.stat().st_atime))

    for i in range(3):
        print(datetime.now())
        for path in targets:
            print(path, datetime.fromtimestamp(path.stat().st_atime))
        time.sleep(0.1)

    assert False

When I run this with pytest on my desktop system, I get the following:

/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.123.foo 2022-10-31 00:00:00
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.234.foo 2022-10-21 00:00:00
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.345.foo 2022-10-11 00:00:00
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.456.foo 2022-10-01 00:00:00
2024-03-06 16:55:42.472909
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.123.foo 2022-10-31 00:00:00
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.234.foo 2022-10-21 00:00:00
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.345.foo 2022-10-11 00:00:00
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.456.foo 2022-10-01 00:00:00
2024-03-06 16:55:42.573172
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.123.foo 2024-03-06 16:55:42.473460
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.234.foo 2024-03-06 16:55:42.475460
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.345.foo 2024-03-06 16:55:42.475460
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.456.foo 2024-03-06 16:55:42.474460
2024-03-06 16:55:42.673714
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.123.foo 2024-03-06 16:55:42.473460
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.234.foo 2024-03-06 16:55:42.475460
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.345.foo 2024-03-06 16:55:42.475460
/var/tmp/xxxx/pytest-of-xxxx/pytest-80/test_create0/a.456.foo 2024-03-06 16:55:42.474460

When I run the same thing with a different temporary directory, i.e. env PYTEST_DEBUG_TEMPROOT=$HOME/Output/testing pytest testcase.py, I don’t see the problem:

/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.123.foo 2022-10-31 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.234.foo 2022-10-21 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.345.foo 2022-10-11 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.456.foo 2022-10-01 00:00:00
2024-03-06 16:56:23.866428
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.123.foo 2022-10-31 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.234.foo 2022-10-21 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.345.foo 2022-10-11 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.456.foo 2022-10-01 00:00:00
2024-03-06 16:56:23.966695
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.123.foo 2022-10-31 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.234.foo 2022-10-21 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.345.foo 2022-10-11 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.456.foo 2022-10-01 00:00:00
2024-03-06 16:56:24.067321
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.123.foo 2022-10-31 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.234.foo 2022-10-21 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.345.foo 2022-10-11 00:00:00
/net/home/xxxx/Output/testing/pytest-of-xxxx/pytest-6/test_create0/a.456.foo 2022-10-01 00:00:00

A typical example of a failure from the fab test suite:

______________________________ TestCleanupPrebuilds.test_clean[kwargs4-expect4] ______________________________

self = <test_incremental_fortran.TestCleanupPrebuilds object at 0x7f661a4fa2f0>
tmp_path = PosixPath('/var/tmp/xxxx/pytest-of-xxxx/pytest-132/test_clean_kwargs4_expect4_0')
kwargs = {'n_versions': 2, 'older_than': datetime.timedelta(days=15)}, expect = ['a.123.foo', 'a.234.foo']

    @pytest.mark.parametrize("kwargs,expect", in_out)
    def test_clean(self, tmp_path, kwargs, expect):
    
        with BuildConfig(project_label=PROJECT_LABEL, fab_workspace=tmp_path, multiprocessing=False) as config:
            remaining = self._prune(config, kwargs=kwargs)
    
>       assert sorted(remaining) == expect
E       AssertionError: assert ['a.123.foo'] == ['a.123.foo', 'a.234.foo']
E         
E         Right contains one more item: 'a.234.foo'
E         Use -v to get more diff

tests/system_tests/incremental_fortran/test_incremental_fortran.py: