homepage

I have an example code that works fine on Python 2.6.3, but when run in
Python 3.1.1 - after a very short period of time, will go wrong.
Summary:
We have a queue, and when the queue has something in it (a list), we
start a thread to deal with that entry.
The thread then runs a Process for every entry in the list we popped off
the queue. The Process target takes a Pipe, and it sends "True" back
down the pipe, and then exits. However, this Process never goes defunct,
and thus the Thread that started the Process never reaps it. When doing
a truss on the Process, it sits there in:
lwp_park(0x00000000, 0) (sleeping...)

Further information: it doesn't fail everytime in Python 3.1 - usually 1
in 4, or 1 in 5 times. It never fails with Python 2.6.3
Example output from the script when its failing (python 3.1):
Starting data1
Starting data2
Started subproc: PID: 20209 : args: data1
poll
Started subproc: PID: 20210 : args: data2
poll
Child has sent:True
poll
Child has sent:True
poll
isalive: False
isalive: True
Reaping PID: 20210
isalive: True
poll
Finishing: data2
isalive: True
poll
isalive: True
poll
isalive: True
poll
isalive: True
poll
<repeat isalive and poll lines until>:
isalive: True
poll
isalive: True
terminating
Child had to be killed due to a timeout
Finishing: data1
True
Working output (consistantly works on Python 2.6.3):
Starting data1
Starting data2
Started subproc: PID: 20252 : args: data1
poll
Started subproc: PID: 20253 : args: data2
poll
Child has sent:True
Child has sent:True
poll
Child has sent:True
poll
isalive: False
isalive: False
isalive: False
Reaping PID: 20252
Reaping PID: 20253
Finishing: data1
Finishing: data2
True

Acccording to http://blogs.sun.com/chrisg/entry/lwp_park_and_lwp_unpark,
the lwp_park() call could point to a mutex which is waiting to be acquired.

Well, if it helps, here is the output of the dtrace script from starting
of a loop with the failure, and stopping during the failure.

Does it not happen if you call your checkAlive() function directly from
your main() function?

As for the dtrace output: I'm not a Solaris expert unfortunately, I was
just trying to suggest a possible direction for diagnosing this problem.

If you mean, in main() instead of doing:
while True:
 q.put(["data1", "data2"])
 t = Process(target=popJobs, args=(q, ))
 t.start()
 t.join()
and doing:
while True:
 q.put(["data1", "data2"])
 popJobs(q)
instead. Then, the bug does indeed occur the same way. It did take more
iterations before it occured however. 
If however, you meant:
while True:
 fail=failureObject()
 for x in ["data1", "data2"]:
 checkAlive(fail, x)
 print(fail.status())
Then the bug never occurs.

Same thing occurs, as you would expect, when I do:
while True:
 fail=failureObject()
 tlist = []
 for x in ["data1", "data2"]:
 t = threading.Thread(target=checkAlive, args = (fail, x), name=x)
 t.start()
 tlist.append(t)
 for x in tlist:
 t.join()

Further oddness:
When running the script (i've reduced its size further now, see attached):
I get the following output:
Reaping PID: 23215
True
Started subproc: PID: 23216 : args: data1
Started subproc: PID: 23216 : args: data1
Started subproc: PID: 23217 : args: data2
poll
isalive: True
isalive: True
poll
Notice the Started subprod of the SAME PID and the Same args twice, yet
this print only occurs once in the code, and I can't see how this should
happen?

> Notice the Started subprod of the SAME PID and the Same args twice, yet
> this print only occurs once in the code, and I can't see how this should
> happen?
This is a thread-safety issue in sys.stdout/stderr, it will be fixed in
3.1.2 (see issue6750).

Sorry for the spam on the updates :) - but, its the same thread printing
this out too. I changed the print line to:
curThread = threading.current_thread()
print("Started subproc: PID: %d : args: %s Thread ID: %s" %(newJob.pid,
str(args), str(curThread.ident)))
and got the output:
Reaping PID: 23707
True
Started subproc: PID: 23709 : args: data1 Thread ID: 12
Started subproc: PID: 23709 : args: data1 Thread ID: 12
poll
isalive: True
Started subproc: PID: 23710 : args: data2 Thread ID: 13
poll
isalive: True
Again, I can't see how this could pring it out twice? Could this be
related to the problem we are having? Altgough I do seem to get the line
twice on 2.6.3 as well - but nothing like as often..

Tested on Linux, and repeated the issue - just to confirm this isn't a
Solaris specific issue.
Tested using dummy_threading - bug does not appear when that is used.
Added _verbose=True to threads, and log_to_stderr(SUBDEBUG) set for Process.
Attached is the output of the script with those set. 
Other odd things to notice, and some point, more than 2 children
sometimes exist.. 
isalive PID: 7646 : True
isalive PID: 7652 : True
isalive PID: 7653 : True
isalive PID: 7646 : True
isalive PID: 7652 : True
isalive PID: 7653 : True
isalive PID: 7646 : True
isalive PID: 7653 : True
The code starts 2 threads, which start 2 processes. Both threads are
joined before new ones are started.. So, in theroy, only 2 should be
able to exist at once.. ?

I am pretty sure this is another instance of issue 6721.
multiprocessing is forking a new process and if that happens while the other thread is holding the lock for stdout, the process will deadlock because the lock state is replicated in the subprocess while the thread that is supposed unlock it isn't (even if you remove all prints, the deadlock will happen on a stdout flush).
Attaching a gdb to a hung subprocess confirms that it is waiting for a lock in the bufferedio module.
I've reproduced this on Python trunk running on Linux (using pthreads) and can confirm that the patch attached to issue 6721 fixes it.
I'm also attaching a shorter test case that omits unused code from the original example.

> I am pretty sure this is another instance of issue 6721.
Indeed.
Closing as duplicate.