Intermittent CI issues: subprocess.CalledProcessError - Fatal Python error: _enter_buffered_busy: could not acquire lock

[jacobtomlinson]

I am noticing an intermittent subprocess.CalledProcessError error in CI mentioning locks and stderr. This has been seen in https://github.com/dask-contrib/dask-ctl/runs/5448329455?check_suite_focus=true and mentioned in #36 too.

subprocess.CalledProcessError: Command '['daskctl', 'cluster', 'create', '-f', '/home/runner/work/dask-ctl/dask-ctl/dask_ctl/tests/specs/simple.yaml']' died with <Signals.SIGABRT: 6>.

Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/threading.py", line 973, in _bootstrap_inner
    self.run()
  File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/threading.py", line 910, in run
    self._target(*self._args, **self._kwargs)
  File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/process.py", line 216, in _watch_process
Fatal Python error: _enter_buffered_busy: could not acquire lock for <_io.BufferedWriter name='<stderr>'> at interpreter shutdown, possibly due to daemon threads
Python runtime state: finalizing (tstate=0x55883c7ff240)

Current thread 0x00007f163932b740 (most recent call first):
<no Python frame>

Full log

```python-traceback ============================= test session starts ============================== platform linux -- Python 3.[9](https://github.com/dask-contrib/dask-ctl/runs/5448329455?check_suite_focus=true#step:5:9).[10](https://github.com/dask-contrib/dask-ctl/runs/5448329455?check_suite_focus=true#step:5:10), pytest-7.0.1, pluggy-1.0.0 rootdir: /home/runner/work/dask-ctl/dask-ctl, configfile: setup.cfg plugins: asyncio-0.15.1, cov-3.0.0 collected 24 items dask_ctl/discovery.py sss [ 12%] dask_ctl/lifecycle.py ssssss [ 37%] dask_ctl/proxy.py sss [ 50%] dask_ctl/tests/test_cli.py ..F. [ 66%] dask_ctl/tests/test_dask_ctl.py . [ 70%] dask_ctl/tests/test_discovery.py ..... [ 91%] dask_ctl/tests/test_lifecycle.py .. [100%] =================================== FAILURES =================================== _________________________________ test_create __________________________________ simple_spec_path = '/home/runner/work/dask-ctl/dask-ctl/dask_ctl/tests/specs/simple.yaml' def test_create(simple_spec_path): > output = check_output(["daskctl", "cluster", "create", "-f", simple_spec_path]) dask_ctl/tests/test_cli.py:25: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ /opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/subprocess.py:424: in check_output return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ input = None, capture_output = False, timeout = None, check = True popenargs = (['daskctl', 'cluster', 'create', '-f', '/home/runner/work/dask-ctl/dask-ctl/dask_ctl/tests/specs/simple.yaml'],) kwargs = {'stdout': -1} process = stdout = b'Created cluster 09fa9ac9.\n', stderr = None, retcode = -6 def run(*popenargs, input=None, capture_output=False, timeout=None, check=False, **kwargs): """Run command with arguments and return a CompletedProcess instance. The returned instance will have attributes args, returncode, stdout and stderr. By default, stdout and stderr are not captured, and those attributes will be None. Pass stdout=PIPE and/or stderr=PIPE in order to capture them. If check is True and the exit code was non-zero, it raises a CalledProcessError. The CalledProcessError object will have the return code in the returncode attribute, and output & stderr attributes if those streams were captured. If timeout is given, and the process takes too long, a TimeoutExpired exception will be raised. There is an optional argument "input", allowing you to pass bytes or a string to the subprocess's stdin. If you use this argument you may not also use the Popen constructor's "stdin" argument, as it will be used internally. By default, all communication is in bytes, and therefore any "input" should be bytes, and the stdout and stderr will be bytes. If in text mode, any "input" should be a string, and stdout and stderr will be strings decoded according to locale encoding, or by "encoding" if set. Text mode is triggered by setting any of text, encoding, errors or universal_newlines. The other arguments are the same as for the Popen constructor. """ if input is not None: if kwargs.get('stdin') is not None: raise ValueError('stdin and input arguments may not both be used.') kwargs['stdin'] = PIPE if capture_output: if kwargs.get('stdout') is not None or kwargs.get('stderr') is not None: raise ValueError('stdout and stderr arguments may not be used ' 'with capture_output.') kwargs['stdout'] = PIPE kwargs['stderr'] = PIPE with Popen(*popenargs, **kwargs) as process: try: stdout, stderr = process.communicate(input, timeout=timeout) except TimeoutExpired as exc: process.kill() if _mswindows: # Windows accumulates the output in a single blocking # read() call run on child threads, with the timeout # being done in a join() on those threads. communicate() # _after_ kill() is required to collect that and add it # to the exception. exc.stdout, exc.stderr = process.communicate() else: # POSIX _communicate already populated the output so # far into the TimeoutExpired exception. process.wait() raise except: # Including KeyboardInterrupt, communicate handled that. process.kill() # We don't call process.wait() as .__exit__ does that for us. raise retcode = process.poll() if check and retcode: > raise CalledProcessError(retcode, process.args, output=stdout, stderr=stderr) E subprocess.CalledProcessError: Command '['daskctl', 'cluster', 'create', '-f', '/home/runner/work/dask-ctl/dask-ctl/dask_ctl/tests/specs/simple.yaml']' died with . /opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/subprocess.py:528: CalledProcessError ----------------------------- Captured stderr call ----------------------------- /home/runner/work/dask-ctl/dask-ctl/dask_ctl/cli.py:15: FutureWarning: typename is deprecated and will be removed in a future release. Please use dask.utils.typename instead. from distributed.utils import typename Exception in thread AsyncProcess Dask Worker process (from Nanny) watch process join: Fatal Python error: _enter_buffered_busy: could not acquire lock for <_io.BufferedWriter name=''> at interpreter shutdown, possibly due to daemon threads Python runtime state: finalizing (tstate=0x559447276ac0) Current thread 0x00007f7f2bd16740 (most recent call first): =============================== warnings summary =============================== dask_ctl/cli.py:15 /home/runner/work/dask-ctl/dask-ctl/dask_ctl/cli.py:15: FutureWarning: typename is deprecated and will be removed in a future release. Please use dask.utils.typename instead. from distributed.utils import typename dask_ctl/tests/test_cli.py::test_list dask_ctl/tests/test_lifecycle.py::test_snippet /opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/scheduler.py:5715: UserWarning: Scheduler already contains a plugin with name worker-status; overwriting. warnings.warn( dask_ctl/tests/test_cli.py::test_autocompletion dask_ctl/tests/test_discovery.py::test_discover_cluster_names dask_ctl/tests/test_lifecycle.py::test_snippet /opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/client.py:1354: RuntimeWarning: coroutine 'wait_for' was never awaited self.close() dask_ctl/tests/test_cli.py::test_autocompletion dask_ctl/tests/test_discovery.py::test_discover_cluster_names dask_ctl/tests/test_lifecycle.py::test_snippet /opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/client.py:1354: RuntimeWarning: coroutine 'Client._close' was never awaited self.close() dask_ctl/tests/test_discovery.py::test_discover_clusters /home/runner/work/dask-ctl/dask-ctl/dask_ctl/discovery.py:100: UserWarning: Cluster discovery for proxycluster timed out. warnings.warn( dask_ctl/tests/test_discovery.py::test_discover_clusters /opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/_pytest/unraisableexception.py:78: PytestUnraisableExceptionWarning: Exception ignored in: Traceback (most recent call last): File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/client.py", line 1354, in __del__ self.close() File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/client.py", line 1597, in close sync(self.loop, self._close, fast=True, callback_timeout=timeout) File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/utils.py", line 371, in sync raise TimeoutError(f"timed out after {callback_timeout} s.") asyncio.exceptions.TimeoutError: timed out after 2 s. warnings.warn(pytest.PytestUnraisableExceptionWarning(msg)) dask_ctl/tests/test_lifecycle.py::test_snippet Exception in thread AsyncProcess Dask Worker process (from Nanny) watch process join: /opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/node.py:180: UserWarning: Port 8787 is already in use. Perhaps you already have a cluster running? Hosting the HTTP server on port 43767 instead warnings.warn( -- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html ---------- coverage: platform linux, python 3.9.10-final-0 ----------- Name Stmts Miss Cover ------------------------------------------------ dask_ctl/__init__.py 10 0 100% dask_ctl/cli.py 162 53 67% dask_ctl/config.py 8 0 100% dask_ctl/discovery.py 34 4 88% dask_ctl/lifecycle.py 42 9 79% dask_ctl/proxy.py 46 2 96% dask_ctl/spec.py 14 1 93% dask_ctl/tests/conftest.py [11](https://github.com/dask-contrib/dask-ctl/runs/5448329455?check_suite_focus=true#step:5:11) 1 91% dask_ctl/utils.py 18 0 100% ------------------------------------------------ TOTAL 345 70 80% =========================== short test summary info ============================ FAILED dask_ctl/tests/test_cli.py::test_create - subprocess.CalledProcessErro... ============ 1 failed, 11 passed, [12](https://github.com/dask-contrib/dask-ctl/runs/5448329455?check_suite_focus=true#step:5:12) skipped, 12 warnings in 34.43s ============ Traceback (most recent call last): File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/threading.py", line 973, in _bootstrap_inner self.run() File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/threading.py", line 910, in run self._target(*self._args, **self._kwargs) File "/opt/hostedtoolcache/Python/3.9.10/x64/lib/python3.9/site-packages/distributed/process.py", line 216, in _watch_process Fatal Python error: _enter_buffered_busy: could not acquire lock for <_io.BufferedWriter name=''> at interpreter shutdown, possibly due to daemon threads Python runtime state: finalizing (tstate=0x55883c7ff240) Current thread 0x00007f163932b740 (most recent call first): /home/runner/work/_temp/58de1659-75dd-4396-916b-3d1fc3[13](https://github.com/dask-contrib/dask-ctl/runs/5448329455?check_suite_focus=true#step:5:13)2720.sh: line 1: [17](https://github.com/dask-contrib/dask-ctl/runs/5448329455?check_suite_focus=true#step:5:17)06 Aborted (core dumped) pytest ```

[keewis]

If I understand correctly, the issue is that there are daemon threads (those with thread.daemon = True) involved somewhere that try to print to stderr on shutdown (which might have already been deconstructed).

Since there's no explicit use of threading here I suppose this should actually be forwarded to distributed?

Edit: I have also occasionally seen this when shutting down (double Ctrl-C in the terminal) a jupyterlab instance with a cluster created by dask-labextension still running