joblib / loky

Robust and reusable Executor for joblib
http://loky.readthedocs.io/en/stable/
BSD 3-Clause "New" or "Revised" License
528 stars 45 forks source link

AssertionError: notify: Should not have been able to acquire _wait_semaphore on Python 3.11 / Windows #392

Closed ogrisel closed 1 year ago

ogrisel commented 1 year ago

As observed in test_kill_process_tree of:

________________________ test_kill_process_tree[True] _________________________
use_psutil = True
    @pytest.mark.parametrize("use_psutil", [True, False])
    def test_kill_process_tree(use_psutil):
        psutil = pytest.importorskip("psutil")
        event = ctx_loky.Event()
        p = ctx_loky.Process(target=_run_nested_delayed, args=(4, 1000, event))
        p.start()

        # Wait for all the processes to be launched
        if not event.wait(30):
            kill_process_tree(p, use_psutil=use_psutil)
>           raise RuntimeError(
                "test_kill_process_tree was not able to launch "
                "all nested processes."
            )
E           RuntimeError: test_kill_process_tree was not able to launch all nested processes.
event      = <Event at 0x1f84532f250 unset>
p          = <LokyProcess name='LokyProcess-20' pid=808 parent=7696 stopped exitcode=15>
psutil     = <module 'psutil' from 'D:\\a\\1\\s\\.tox\\py311\\Lib\\site-packages\\psutil\\__init__.py'>
use_psutil = True
tests\test_loky_backend.py:727: RuntimeError
---------------------------- Captured stderr call -----------------------------
[DEBUG:MainProcess:MainThread] created semlock with handle 1876
[DEBUG:MainProcess:MainThread] created semlock with handle 1868
[DEBUG:MainProcess:MainThread] created semlock with handle 1892
[DEBUG:MainProcess:MainThread] created semlock with handle 1780
[DEBUG:MainProcess:MainThread] created semlock with handle 1792
[DEBUG:LokyProcess-20:MainThread] recreated blocker with handle 20
[DEBUG:LokyProcess-20:MainThread] recreated blocker with handle 24
[DEBUG:LokyProcess-20:MainThread] recreated blocker with handle 28
[DEBUG:LokyProcess-20:MainThread] recreated blocker with handle 36
[DEBUG:LokyProcess-20:MainThread] recreated blocker with handle 48
[INFO:LokyProcess-20:MainThread] child process calling self.run()
[DEBUG:LokyProcess-20:1:MainThread] recreated blocker with handle 88
[DEBUG:LokyProcess-20:1:MainThread] recreated blocker with handle 92
[DEBUG:LokyProcess-20:1:MainThread] recreated blocker with handle 96
[DEBUG:LokyProcess-20:1:MainThread] recreated blocker with handle 100
[DEBUG:LokyProcess-20:1:MainThread] recreated blocker with handle 104
[INFO:LokyProcess-20:1:MainThread] child process calling self.run()
[DEBUG:LokyProcess-20:1:1:MainThread] recreated blocker with handle 88
[DEBUG:LokyProcess-20:1:1:MainThread] recreated blocker with handle 92
[DEBUG:LokyProcess-20:1:1:MainThread] recreated blocker with handle 96
[DEBUG:LokyProcess-20:1:1:MainThread] recreated blocker with handle 100
[DEBUG:LokyProcess-20:1:1:MainThread] recreated blocker with handle 104
[INFO:LokyProcess-20:1:1:MainThread] child process calling self.run()
[DEBUG:LokyProcess-20:1:1:1:MainThread] recreated blocker with handle 88
[DEBUG:LokyProcess-20:1:1:1:MainThread] recreated blocker with handle 92
[DEBUG:LokyProcess-20:1:1:1:MainThread] recreated blocker with handle 96
[DEBUG:LokyProcess-20:1:1:1:MainThread] recreated blocker with handle 100
[DEBUG:LokyProcess-20:1:1:1:MainThread] recreated blocker with handle 104
[INFO:LokyProcess-20:1:1:1:MainThread] child process calling self.run()
[DEBUG:LokyProcess-20:1:1:1:1:MainThread] recreated blocker with handle 84
[DEBUG:LokyProcess-20:1:1:1:1:MainThread] recreated blocker with handle 88
[DEBUG:LokyProcess-20:1:1:1:1:MainThread] recreated blocker with handle 96
[DEBUG:LokyProcess-20:1:1:1:1:MainThread] recreated blocker with handle 100
[DEBUG:LokyProcess-20:1:1:1:1:MainThread] recreated blocker with handle 104
[INFO:LokyProcess-20:1:1:1:1:MainThread] child process calling self.run()
[INFO:LokyProcess-20:1:1:1:1:MainThread] process shutting down
[DEBUG:LokyProcess-20:1:1:1:1:MainThread] running all "atexit" finalizers with priority >= 0
[DEBUG:LokyProcess-20:1:1:1:1:MainThread] running the remaining "atexit" finalizers
Process LokyProcess-20:1:1:1:1:
Traceback (most recent call last):
  File "C:\hostedtoolcache\windows\Python\3.11.2\x64\Lib\multiprocessing\synchronize.py", line 338, in set
    self._cond.notify_all()
  File "C:\hostedtoolcache\windows\Python\3.11.2\x64\Lib\multiprocessing\synchronize.py", line 297, in notify_all
    self.notify(n=sys.maxsize)
  File "C:\hostedtoolcache\windows\Python\3.11.2\x64\Lib\multiprocessing\synchronize.py", line 272, in notify
    assert not self._wait_semaphore.acquire(
AssertionError: notify: Should not have been able to acquire _wait_semaphore

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\hostedtoolcache\windows\Python\3.11.2\x64\Lib\multiprocessing\process.py", line 314, in _bootstrap
    self.run()
  File "C:\hostedtoolcache\windows\Python\3.11.2\x64\Lib\multiprocessing\process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "D:\a\1\s\tests\test_loky_backend.py", line 712, in _run_nested_delayed
    event.set()
  File "C:\hostedtoolcache\windows\Python\3.11.2\x64\Lib\multiprocessing\synchronize.py", line 335, in set
    with self._cond:
  File "C:\hostedtoolcache\windows\Python\3.11.2\x64\Lib\multiprocessing\synchronize.py", line 233, in __exit__
    return self._lock.__exit__(*args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\hostedtoolcache\windows\Python\3.11.2\x64\Lib\multiprocessing\synchronize.py", line 98, in __exit__
    return self._semlock.__exit__(*args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
OSError: [WinError 6] The handle is invalid
[INFO:LokyProcess-20:1:1:1:1:MainThread] process exiting with exitcode 1
ogrisel commented 1 year ago

Fixed by #394.