classification
Title: 2.6rc1: test_threading hangs on FreeBSD 6.3 i386
Type: crash Stage:
Components: Extension Modules Versions: Python 2.5.3, Python 2.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: gregory.p.smith Nosy List: aimacintyre, bms, gregory.p.smith, jnoller, loewis, ocean-city, pitrou
Priority: release blocker Keywords: patch

Created on 2008-09-14 11:25 by aimacintyre, last changed 2009-03-12 15:46 by bms. This issue is now closed.

Files
File name Uploaded Description Edit
fbsd_thr_crash.py gregory.p.smith, 2008-09-15 04:49
test_threading_fbsd6.py.patch aimacintyre, 2008-09-15 13:18 patch: skip fork() from worker thread on FreeBSD 6.x and earlier
Messages (19)
msg73210 - (view) Author: Andrew I MacIntyre (aimacintyre) * Date: 2008-09-14 11:25
sources: 2.6rc1 tarball
system: FreeBSD 6.3 i386, gcc 3.4.6 (system compiler)
build:  ./configure; make

it makes no difference whether test_threading is run as part of make test 
or on its own - process suspends and has to be killed (I left one run the 
best part of an hour with no progress).

a log from a verbose run:
andymac@bullseye$ ./python -E -tt Lib/test/regrtest.py -v test_threading
>logfile 2>&1
test_threading
test_PyThreadState_SetAsyncExc (test.test_threading.ThreadTests) ...   
 started worker thread
    trying nonsensical thread id
    waiting for worker thread to get started
    verifying worker hasn't exited
    attempting to raise asynch exception in worker
    waiting for worker to say it caught the exception
    all OK -- joining worker
ok
test_enumerate_after_join (test.test_threading.ThreadTests) ... ok
test_finalize_runnning_thread (test.test_threading.ThreadTests) ... ok
test_finalize_with_trace (test.test_threading.ThreadTests) ... ok
test_foreign_thread (test.test_threading.ThreadTests) ... ok
test_no_refcycle_through_target (test.test_threading.ThreadTests) ... ok
test_various_ops (test.test_threading.ThreadTests) ... task <thread 0>
will run for 26.0 usec
1 tasks are running
task <thread 1> will run for 25.7 usec
2 tasks are running
task <thread 2> will run for 28.9 usec
3 tasks are running
task <thread 3> will run for 47.1 usec
task <thread 4> will run for 19.8 usec
task <thread 5> will run for 10.0 usec
task <thread 6> will run for 25.4 usec
task <thread 7> will run for 55.5 usectasktask <thread 1> done
<thread 1> is finished. 2 tasks are running

  task <thread 2> done
<thread 2> is finished. 1 tasks are running
2 tasks are running
<thread 0> done
<thread 0> is finished. 1 tasks are running
task <thread 8> will run for 61.3 usec
2 tasks are running
3 tasks are running
task <thread 9> will run for 53.1 usec
waiting for all tasks to complete
task <thread 3> done
<thread 3> is finished. 2 tasks are running
task <thread 4> done
<thread 4> is finished. 1 tasks are running
2 tasks are running
3 tasks are running
task <thread 8> done
<thread 8> is finished. 2 tasks are running
3 tasks are running
task <thread 7> done
<thread 7> is finished. 2 tasks are running
task <thread 6> done
<thread 6> is finished. 1 tasks are running
2 tasks are running
task <thread 5> done
<thread 5> is finished. 1 tasks are running
task <thread 9> done
<thread 9> is finished. 0 tasks are running
all tasks done
ok
test_various_ops_large_stack (test.test_threading.ThreadTests) ... with
1MB thread stack size...
task <thread 0> will run for 96.9 usec
1 tasks are running
task <thread 1> will run for 99.4 usec
2 tasks are running
task <thread 2> will run for 0.8 usec
3 tasks are running
task <thread 2> done
<thread 2> is finished. 2 tasks are running
task <thread 3> will run for 89.1 usec
3 tasks are running
task <thread 4> will run for 46.8 usec
task <thread 5> will run for 13.2 usec
task <thread 6> will run for 23.8 usec
tasktask <thread 0> done
<thread 0> is finished. 2 tasks are running
task <thread 7> will run for 41.6 usec 
<thread 1> done
<thread 1> is finished. 1 tasks are running
2 tasks are running
3task <thread 8> will run for 55.8 usec
 tasks are running
