multiprocessing module is racy

[donmez]

BPO	3419
Nosy	@mdickinson, @benjaminp
Files	multibug3.py: script demonstrating incref bug mp_nohang_jnoller.patch issue3419.patch: Possible fix for incref bug

^{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 2008-09-02.18:15:48.186>
created_at = <Date 2008-07-19.20:00:42.032>
labels = ['tests', 'release-blocker']
title = 'multiprocessing module is racy'
updated_at = <Date 2008-09-02.19:12:48.187>
user = 'https://bugs.python.org/donmez'

bugs.python.org fields:

activity = <Date 2008-09-02.19:12:48.187>
actor = 'jnoller'
assignee = 'jnoller'
closed = True
closed_date = <Date 2008-09-02.18:15:48.186>
closer = 'jnoller'
components = ['Tests']
creation = <Date 2008-07-19.20:00:42.032>
creator = 'donmez'
dependencies = []
files = ['11075', '11100', '11138']
hgrepos = []
issue_num = 3419
keywords = ['patch', 'needs review']
message_count = 23.0
messages = ['70053', '70056', '70060', '70539', '70570', '70603', '70608', '70609', '70631', '70632', '70803', '70809', '70857', '70859', '70860', '71026', '71030', '71031', '71068', '71273', '71275', '72358', '72361']
nosy_count = 5.0
nosy_names = ['mark.dickinson', 'donmez', 'roudkerk', 'benjamin.peterson', 'jnoller']
pr_nums = []
priority = 'release blocker'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue3419'
versions = ['Python 2.6', 'Python 3.0']

[donmez]

Tested on MacOSX 10.5.4, running test_multiprocessing in a tight loop :

[~/Sources/py3k]> while true;do ./python ./Lib/test/regrtest.py 
test_multiprocessing;done
test_multiprocessing
1 test OK.
test_multiprocessing
1 test OK.
test_multiprocessing
1 test OK.
test_multiprocessing
Process Process-48:
Traceback (most recent call last):
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/managers.py", 
line 720, in _callmethod
    conn = self._tls.connection
AttributeError: 'ForkAwareLocal' object has no attribute 'connection'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/process.py", 
line 232, in _bootstrap
    self.run()
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/process.py", 
line 88, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/cartman/Sources/py3k/Lib/test/test_multiprocessing.py", 
line 601, in f
    cond.acquire()
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/managers.py", 
line 949, in acquire
    return self._callmethod('acquire', (blocking,))
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/managers.py", 
line 724, in _callmethod
    self._connect()
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/managers.py", 
line 711, in _connect
    conn = self._Client(self._token.address, authkey=self._authkey)
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/connection.py", 
line 133, in Client
    c = SocketClient(address)
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/connection.py", 
line 254, in SocketClient
    s.connect(address)
socket.error: [Errno 61] Connection refused
Exception in thread Thread-58:
Traceback (most recent call last):
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/managers.py", 
line 720, in _callmethod
    conn = self._tls.connection
AttributeError: 'ForkAwareLocal' object has no attribute 'connection'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/cartman/Sources/py3k/Lib/threading.py", line 492, in 
_bootstrap_inner
    self.run()
  File "/Users/cartman/Sources/py3k/Lib/threading.py", line 447, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/cartman/Sources/py3k/Lib/test/test_multiprocessing.py", 
line 601, in f
    cond.acquire()
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/managers.py", 
line 949, in acquire
    return self._callmethod('acquire', (blocking,))
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/managers.py", 
line 724, in _callmethod
    self._connect()
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/managers.py", 
line 711, in _connect
    conn = self._Client(self._token.address, authkey=self._authkey)
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/connection.py", 
line 133, in Client
    c = SocketClient(address)
  File "/Users/cartman/Sources/py3k/Lib/multiprocessing/connection.py", 
line 254, in SocketClient
    s.connect(address)
socket.error: [Errno 61] Connection refused

[benjaminp]

When running test_multiprocessing in a loop, I see:

test test_multiprocessing failed -- Traceback (most recent call last):
  File "/temp/python/trunk/Lib/test/test_multiprocessing.py", line 1157,
in test_remote
    queue = manager2.get_queue()
  File "/temp/python/trunk/Lib/multiprocessing/managers.py", line 635,
in temp
    authkey=self._authkey, exposed=exp
  File "/temp/python/trunk/Lib/multiprocessing/managers.py", line 887,
in AutoProxy
    incref=incref)
  File "/temp/python/trunk/Lib/multiprocessing/managers.py", line 696,
in __init__
    self._incref()
  File "/temp/python/trunk/Lib/multiprocessing/managers.py", line 743,
in _incref
    dispatch(conn, None, 'incref', (self._id,))
  File "/temp/python/trunk/Lib/multiprocessing/managers.py", line 79, in
dispatch
    raise convert_to_error(kind, result)
