Flaky test: test_nested_loop_error_in_grandchild_resource_tracker_silent

[ogrisel]

Observed several times:

• linux_py310_distributed in Bump up dependency versions on the CI config #1272:

https://dev.azure.com/joblib/joblib/_build/results?buildId=1849&view=logs&j=e366bf14-feff-5258-9913-c0ec433aa72d&t=db9d9cf0-46c0-52ca-1b5f-c25993207165&l=1312

• linux_py37_distributed in MAINT: remove pytest.warns(None) warnings in pytest 7 #1264

• linux_py310_distributed in

https://dev.azure.com/joblib/joblib/_build/results?buildId=1874&view=logs&j=e366bf14-feff-5258-9913-c0ec433aa72d

2022-02-23T13:12:02.7548426Z =================================== FAILURES ===================================
2022-02-23T13:12:02.7549232Z _________ test_nested_loop_error_in_grandchild_resource_tracker_silent _________
2022-02-23T13:12:02.7549590Z 
2022-02-23T13:12:02.7549891Z     @with_numpy
2022-02-23T13:12:02.7550280Z     @with_multiprocessing
2022-02-23T13:12:02.7550753Z     def test_nested_loop_error_in_grandchild_resource_tracker_silent():
2022-02-23T13:12:02.7551346Z         # Safety smoke test: test that nested parallel calls using the loky backend
2022-02-23T13:12:02.7552776Z         # don't yield noisy resource_tracker outputs when the grandchild errors
2022-02-23T13:12:02.7553258Z         # out.
2022-02-23T13:12:02.7553799Z         cmd = '''if 1:
2022-02-23T13:12:02.7554216Z             from joblib import Parallel, delayed
2022-02-23T13:12:02.7554608Z     
2022-02-23T13:12:02.7555968Z     
2022-02-23T13:12:02.7556348Z             def raise_error(i):
2022-02-23T13:12:02.7556756Z                 raise ValueError
2022-02-23T13:12:02.7557096Z     
2022-02-23T13:12:02.7557431Z     
2022-02-23T13:12:02.7557795Z             def nested_loop(f):
2022-02-23T13:12:02.7558206Z                 Parallel(backend="loky", n_jobs=2)(
2022-02-23T13:12:02.7558663Z                     delayed(f)(i) for i in range(10)
2022-02-23T13:12:02.7559039Z                 )
2022-02-23T13:12:02.7559383Z     
2022-02-23T13:12:02.7559722Z     
2022-02-23T13:12:02.7560074Z             if __name__ == "__main__":
2022-02-23T13:12:02.7560524Z                 Parallel(backend="loky", n_jobs=2)(
2022-02-23T13:12:02.7560998Z                     delayed(nested_loop)(func) for func in [raise_error]
2022-02-23T13:12:02.7561450Z                 )
2022-02-23T13:12:02.7561991Z         '''
2022-02-23T13:12:02.7562587Z         p = subprocess.Popen([sys.executable, '-c', cmd],
2022-02-23T13:12:02.7563126Z                              stderr=subprocess.PIPE, stdout=subprocess.PIPE)
2022-02-23T13:12:02.7563847Z         p.wait()
2022-02-23T13:12:02.7564221Z         out, err = p.communicate()
2022-02-23T13:12:02.7564738Z         assert p.returncode == 1, out.decode()
2022-02-23T13:12:02.7565203Z >       assert b"resource_tracker" not in err, err.decode()
2022-02-23T13:12:02.7565763Z E       AssertionError: joblib.externals.loky.process_executor._RemoteTraceback: 
2022-02-23T13:12:02.7566236Z E         """
2022-02-23T13:12:02.7569213Z E         joblib.externals.loky.process_executor._RemoteTraceback: 
2022-02-23T13:12:02.7569920Z E         """
2022-02-23T13:12:02.7575120Z E         Traceback (most recent call last):
2022-02-23T13:12:02.7576344Z E           File "/home/vsts/work/1/s/joblib/externals/loky/process_executor.py", line 418, in _process_worker
2022-02-23T13:12:02.7579612Z E             r = call_item()
2022-02-23T13:12:02.7580180Z E           File "/home/vsts/work/1/s/joblib/externals/loky/process_executor.py", line 274, in __call__
2022-02-23T13:12:02.7580730Z E             return self.fn(*self.args, **self.kwargs)
2022-02-23T13:12:02.7581200Z E           File "/home/vsts/work/1/s/joblib/_parallel_backends.py", line 620, in __call__
2022-02-23T13:12:02.7581763Z E             return self.func(*args, **kwargs)
2022-02-23T13:12:02.7582513Z E           File "/home/vsts/work/1/s/joblib/parallel.py", line 287, in __call__
2022-02-23T13:12:02.7582958Z E             return [func(*args, **kwargs)
2022-02-23T13:12:02.7583504Z E           File "/home/vsts/work/1/s/joblib/parallel.py", line 287, in <listcomp>
2022-02-23T13:12:02.7584036Z E             return [func(*args, **kwargs)
2022-02-23T13:12:02.7584489Z E           File "<string>", line 6, in raise_error
2022-02-23T13:12:02.7584935Z E         ValueError
2022-02-23T13:12:02.7585327Z E         """
2022-02-23T13:12:02.7585673Z E         
2022-02-23T13:12:02.7586159Z E         The above exception was the direct cause of the following exception:
2022-02-23T13:12:02.7586614Z E         
2022-02-23T13:12:02.7587037Z E         Traceback (most recent call last):
2022-02-23T13:12:02.7587618Z E           File "/home/vsts/work/1/s/joblib/externals/loky/process_executor.py", line 418, in _process_worker
2022-02-23T13:12:02.7588148Z E             r = call_item()
2022-02-23T13:12:02.7588721Z E           File "/home/vsts/work/1/s/joblib/externals/loky/process_executor.py", line 274, in __call__
2022-02-23T13:12:02.7589305Z E             return self.fn(*self.args, **self.kwargs)
2022-02-23T13:12:02.7589856Z E           File "/home/vsts/work/1/s/joblib/_parallel_backends.py", line 620, in __call__
2022-02-23T13:12:02.7590443Z E             return self.func(*args, **kwargs)
2022-02-23T13:12:02.7590955Z E           File "/home/vsts/work/1/s/joblib/parallel.py", line 287, in __call__
2022-02-23T13:12:02.7591485Z E             return [func(*args, **kwargs)
2022-02-23T13:12:02.7592011Z E           File "/home/vsts/work/1/s/joblib/parallel.py", line 287, in <listcomp>
2022-02-23T13:12:02.7592569Z E             return [func(*args, **kwargs)
2022-02-23T13:12:02.7593053Z E           File "<string>", line 10, in nested_loop
2022-02-23T13:12:02.7593584Z E           File "/home/vsts/work/1/s/joblib/parallel.py", line 1093, in __call__
2022-02-23T13:12:02.7594061Z E             self.retrieve()
2022-02-23T13:12:02.7594567Z E           File "/home/vsts/work/1/s/joblib/parallel.py", line 972, in retrieve
2022-02-23T13:12:02.7595140Z E             self._output.extend(job.get(timeout=self.timeout))
2022-02-23T13:12:02.7595721Z E           File "/home/vsts/work/1/s/joblib/_parallel_backends.py", line 567, in wrap_future_result
2022-02-23T13:12:02.7596340Z E             return future.result(timeout=timeout)
2022-02-23T13:12:02.7596938Z E           File "/usr/share/miniconda/envs/testenv/lib/python3.10/concurrent/futures/_base.py", line 446, in result
2022-02-23T13:12:02.7597509Z E             return self.__get_result()
2022-02-23T13:12:02.7598103Z E           File "/usr/share/miniconda/envs/testenv/lib/python3.10/concurrent/futures/_base.py", line 391, in __get_result
2022-02-23T13:12:02.7598899Z E             raise self._exception
2022-02-23T13:12:02.7599298Z E         ValueError
2022-02-23T13:12:02.7599684Z E         """
2022-02-23T13:12:02.7600020Z E         
2022-02-23T13:12:02.7600501Z E         The above exception was the direct cause of the following exception:
2022-02-23T13:12:02.7601083Z E         
2022-02-23T13:12:02.7601475Z E         Traceback (most recent call last):
2022-02-23T13:12:02.7601887Z E           File "<string>", line 16, in <module>
2022-02-23T13:12:02.7602393Z E           File "/home/vsts/work/1/s/joblib/parallel.py", line 1093, in __call__
2022-02-23T13:12:02.7602896Z E             self.retrieve()
2022-02-23T13:12:02.7603398Z E           File "/home/vsts/work/1/s/joblib/parallel.py", line 972, in retrieve
2022-02-23T13:12:02.7604059Z E             self._output.extend(job.get(timeout=self.timeout))
2022-02-23T13:12:02.7604665Z E           File "/home/vsts/work/1/s/joblib/_parallel_backends.py", line 567, in wrap_future_result
2022-02-23T13:12:02.7605249Z E             return future.result(timeout=timeout)
2022-02-23T13:12:02.7605823Z E           File "/usr/share/miniconda/envs/testenv/lib/python3.10/concurrent/futures/_base.py", line 446, in result
2022-02-23T13:12:02.7606405Z E             return self.__get_result()
2022-02-23T13:12:02.7607000Z E           File "/usr/share/miniconda/envs/testenv/lib/python3.10/concurrent/futures/_base.py", line 391, in __get_result
2022-02-23T13:12:02.7607565Z E             raise self._exception
2022-02-23T13:12:02.7607989Z E         ValueError
2022-02-23T13:12:02.7608829Z E         /home/vsts/work/1/s/joblib/externals/loky/backend/resource_tracker.py:310: UserWarning: resource_tracker: There appear to be 3 leaked semlock objects to clean up at shutdown
2022-02-23T13:12:02.7609561Z E           warnings.warn(
2022-02-23T13:12:02.7611304Z E         
2022-02-23T13:12:02.7613091Z E       assert b'resource_tracker' not in b'joblib.externals.loky.process_executor._RemoteTraceback: \n"""\njoblib.externals.loky.process_executor._RemoteTraceb...UserWarning: resource_tracker: There appear to be 3 leaked semlock objects to clean up at shutdown\n  warnings.warn(\n'
2022-02-23T13:12:02.7614912Z 
2022-02-23T13:12:02.7623487Z cmd        = 'if 1:\n        from joblib import Parallel, delayed\n\n\n        def raise_error(i):\n            raise ValueError\n\...(backend="loky", n_jobs=2)(\n                delayed(nested_loop)(func) for func in [raise_error]\n            )\n    '
2022-02-23T13:12:02.7625198Z err        = b'joblib.externals.loky.process_executor._RemoteTraceback: \n"""\njoblib.externals.loky.process_executor._RemoteTraceb...UserWarning: resource_tracker: There appear to be 3 leaked semlock objects to clean up at shutdown\n  warnings.warn(\n'
2022-02-23T13:12:02.7626194Z out        = b''
2022-02-23T13:12:02.7626895Z p          = <Popen: returncode: 1 args: ['/usr/share/miniconda/envs/testenv/bin/python',...>
2022-02-23T13:12:02.7627310Z 
2022-02-23T13:12:02.7627698Z joblib/test/test_memmapping.py:619: AssertionError

[ogrisel]

Maybe this is related to distributed that leaks resources from other tests? That seems unlikely, maybe this is just a coincidence.

[cmarmo]

Also observed in the amd64 build for debian