waiting for all tasks to complete
task <thread 3> done
<thread 3> is finished. 2 tasks are running
task <thread 9> will run for 53.2 usec 3 tasks are running

task <thread 4> done
<thread 4> is finished. 2 tasks are running
task <thread 5> done
<thread 5> is finished. 1 tasks are running
2 tasks are running
3 tasks are running
task <thread 6> done
<thread 6> is finished. 2 tasks are running
3 tasks are running
task <thread 7> done
<thread 7> is finished. 2 tasks are running
task <thread 8> done
<thread 8> is finished. 1 tasks are running
task <thread 9> done
<thread 9> is finished. 0 tasks are running
all tasks done
ok
test_various_ops_small_stack (test.test_threading.ThreadTests) ... with
256kB thread stack size...
task <thread 0> will run for 54.5 usec
1 tasks are running
task <thread 1> will run for 5.2 usec
2 tasks are running
task <thread 2> will run for 2.1 usec
3 tasks are running
task <thread 3> will run for 40.5 usec
task <thread 4> will run for 55.9 usec
task <thread 5> will run for 77.1 usec
task <thread 6> will run for 82.4 usec
task <thread 0> done
<thread 0> is finished. 2 tasks are running
task <thread 1> done
<thread 1> is finished. 1 tasks are running
2 tasks are running
task <thread 7> will run for 100.0 usec
task <thread 8> will run for 64.5 usec
3 tasks are running
waiting for all tasks to complete
task <thread 2> done
<thread 2> is finished. 2 tasks are running
3 tasks are running
task <thread 9> will run for 76.7 usec
task <thread 3> done
<thread 3> is finished. 2 tasks are running
task <thread 4> done
<thread 4> is finished. 1 tasks are running
2 tasks are running
3 tasks are running
task <thread 5> done
<thread 5> is finished. 2 tasks are running
3 tasks are running
task <thread 7> done
<thread 7> is finished. 2 tasks are running
task <thread 6> done
<thread 6> is finished. 1 tasks are running
2 tasks are running
task <thread 8> done
<thread 8> is finished. 1 tasks are running
task <thread 9> done
<thread 9> is finished. 0 tasks are running
all tasks done
ok
test_1_join_on_shutdown (test.test_threading.ThreadJoinOnShutdown) ... ok
test_2_join_in_forked_process (test.test_threading.ThreadJoinOnShutdown)
... ok
test_3_join_in_forked_from_thread
(test.test_threading.ThreadJoinOnShutdown) ... Fatal error 'mutex is on
list' at line 540 in file /usr/src/lib/libpthread/thread/thr_mutex.c
(errno = 0)

Exception in thread Thread-1:
Traceback (most recent call last):
  File "/home/andymac/build/Python-2.6rc1/Lib/threading.py", line 522,
in __bootstrap_inner
    self.run()
  File "/home/andymac/build/Python-2.6rc1/Lib/threading.py", line 477,
in run
    self.__target(*self.__args, **self.__kwargs)
  File "<string>", line 14, in worker
OSError: [Errno 4] Interrupted system call

Exception KeyboardInterrupt in <module 'threading' from
'/home/andymac/build/Python-2.6rc1/Lib/threading.pyc'> ignored
msg73211 - (view) Author: Andrew I MacIntyre (aimacintyre) * Date: 2008-09-14 11:32
I should add that this is a regression of the trunk, as I built and
tested the trunk from an SVN checkout (r63892) in early June and didn't
encounter this issue.
msg73242 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2008-09-14 23:47
I also see this in release25-maint's test_threading
test_2_join_in_forked_process.

This is likely related to the fixes for issue #874900 but i'm not sure
yet if this is a new problem or just one thats been there for a while
and exposed by the new tests added for that issue.