RemoteError: 
---------------------------------------------------------------------------
Traceback (most recent call last):
  File "/temp/python/trunk/Lib/multiprocessing/managers.py", line 181,
in handle_request
    result = func(c, *args, **kwds)
  File "/temp/python/trunk/Lib/multiprocessing/managers.py", line 397,
in incref
    self.id_to_refcount[ident] += 1
KeyError: '1033760'

---

[jnoller]

This also happens under trunk

[jnoller]

Ben's incref error != the connection refused error. Here's some information
from Scott Leerssen who is using the original .52 code:

Hi Jesse,

I am having some trouble with the processing module (0.52) and thought you
might be of some help since you were so involved with it in the PEP process.

I have a queue of Process objects from which a runner thread pulls and starts
processes. The producers for the queue are many, many threads. I'm seeing
some very odd behavior when lots of processes try to start while others are
being reaped at the same time. I see tracebacks that look like the one below,
and also occasionally get "hangs" where the process module "seems" to take over
the GIL and never give it back. I did find a race condition bug in process.py
where a _cleaner function is run in start(), potentially joining on processes
that other threads may also be joining at the same time, which leads to
KeyError exceptions coming from _cleaner. I mutexed all my starts and joins to
get around that for now, but am stumped on the issue below. Does it look
familiar to you?

Thanks, and feel free to shrug and reply "beats me".
Scott

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,609 SYSMESG Process Process-24:
[dmbd:32451:-1236096096] 2008-07-31 16:52:10,612 SYSMESG

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,613 SYSMESG Traceback (most
recent call last):

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,613 SYSMESG File
"/opt/race/share/sw/os/Linux_2.6_i686/python/lib/python2.5/site-
packages/processing/process.py", line 224, in _bootstrap

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,615 SYSMESG
_runAfterForkers()

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,616 SYSMESG File
"/opt/race/share/sw/os/Linux_2.6_i686/python/lib/python2.5/site-
packages/processing/process.py", line 300, in _runAfterForkers

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,617 SYSMESG func(obj)

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,617 SYSMESG File
"/opt/race/share/sw/os/Linux_2.6_i686/python/lib/python2.5/site-
packages/processing/managers.py", line 806, in _afterFork

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,620 SYSMESG self._incref()

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,621 SYSMESG File
"/opt/race/share/sw/os/Linux_2.6_i686/python/lib/python2.5/site-
packages/processing/managers.py", line 760, in _incref

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,621 SYSMESG
dispatch(connection, None, 'incref', (self._id,))

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,622 SYSMESG File
"/opt/race/share/sw/os/Linux_2.6_i686/python/lib/python2.5/site-
packages/processing/managers.py", line 92, in dispatch

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,623 SYSMESG raise result

[dmbd:32451:-1236096096] 2008-07-31 16:52:10,624 SYSMESG RemoteError:
---------------------------------------------------------------------------

Remote Traceback (most recent call last):
 File "/opt/race/share/sw/os/Linux_2.6_i686/python/lib/python2.5/site-
packages/processing/managers.py", line 190, in handleRequest
   result = func(c, *args, **kwds)
 File "/opt/race/share/sw/os/Linux_2.6_i686/python/lib/python2.5/site-
packages/processing/managers.py", line 404, in incref
   self.id_to_refcount[ident] += 1
KeyError: 2880341100L

[mdickinson]

I'm also seeing the incref error occasionally, on OS X 10.5.4:

======================================================================
ERROR: test_remote (main.WithManagerTestRemoteManager)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "Lib/test/test_multiprocessing.py", line 1157, in test_remote
    queue = manager2.get_queue()
  File "/Users/dickinsm/python_source/trunk/Lib/multiprocessing/managers.py", line 635, in temp
    authkey=self._authkey, exposed=exp
  File "/Users/dickinsm/python_source/trunk/Lib/multiprocessing/managers.py", line 887, in AutoProxy
    incref=incref)
  File "/Users/dickinsm/python_source/trunk/Lib/multiprocessing/managers.py", line 696, in __init__
    self._incref()
  File "/Users/dickinsm/python_source/trunk/Lib/multiprocessing/managers.py", line 743, in _incref
    dispatch(conn, None, 'incref', (self._id,))
  File "/Users/dickinsm/python_source/trunk/Lib/multiprocessing/managers.py", line 79, in dispatch
    raise convert_to_error(kind, result)
RemoteError: 
---------------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/dickinsm/python_source/trunk/Lib/multiprocessing/managers.py", line 181, in handle_request
    result = func(c, *args, **kwds)
  File "/Users/dickinsm/python_source/trunk/Lib/multiprocessing/managers.py", line 397, in incref
    self.id_to_refcount[ident] += 1
KeyError: '6fdb78'

---

[mdickinson]

For the connection refused error, the following script fails for me
(again, on OS X 10.5.4) with the message:

