Flaky test: test_multithreaded_parallel_termination_resource_tracker_silent

[ogrisel]

Observed after the merge of loky 3.1.0.

• windows_py310 on Trigger new CI run #1274

https://dev.azure.com/joblib/joblib/_build/results?buildId=1852&view=logs&j=a35b4612-962d-5bf3-96de-7e8bc5750ea4&t=0182bc6c-d367-55f8-ab6b-9f319778ff9d

and:

• windows_py310 on Bump up dependency versions on the CI config #1272

https://dev.azure.com/joblib/joblib/_build/results?buildId=1850&view=logs&j=8008bb8c-6b4f-56d5-66f4-b1d037aba1bf&t=7af8808d-3494-56e0-c1dc-6fbf5bb2bc40

2022-02-23T13:35:43.2669420Z ================================== FAILURES ===================================
2022-02-23T13:35:43.2670528Z _______ test_multithreaded_parallel_termination_resource_tracker_silent _______
2022-02-23T13:35:43.2671117Z 
2022-02-23T13:35:43.2671822Z     @with_numpy
2022-02-23T13:35:43.2692699Z     @with_multiprocessing
2022-02-23T13:35:43.2825045Z     def test_multithreaded_parallel_termination_resource_tracker_silent():
2022-02-23T13:35:43.2826313Z         # test that concurrent termination attempts of a same executor does not
2022-02-23T13:35:43.2827079Z         # emit any spurious error from the resource_tracker. We test various
2022-02-23T13:35:43.2827864Z         # situations making 0, 1 or both parallel call sending a task that will
2022-02-23T13:35:43.2828604Z         # make the worker (and thus the whole Parallel call) error out.
2022-02-23T13:35:43.2829221Z         cmd = '''if 1:
2022-02-23T13:35:43.2829983Z             import os
2022-02-23T13:35:43.2830519Z             import numpy as np
2022-02-23T13:35:43.2831177Z             from joblib import Parallel, delayed
2022-02-23T13:35:43.2831882Z             from joblib.externals.loky.backend import resource_tracker
2022-02-23T13:35:43.2832575Z             from concurrent.futures import ThreadPoolExecutor, wait
2022-02-23T13:35:43.2833204Z     
2022-02-23T13:35:43.2834162Z             resource_tracker.VERBOSE = 0
2022-02-23T13:35:43.2834760Z     
2022-02-23T13:35:43.2835410Z             array = np.arange(int(1e2))
2022-02-23T13:35:43.2835949Z     
2022-02-23T13:35:43.2836574Z             temp_dirs_thread_1 = set()
2022-02-23T13:35:43.2837256Z             temp_dirs_thread_2 = set()
2022-02-23T13:35:43.2837839Z     
2022-02-23T13:35:43.2838358Z     
2022-02-23T13:35:43.2838884Z             def raise_error(array):
2022-02-23T13:35:43.2839498Z                 raise ValueError
2022-02-23T13:35:43.2840014Z     
2022-02-23T13:35:43.2840541Z     
2022-02-23T13:35:43.2841153Z             def parallel_get_filename(array, temp_dirs):
2022-02-23T13:35:43.2841848Z                 with Parallel(backend="loky", n_jobs=2, max_nbytes=10) as p:
2022-02-23T13:35:43.2842586Z                     for i in range(10):
2022-02-23T13:35:43.2843201Z                         [filename] = p(
2022-02-23T13:35:43.2844499Z                             delayed(getattr)(array, "filename") for _ in range(1)
2022-02-23T13:35:43.2845213Z                         )
2022-02-23T13:35:43.2845839Z                         temp_dirs.add(os.path.dirname(filename))
2022-02-23T13:35:43.2846466Z     
2022-02-23T13:35:43.2847002Z     
2022-02-23T13:35:43.2847554Z             def parallel_raise(array, temp_dirs):
2022-02-23T13:35:43.2848262Z                 with Parallel(backend="loky", n_jobs=2, max_nbytes=10) as p:
2022-02-23T13:35:43.2849945Z                     for i in range(10):
2022-02-23T13:35:43.2850701Z                         [filename] = p(
2022-02-23T13:35:43.2851377Z                             delayed(raise_error)(array) for _ in range(1)
2022-02-23T13:35:43.2852153Z                         )
2022-02-23T13:35:43.2852791Z                         temp_dirs.add(os.path.dirname(filename))
2022-02-23T13:35:43.2853407Z     
2022-02-23T13:35:43.2853894Z     
2022-02-23T13:35:43.2854511Z             executor = ThreadPoolExecutor(max_workers=2)
2022-02-23T13:35:43.2855267Z     
2022-02-23T13:35:43.2855919Z             # both function calls will use the same loky executor, but with a
2022-02-23T13:35:43.2856623Z             # different Parallel object.
2022-02-23T13:35:43.2857270Z             future_1 = executor.submit({f1}, array, temp_dirs_thread_1)
2022-02-23T13:35:43.2858011Z             future_2 = executor.submit({f2}, array, temp_dirs_thread_2)
2022-02-23T13:35:43.2858601Z     
2022-02-23T13:35:43.2859217Z             # Wait for both threads to terminate their backend
2022-02-23T13:35:43.2859885Z             wait([future_1, future_2])
2022-02-23T13:35:43.2862325Z     
2022-02-23T13:35:43.2863060Z             future_1.result()
2022-02-23T13:35:43.2863630Z             future_2.result()
2022-02-23T13:35:43.2864209Z         '''
2022-02-23T13:35:43.2864900Z         functions_and_returncodes = [
2022-02-23T13:35:43.2865622Z             ("parallel_get_filename", "parallel_get_filename", 0),
2022-02-23T13:35:43.2866353Z             ("parallel_get_filename", "parallel_raise", 1),
2022-02-23T13:35:43.2867055Z             ("parallel_raise", "parallel_raise", 1)
2022-02-23T13:35:43.2867820Z         ]
2022-02-23T13:35:43.2868321Z     
2022-02-23T13:35:43.2868971Z         for f1, f2, returncode in functions_and_returncodes:
2022-02-23T13:35:43.2869685Z             p = subprocess.Popen([sys.executable, '-c', cmd.format(f1=f1, f2=f2)],
2022-02-23T13:35:43.2871642Z                                  stderr=subprocess.PIPE, stdout=subprocess.PIPE)
2022-02-23T13:35:43.2872472Z             p.wait()
2022-02-23T13:35:43.2873052Z             out, err = p.communicate()
2022-02-23T13:35:43.2873742Z             assert p.returncode == returncode, out.decode()
2022-02-23T13:35:43.2874466Z >           assert b"resource_tracker" not in err, err.decode()
2022-02-23T13:35:44.1447184Z E           AssertionError: Traceback (most recent call last):
2022-02-23T13:35:44.1449347Z 
2022-02-23T13:35:44.1451047Z E               File "D:\a\1\s\joblib\externals\loky\backend\resource_tracker.py", line 271, in main
2022-02-23T13:35:44.1451412Z 
2022-02-23T13:35:44.1451844Z E                 del registry[rtype][name]
2022-02-23T13:35:44.1452093Z 
2022-02-23T13:35:44.1452884Z E             KeyError: 'C:\\Users\\VSSADM~1\\AppData\\Local\\Temp\\joblib_memmapping_folder_1196_62c0aebffe334d5b905be1603dd8495d_dd00eadf3e06482e876453a83937d4c2\\1196-2784653655968-c025310e3e1747aca846aed7ae6dfa70.pkl'
2022-02-23T13:35:44.1453502Z 
2022-02-23T13:35:44.1454387Z E             Traceback (most recent call last):
2022-02-23T13:35:44.1454759Z 
2022-02-23T13:35:44.1455261Z E               File "<string>", line 48, in <module>
2022-02-23T13:35:44.1455511Z 
2022-02-23T13:35:44.1456007Z E               File "C:\Miniconda\envs\testenv\lib\concurrent\futures\_base.py", line 439, in result
2022-02-23T13:35:44.1456396Z 
2022-02-23T13:35:44.1456768Z E                 return self.__get_result()
2022-02-23T13:35:44.1457045Z 
2022-02-23T13:35:44.1457539Z E               File "C:\Miniconda\envs\testenv\lib\concurrent\futures\_base.py", line 391, in __get_result
2022-02-23T13:35:44.1457885Z 
2022-02-23T13:35:44.1458298Z E                 raise self._exception
2022-02-23T13:35:44.1458522Z 
2022-02-23T13:35:44.1459033Z E               File "C:\Miniconda\envs\testenv\lib\concurrent\futures\thread.py", line 58, in run
2022-02-23T13:35:44.1459364Z 
2022-02-23T13:35:44.1459989Z E                 result = self.fn(*self.args, **self.kwargs)
2022-02-23T13:35:44.1460393Z 
2022-02-23T13:35:44.1461028Z E               File "<string>", line 23, in parallel_get_filename
2022-02-23T13:35:44.1461670Z 
2022-02-23T13:35:44.1462258Z E               File "D:\a\1\s\joblib\parallel.py", line 1080, in __call__
2022-02-23T13:35:44.1462870Z 
2022-02-23T13:35:44.1463312Z E                 if self.dispatch_one_batch(iterator):
2022-02-23T13:35:44.1463566Z 
2022-02-23T13:35:44.1464129Z E               File "D:\a\1\s\joblib\parallel.py", line 898, in dispatch_one_batch
2022-02-23T13:35:44.1464436Z 
2022-02-23T13:35:44.1464793Z E                 self._dispatch(tasks)
2022-02-23T13:35:44.1465065Z 
2022-02-23T13:35:44.1465476Z E               File "D:\a\1\s\joblib\parallel.py", line 816, in _dispatch
2022-02-23T13:35:44.1465808Z 
2022-02-23T13:35:44.1466226Z E                 job = self._backend.apply_async(batch, callback=cb)
2022-02-23T13:35:44.1466511Z 
2022-02-23T13:35:44.1466998Z E               File "D:\a\1\s\joblib\_parallel_backends.py", line 556, in apply_async
2022-02-23T13:35:44.1467304Z 
2022-02-23T13:35:44.1467760Z E                 future = self._workers.submit(SafeFunction(func))
2022-02-23T13:35:44.1468037Z 
2022-02-23T13:35:44.1468539Z E               File "D:\a\1\s\joblib\externals\loky\reusable_executor.py", line 176, in submit
2022-02-23T13:35:44.1468868Z 
2022-02-23T13:35:44.1469306Z E                 return super().submit(fn, *args, **kwargs)
2022-02-23T13:35:44.1469567Z 
2022-02-23T13:35:44.1470025Z E               File "D:\a\1\s\joblib\externals\loky\process_executor.py", line 1090, in submit
2022-02-23T13:35:44.1470392Z 
2022-02-23T13:35:44.1470763Z E                 raise ShutdownExecutorError(
2022-02-23T13:35:44.1471163Z 
2022-02-23T13:35:44.1471684Z E             joblib.externals.loky.process_executor.ShutdownExecutorError: cannot schedule new futures after shutdown
2022-02-23T13:35:44.1472113Z 
2022-02-23T13:35:44.1472388Z E             
2022-02-23T13:35:44.1473275Z E           assert b'resource_tracker' not in b'Traceback (most recent call last):\r\n  File "D:\\a\\1\\s\\joblib\\externals\\loky\\backend\\resource_tracker.py", l...Error(\r\njoblib.externals.loky.process_executor.ShutdownExecutorError: cannot schedule new futures after shutdown\r\n'
2022-02-23T13:35:44.1474054Z 
2022-02-23T13:35:44.1474811Z cmd        = 'if 1:\n        import os\n        import numpy as np\n        from joblib import Parallel, delayed\n        from jobl...minate their backend\n        wait([future_1, future_2])\n\n        future_1.result()\n        future_2.result()\n    '
2022-02-23T13:35:44.1476016Z err        = b'Traceback (most recent call last):\r\n  File "D:\\a\\1\\s\\joblib\\externals\\loky\\backend\\resource_tracker.py", l...Error(\r\njoblib.externals.loky.process_executor.ShutdownExecutorError: cannot schedule new futures after shutdown\r\n'
2022-02-23T13:35:44.1476889Z f1         = 'parallel_get_filename'
2022-02-23T13:35:44.1477300Z f2         = 'parallel_raise'
2022-02-23T13:35:44.1478032Z functions_and_returncodes = [('parallel_get_filename', 'parallel_get_filename', 0), ('parallel_get_filename', 'parallel_raise', 1), ('parallel_raise', 'parallel_raise', 1)]
2022-02-23T13:35:44.1478703Z out        = b''
2022-02-23T13:35:44.1479230Z p          = <Popen: returncode: 1 args: ['C:\\Miniconda\\envs\\testenv\\python.exe', '-c...>
2022-02-23T13:35:44.1479717Z returncode = 1
2022-02-23T13:35:44.1479949Z 
2022-02-23T13:35:44.1480377Z joblib\test\test_memmapping.py:586: AssertionError

May be related to #1273.