Green hangs on ModuleNotFoundError

[jakebott]

I have recently noticed that if a test tries to import a non-existent module, it will print out a stack trace then hang indefinitely instead of the expected behaviour of reporting a failed test or crashing.

Reproducing the error

Create a file called test_something.py in an empty directory with the following contents:

import unittest
#import notinstalledlibrary

class TestRunner(unittest.TestCase):
    def test_something(self):
        self.assertEqual(42, 42)

Run green in the directory. It will produce the following output as expected:

.

Ran 1 test in 0.026s using 12 processes

OK (passes=1)

Now uncomment line 2 and re-run green. It will produce the following output then hang indefinitely without returning.

Traceback (most recent call last):
  File "/usr/bin/green", line 11, in <module>
    load_entry_point('green==3.1.0', 'console_scripts', 'green')()
  File "/usr/lib/python3.8/site-packages/green/cmdline.py", line 70, in main
    result = run(test_suite, stream, args, testing)
  File "/usr/lib/python3.8/site-packages/green/runner.py", line 89, in run
    for target in toParallelTargets(suite, args.targets)]
  File "/usr/lib/python3.8/site-packages/green/loader.py", line 346, in toParallelTargets
    proto_test_list = toProtoTestList(suite)
  File "/usr/lib/python3.8/site-packages/green/loader.py", line 330, in toProtoTestList
    toProtoTestList(i, test_list, doing_completions)
  File "/usr/lib/python3.8/site-packages/green/loader.py", line 322, in toProtoTestList
    getattr(suite, exception_method)()
  File "/usr/lib/python3.8/site-packages/green/loader.py", line 83, in testFailure
    raise ImportError(message)
ImportError: Failed to import test_something computed from filename /home/jake/green_test/test_something.py
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/green/loader.py", line 55, in loadFromModuleFilename
    __import__(dotted_module)
  File "/home/jake/green_test/test_something.py", line 2, in <module>
    import notinstalledlibrary
ModuleNotFoundError: No module named 'notinstalledlibrary'

If the process is then terminated by pressing control+C, it will print this:

^C^CProcess DaemonlessPoolWorker-4:
Process DaemonlessPoolWorker-8:
Process DaemonlessPoolWorker-6:
Process DaemonlessPoolWorker-12:
Process DaemonlessPoolWorker-5:
Process DaemonlessPoolWorker-10:
Process DaemonlessPoolWorker-1:
Process DaemonlessPoolWorker-7:
Process DaemonlessPoolWorker-2:
Process DaemonlessPoolWorker-11:
Process DaemonlessPoolWorker-9:
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/util.py", line 277, in _run_finalizers
    finalizer()
  File "/usr/lib/python3.8/multiprocessing/util.py", line 201, in __call__
    res = self._callback(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/multiprocessing/pool.py", line 689, in _terminate_pool
Traceback (most recent call last):
    cls._help_stuff_finish(inqueue, task_handler, len(pool))
  File "/usr/lib/python3.8/multiprocessing/pool.py", line 674, in _help_stuff_finish
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
Process DaemonlessPoolWorker-3:
Traceback (most recent call last):
Traceback (most recent call last):
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
Traceback (most recent call last):
    inqueue._rlock.acquire()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
KeyboardInterrupt
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
    self.default_handler(signum, frame)
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
KeyboardInterrupt
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
Traceback (most recent call last):
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
KeyboardInterrupt
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
KeyboardInterrupt
KeyboardInterrupt
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
KeyboardInterrupt
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 356, in get
    res = self._reader.recv_bytes()
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/connection.py", line 216, in recv_bytes
    buf = self._recv_bytes(maxlength)
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/connection.py", line 414, in _recv_bytes
    buf = self._recv(4)
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
  File "/usr/lib/python3.8/multiprocessing/connection.py", line 379, in _recv
    chunk = read(handle, remaining)
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
KeyboardInterrupt
KeyboardInterrupt
Traceback (most recent call last):
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
KeyboardInterrupt
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
Traceback (most recent call last):
KeyboardInterrupt
KeyboardInterrupt
  File "/usr/lib/python3.8/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/lib/python3.8/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.8/site-packages/green/process.py", line 176, in worker
    task = get()
  File "/usr/lib/python3.8/multiprocessing/queues.py", line 355, in get
    with self._rlock:
  File "/usr/lib/python3.8/multiprocessing/synchronize.py", line 95, in __enter__
    return self._semlock.__enter__()
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
KeyboardInterrupt
  File "/usr/lib/python3.8/unittest/signals.py", line 36, in __call__
    self.default_handler(signum, frame)
KeyboardInterrupt

System Information

$ green --version
Green 3.1.0, Coverage 4.5.4, Python 3.8.2

OS: Arch Linux (also reproducible on our CI system which uses the python:3.8 docker image CPU: i7-8750H (CI runs on an AMD Ryzen 9 3900X)

Please let me know if there is any other information that would be useful.

[CleanCut]

Thanks, @jakebott! Great bug report! Although I wasn't able to reproduce it on my Mac, that docker image allowed me to reproduce it and track it down.

The TL;DR is that it was a bug uptream, and I was able to work around it pretty easily by moving the initialization of the multiprocessing pool until after we've had a chance to load the modules (and crash out).

Here's how I put it in the release notes for Green 3.1.1:

• Fixed a hang that sometimes occurs in Python 3.8.0-3.8.2 due to a bug in upstream Python
  • Upstream bug report: https://bugs.python.org/issue39360
  • Upstream fix in master: https://github.com/python/cpython/pull/19009
  • Upstream fix in 3.8 branch (Maybe gets included in 3.8.3?): https://github.com/python/cpython/pull/19023

[CleanCut]

Fix included in Green 3.1.1, just released.

[jakebott]

Thanks @CleanCut! I have double-checked and so I can confirm that Green 3.1.1 fixes the problem.

[CleanCut]

FYI, the way I fixed this in 3.1.1 introduced hangs and crashes (I observed them on macOS)...with increasing chances of problems with each additional subprocess. I fixed the regression in 3.2.0 while preserving this fix. I recommend anyone using 3.1.x upgrade to at least 3.2.0.