errno: [Errno 61] Connection refused

on most runs. (If xrange(10) is replaced by a smaller range like
xrange(4) then the script usually runs without error.) Looks like
something in semaphore.c needs fixing, but I've no idea what.

from multiprocessing import Process, Manager
sleeping = Manager().Semaphore(0)

def f():
    sleeping.release()

for _ in xrange(10):
    Process(target=f).start()
for _ in xrange(10):
    sleeping.acquire()

[mdickinson]

Looks like something in semaphore.c needs fixing, but I've no idea what.

I take that back. It's nothing to do with semaphore.c. I'll keep trying.

[jnoller]

Are you looking at the conn refused or the incref error?

[mdickinson]

Are you looking at the conn refused or the incref error?

The connection refused error.

The attached patch fixes the problem, for me. On my machine, the
connection refused error code was 61 rather than 10061. With this patch,
I'm no longer seeing any hangs in test_multiprocessing.py (at least, not in
the last 500 runs :-)). (Though I am still seeing the incref error
occasionally.)

If anyone's prepared to answer a stupid question: I'm curious why failed
socket connections occur at all. Is connecting to a socket generally
considered an unreliable operation, or is there some aspect of the
multiprocessing module that makes it potentially unreliable?

[jnoller]

On Aug 2, 2008, at 9:44 AM, Mark Dickinson <report@bugs.python.org>
wrote:

Mark Dickinson <dickinsm@gmail.com> added the comment:

> Are you looking at the conn refused or the incref error?

The connection refused error.

The attached patch fixes the problem, for me. On my machine, the
connection refused error code was 61 rather than 10061. With this
patch,
I'm no longer seeing any hangs in test_multiprocessing.py (at least,
not in
the last 500 runs :-)). (Though I am still seeing the incref error
occasionally.)

If anyone's prepared to answer a stupid question: I'm curious why
failed
socket connections occur at all. Is connecting to a socket generally
considered an unreliable operation, or is there some aspect of the
multiprocessing module that makes it potentially unreliable?

I believe the conn refused error is another race, the child processes
are connecting to a manager which is shutting down/gone

Thanks again mark- when I get a chance today I'll review/test/apply
the patch

[mdickinson]

I believe the conn refused error is another race, the child processes
are connecting to a manager which is shutting down/gone

After some research, I think it actually has to do with the value of the
'backlog' parameter when creating a Listener instance: if there are too
many queued requests to a socket then further connection requests are
refused; the 'backlog' parameter appears to set the maximum size of the
queue.

...or something like that. I'm a novice here... :-)

Anyway, in the __init__ method of the Server class, in managers.py, the
Server creates a Listener instance with the line

        self.listener = Listener(address=address, backlog=5)

When I change backlog to 50 instead of 5, I don't see the connection
refused error any more.

I'm not suggesting that the backlog value should be changed---it
probably shouldn't. But this does at least explain why connections can
be refused, and why they should be retried in that case.

I do still think that the patch, or something like it, should be
applied.

[mdickinson]

Here's what's going on with the incref error:

Look in the Server class, in managers.py: consider a shared object with
id 'id'. When a reference to the shared object is created, its id is
added to the id_to_refcount dictionary:

{id: None}

and *shortly afterwards*, the refcount is incremented to get:

{id: 1}

When the object is deleted or goes out of scope later on, the refcount
is decref'd, and id is removed entirely from id_to_refcount.

The problem occurs when there are two processes simultaneously asking
for access to the same object. If a second process happens to decref
'id' in between the first process creating the reference and
incrementing it, then the incref from the first process will fail. This
is exactly what's happening (some of the time) in test_remote in the
test_suite. The failing sequence of operations is:

initial state: id not in id_to_refcount
(process 1): create id_to_refcount[id] is None
(process 1): incref id_to_refcount[id] == 1
(process 2): create id_to_refcount[id] == 1
(process 1): decref id not in id_to_refcount
(process 2): incref KeyError!
(process 2): decref (never get here...)

I'm not really familiar enough with the whole multiprocessing module to
know what the right fix for this is.

[mdickinson]

Hmmm. That last message wasn't too coherent; I really shouldn't try to
post at 2:30am.

Summary: the refcounting logic in the Server class is flawed. In
Server.create(), the initial refcount of a newly-created shared object is
set to None. This is dangerous: the moment another thread gets a look-in,
that refcount can be incremented to 1, then decremented to 0, at which
point the shared object gets disposed of (by the code in Server.decref).
And all this can happen before the Proxy object for the shared object gets
initialized, at which point the KeyError occurs.

(Not much better.)

Can anyone suggest a way to fix this? I can't see any easy fix.
Nevertheless, I consider this a serious flaw that should be fixed before
2.6 and 3.0 are released.

I've attached a minimal file that produces the incref error (on about 1
run out of every 5) for me.