multiprocessing cleanup occasionally throws exception

[JorgeHerskovic]

BPO	24484
Nosy	@pitrou, @ned-deily, @applio, @Marandil
PRs	bpo-24484: Avoid race condition in multiprocessing cleanup #2159 [3.6] bpo-24484: Avoid race condition in multiprocessing cleanup (GH-2159) #2166 [3.5] bpo-24484: Avoid race condition in multiprocessing cleanup (GH-2159) #2167 [2.7] backport test for bpo-24484: Avoid race condition in multiprocessing cleanup (GH-2159) #2168
Files	run_finalizers.patch finalizestress.py

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2017-06-13.15:54:48.330>
created_at = <Date 2015-06-21.15:08:26.962>
labels = ['3.7', 'type-bug', 'library']
title = 'multiprocessing cleanup occasionally throws exception'
updated_at = <Date 2017-06-13.15:54:48.328>
user = 'https://bugs.python.org/JorgeHerskovic'

bugs.python.org fields:

activity = <Date 2017-06-13.15:54:48.328>
actor = 'pitrou'
assignee = 'none'
closed = True
closed_date = <Date 2017-06-13.15:54:48.330>
closer = 'pitrou'
components = ['Library (Lib)']
creation = <Date 2015-06-21.15:08:26.962>
creator = 'Jorge Herskovic'
dependencies = []
files = ['46944', '46946']
hgrepos = []
issue_num = 24484
keywords = ['patch']
message_count = 22.0
messages = ['245597', '245629', '245687', '245704', '245705', '245707', '245713', '245731', '245738', '245739', '245810', '250137', '294546', '295876', '295880', '295886', '295927', '295929', '295931', '295933', '295934', '295935']
nosy_count = 6.0
nosy_names = ['pitrou', 'ned.deily', 'sbt', 'davin', 'Jorge Herskovic', 'Marandil']
pr_nums = ['2159', '2166', '2167', '2168']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue24484'
versions = ['Python 3.5', 'Python 3.6', 'Python 3.7']

[JorgeHerskovic]

I'm writing a library on top of multiprocessing. As part of the test suite, I create and destroy dozens of processes repeatedly. About once in 50 runs, the tests complete successfully but the program crashes with:

Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/multiprocessing/util.py", line 286, in _exit_function
    _run_finalizers(0)
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/multiprocessing/util.py", line 246, in _run_finalizers
    items = [x for x in list(_finalizer_registry.items()) if f(x)]
RuntimeError: dictionary changed size during iteration

(this is on OS X 10.10.3, Python 3.4.3; I've been unable to replicate the behavior on Python 2.7.9, 3.5.0b2, or pypy despite hundreds of runs)

The problematic code is available at https://github.com/jherskovic/mpetl and the tests should be run with nosetests

[JorgeHerskovic]

This happens reliably between 1-5% of the time on my home Mac (a 4.0 GHz i7). My work Mac Pro, a lot slower, doesn't exhibit this behavior on the same 3.4.3 interpreter.

Could it be related to a concurrency issue in the interpreter?

We're attempting to replicate on other systems.

[JorgeHerskovic]

More data:

I've been unable to replicate this behavior on Ubuntu 15.04 on Python 3.4.3 over ~20 thousand test runs. (Same machine, running in a VM)

An overnight repeated run on the original machine on OS X, 3.4.3, official distribution gave an actual frequency of 0.1% (7 crashes in 6980 runs).

Approximately 3,300 runs on Python 2.7.9 on the same machine have not resulted in any crashes.

I now built 3.4.3 from source using the latest clang and am trying it again, on the same machine, instead of using the official distribution. So far, 0 crashes in approximately 3,300 runs so far.

At the moment, then, the problem seems localized to the official 3.4.3 binaries for OS X.

[ned-deily]

Can you show the version info from the Python 3.4 where you see the failures?

/usr/local/bin/python3.4 -c 'import sys;print(sys.version)'

[ned-deily]

Exactly how are you building the Python 3.4 that does not fail for you? FWIW, I am able to reproduce the failure easily on a 10.10.3 system using python.org 64-bit/32-bit 3.4.3, using a current MacPorts source-built 3.4.3 (which is built with clang), and repeatedly using the current head of the 3.4 branch (post-3.4.3) built with clang, both with and without pydebug enabled.

[JorgeHerskovic]

The failing Python:
3.4.3 (v3.4.3:9b73f1c3e601, Feb 23 2015, 02:52:03)
[GCC 4.2.1 (Apple Inc. build 5666) (dot 3)]

The non-failing Python:
3.4.3 (default, Jun 23 2015, 06:33:02)
[GCC 4.2.1 Compatible Apple LLVM 6.1.0 (clang-602.0.53)]

The non-failing python, I just downloaded the tarball and ran ./configure --prefix=/opt/python343, make, sudo make install, and then created a virtualenv using that binary.

Given what you're telling me, I'll run some more loops with the "non-failing" python. I'm grateful you've been able to reproduce the problem, FWIW.

[ned-deily]

FWIW, building 3.4.3 from source as you described results in failures about 30% of the time. With some of the earlier tests, it failed even more frequently. This is running on a 2.2GHz I7.

[JorgeHerskovic]

20,000+ iterations of the test suite with my homebuilt 3.4.3 throw no exceptions.

Weirder and weirder.

Any suggestions? Without any actual knowledge ("unencumbered by the thought process"), a concurrency issue in the interpreter itself is my guess. Especially since I can't reproduce it at all on other versions.

I'll see if I can come up with a shorter, self-contained test that can illustrate the issue too.

[JorgeHerskovic]

Finally able to repro on my old Mac Pro at work (Universal 64/32bit 3.4.3 from python.org, OS X 10.10.3). For some reason I can't quite fathom, there were two exceptions this time.

Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/multiprocessing/util.py", line 286, in _exit_function
    _run_finalizers(0)
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/multiprocessing/util.py", line 246, in _run_finalizers
    items = [x for x in list(_finalizer_registry.items()) if f(x)]
RuntimeError: dictionary changed size during iteration
Exception ignored in: <Finalize object, dead>
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/multiprocessing/util.py", line 185, in __call__
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/multiprocessing/queues.py", line 207, in _finalize_close
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/threading.py", line 342, in notify
TypeError: 'NoneType' object is not callable

[JorgeHerskovic]

Ok, sorry, one more important thing I omitted in the previous comment.

^^^ The second exception above seems to be related to a new test I added, one that includes a daemonic process which itself relies on daemonic threads.

The cleanup of that seems to be FUBARed, and it makes the original exception much more likely to pop up as well.

[JorgeHerskovic]

Ok, I *think* I tracked it down to Connections getting cleaned up in a non-orderly fashion, sometimes while _run_finalizers is executing. The following patch to lib/python3.4/multiprocessing/connection.py cures the problem on my machine.

@@ -124,10 +124,10 @@
         self._handle = handle
         self._readable = readable
         self._writable = writable
-
+        self._shutdown = util.Finalize(self, self._finalizer)
     # XXX should we use util.Finalize instead of a __del__?
-
-    def __del__(self):
+
+    def _finalizer(self):
         if self._handle is not None:
             self._close()

[applio]

The 'crash' type is reserved for core dump type situations; 'behavior' is more appropriate for the misbehavior your describe.