(also fyi - I used a premade barebones FreeBSD 6.3 VMWare image from
http://www.thoughtpolice.co.uk/vmware/ to reproduce it here)
msg73243 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2008-09-15 00:00
and as expected, also happens with py3k.
msg73244 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2008-09-15 00:23
fyi the FreeBSD 6.3 libpthread PANIC message comes from the
MUTEX_ASSERT_NOT_OWNED macro which is called from several places here:

http://www.freebsd.org/cgi/cvsweb.cgi/src/lib/libpthread/thread/Attic/thr_mutex.c?rev=1.52;content-type=text%2Fx-cvsweb-markup;hideattic=0
msg73246 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2008-09-15 04:49
attaching a stand alone script to exercise the bug.  based on the
prints, the error appears to happen during the t.start() call to launch
the joiningfunc() thread from the child processes worker thread (its the
main/only thread in the child process so far).
msg73247 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2008-09-15 05:44
instrumenting Python/thread_pthread.h and turning on thread debugging in
Python/thread.c, FreeBSD raises the Fatal error within pthread_create().

I'm inclined to say that this is a FreeBSD 6.3 bug.  The
fbsd_thr_crash.py test case is a good way to reproduce the problem.  I'd
imagine a similar bit of C code could be written.

What should we do in Python for this?  Just disable this unit test on
FreeBSD?
msg73254 - (view) Author: Andrew I MacIntyre (aimacintyre) * Date: 2008-09-15 10:44
I've briefly got a FreeBSD 7.0 amd64 setup available, and test_threading
passes in this environment.

Short term fix I'd suggest is to only disable this part of the test for
FreeBSD 6.x and earlier (ie platforms freebsd4, freebsd5, freebsd6).

I also checked my OS/2 EMX build and wasn't surprised to see it fail on
the same part of test_threading - fork() on OS/2 EMX is fragile enough
without threads in the mix.

If a disabler is added for FreeBSD as above, 'os2emx' should be in the
same list.
msg73258 - (view) Author: Andrew I MacIntyre (aimacintyre) * Date: 2008-09-15 12:48
test_threading also passes on FreeBSD 7.0 i386.
msg73260 - (view) Author: Andrew I MacIntyre (aimacintyre) * Date: 2008-09-15 13:18
I've attached a simple patch which deactivates
test_3_join_in_forked_from_thread on FreeBSD 6.x and earlier, and also
OS/2 EMX.  With this patch, test_threading completes but...

$ ./python -E -tt Lib/test/regrtest.py test_threading
test_threading
1 test OK.
Unhandled exception in thread started by
Error in sys.excepthook:

Original exception was:
msg74074 - (view) Author: Andrew I MacIntyre (aimacintyre) * Date: 2008-09-30 13:16
I believe this issue ties into the underlying problem FreeBSD 6.x upto
and including 6.3R have with fork() in a threaded application - see the
6.3R errata notice referenced in issue3864.

The issue should be fixed in FreeBSD 6.4 (currently in beta), but it
would be nice to get the patch in to Python 2.6 and Python 3.0 (not sure
about 2.5) just so that running the test doesn't hang on earlier 6.x
releases.
msg74079 - (view) Author: Hirokazu Yamamoto (ocean-city) * (Python committer) Date: 2008-09-30 14:58
Cygwin1.5 also hangs on test_3_join_in_forked_from_thread.
Cygwin1.7 + following snapshot doesn't hang but
http://cygwin.com/snapshots/cygwin1-20080929.dll.bz2
fails with following message.

======================================================================
FAIL: test_3_join_in_forked_from_thread (__main__.ThreadJoinOnShutdown)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "Lib/test/test_threading.py", line 400, in
test_3_join_in_forked_from_thr
ead
    self._run_and_join(script)
  File "Lib/test/test_threading.py", line 342, in _run_and_join
    self.assertEqual(data, "end of main\nend of thread\n")
AssertionError: '' != 'end of main\nend of thread\n'

If stdout is unbuffered mode,
$ export PYTHONUNBUFFERED=x
test passes.
msg74098 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2008-09-30 20:43
r66703 in trunk (2.6) applies the test_threading_fbsd6.py.patch modified
to also print a note to stderr when skipping the test and adds a mention
of buggy OSes in the os.fork documentation.

still needs merging over to 3.0 and possibly 2.5.
msg74099 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2008-09-30 20:45
marking release blocker for 3.0, the patch just needs to be merged after
it runs through any existing trunk freebsd buildbot(s).
msg74693 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2008-10-13 19:21
Apparently this can be merged in py3k. 

(in
http://www.python.org/dev/buildbot/trunk/x86%20FreeBSD%20trunk/builds/1589/step-test/0
:

[...]
test_threading
[18218 refs]
[18576 refs]
[17539 refs]
[17539 refs]
[17539 refs]
Skipping test_3_join_in_forked_from_thread due to known OS bugs on freebsd6
[...])
msg74745 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2008-10-14 14:49
looks like it already has been merged in py3k.
msg74753 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2008-10-14 16:13
Ok, so it's not a release blocker anymore :)
msg77735 - (view) Author: Martin v. Löwis (loewis) * (Python committer) Date: 2008-12-13 14:43
Backported to 2.5 as r67734.
msg83494 - (view) Author: (bms) Date: 2009-03-12 15:46
Hi,

I've committed a fix to FreeBSD-CURRENT for POSIX semaphores this morning.

Root cause analysis on the fork-mt issue points towards the rtld and
malloc in RELENG_7 not being able to deal with a mixture of fork and mt.

As a workaround, you may wish to try my patches against the FreeBSD port
to build with GNU Pth (until we can settle on resolution):-
http://people.freebsd.org/~bms/dump/python26-fbsd-pth.patch

thanks!
BMS
History
Date User Action Args
2009-03-12 15:46:49bmssetnosy: + bms
messages: + msg83494
2008-12-13 14:43:14loewissetstatus: open -> closed
nosy: + loewis
resolution: fixed
messages: + msg77735
2008-12-10 09:15:33loewissetpriority: high -> release blocker
2008-10-14 16:13:35pitrousetpriority: release blocker -> high
messages: + msg74753
2008-10-14 14:49:05gregory.p.smithsetmessages: + msg74745
versions: + Python 2.5.3, - Python 3.0
2008-10-13 19:21:12pitrousetmessages: + msg74693
2008-10-02 12:56:36barrysetpriority: deferred blocker -> release blocker
2008-10-01 11:23:29loewissetpriority: release blocker -> deferred blocker
2008-09-30 20:45:04gregory.p.smithsetpriority: normal -> release blocker
messages: + msg74099
2008-09-30 20:43:25gregory.p.smithsetassignee: gregory.p.smith
messages: + msg74098
versions: - Python 2.6
2008-09-30 14:58:46ocean-citysetnosy: + ocean-city
messages: + msg74079
2008-09-30 13:16:33aimacintyresetmessages: + msg74074
2008-09-15 13:18:12aimacintyresetfiles: + test_threading_fbsd6.py.patch
keywords: + patch
messages: + msg73260
2008-09-15 12:48:04aimacintyresetmessages: + msg73258
2008-09-15 10:44:10aimacintyresetmessages: + msg73254
2008-09-15 05:44:24gregory.p.smithsetpriority: high -> normal
messages: + msg73247
2008-09-15 04:49:29gregory.p.smithsetfiles: + fbsd_thr_crash.py
messages: + msg73246
2008-09-15 00:23:31gregory.p.smithsetmessages: + msg73244
2008-09-15 00:01:00gregory.p.smithsetmessages: + msg73243
versions: + Python 3.0
2008-09-14 23:49:48gregory.p.smithsetpriority: high
type: crash
components: + Extension Modules
versions: + Python 2.5
2008-09-14 23:47:59gregory.p.smithsetnosy: + pitrou, jnoller
messages: + msg73242
2008-09-14 20:59:45gregory.p.smithsetnosy: + gregory.p.smith
2008-09-14 11:32:00aimacintyresetmessages: + msg73211
2008-09-14 11:25:09aimacintyrecreate