interruption of locks by signals not guaranteed when locks are implemented using POSIX condition variables; add sys.thread_info

[sable]

BPO	11223
Nosy	@gpshead, @db3l, @pitrou, @vstinner, @benjaminp, @rnk
Files	test_threadsignals.patch pthread_cond_timedwait_signal.c threading_info.patch threading_info-2.patch threading_info-3.patch sys_thread_info.patch sys_thread_info-2.patch

^{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 2011-04-20.08:30:34.676>
created_at = <Date 2011-02-16.14:25:35.643>
labels = ['interpreter-core', 'type-bug', 'tests']
title = 'interruption of locks by signals not guaranteed when locks are implemented using POSIX condition variables; add sys.thread_info'
updated_at = <Date 2011-06-23.12:22:50.509>
user = 'https://bugs.python.org/sable'

bugs.python.org fields:

activity = <Date 2011-06-23.12:22:50.509>
actor = 'python-dev'
assignee = 'none'
closed = True
closed_date = <Date 2011-04-20.08:30:34.676>
closer = 'vstinner'
components = ['Interpreter Core', 'Tests']
creation = <Date 2011-02-16.14:25:35.643>
creator = 'sable'
dependencies = []
files = ['20772', '21714', '21716', '21724', '21734', '21744', '21786']
hgrepos = []
issue_num = 11223
keywords = ['patch']
message_count = 41.0
messages = ['128668', '128669', '128670', '128672', '128674', '128675', '128676', '128677', '128678', '128680', '128681', '128718', '128719', '128720', '128721', '128722', '128723', '130755', '134028', '134031', '134037', '134049', '134068', '134069', '134070', '134104', '134105', '134106', '134107', '134108', '134131', '134135', '134189', '134191', '134435', '134484', '134505', '134859', '138862', '138863', '138864']
nosy_count = 9.0
nosy_names = ['gregory.p.smith', 'db3l', 'pitrou', 'vstinner', 'sable', 'benjamin.peterson', 'rnk', 'neologix', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue11223'
versions = ['Python 3.2']

[sable]

The test test_lock_acquire_interruption in test_threadsignals.py will lock forever on AIX 5.3.
It works fine on 6.1.

truss shows it is stuck in thread_tsleep:
$ truss -p 1404986
thread_tsleep(0, 0x00000000, 0x00000000, 0x00000000) (sleeping...)

[pitrou]

We have the same issue on our FreeBSD 6.4 buildbot:
http://python.org/dev/buildbot/all/builders/x86%20FreeBSD%203.x/builds/1216/steps/test/logs/stdio
(FreeBSD 7.2 is fine)

Can you tell me what the values of _POSIX_SEMAPHORES and HAVE_SEM_TIMEDWAIT are (or whether they are undefined)?

[sable]

$ grep SEM pyconfig.h
#define HAVE_BROKEN_POSIX_SEMAPHORES 1
/* #undef HAVE_BROKEN_SEM_GETVALUE */
#define HAVE_SEM_GETVALUE 1
#define HAVE_SEM_OPEN 1
#define HAVE_SEM_TIMEDWAIT 1
#define HAVE_SEM_UNLINK 1
/* #undef POSIX_SEMAPHORES_NOT_ENABLED */
#ifndef _POSIX_PTHREAD_SEMANTICS
# define _POSIX_PTHREAD_SEMANTICS 1

[pitrou]

Ok, the problem is when the condition variable-based implementation is chosen in Python/thread_pthread.h.
It is actually reproduceable under Linux by adding #undef USE_SEMAPHORES just after #define USE_SEMAPHORES.
The problem is that, contrary to sem_timedwait(), pthread_cond_wait() doesn't have well-defined behaviour with signals. POSIX simply says:

“If a signal is delivered to a thread waiting for a condition variable, upon return from the signal handler the thread resumes waiting for the condition variable as if it was not interrupted, or it shall return zero due to spurious wakeup.”

So, on those OSes where the semaphore API can't be used, the test can succeed or not depending on how pthread_cond_wait() behaves in the face of signals. It would be better if it didn't hang, though.

(This is not a regression, by the way. Locks were totally uninterruptible under POSIX until 3.2, and the tests weren't there. The new tests were introduced in r87292 (see bpo-8844))

[pitrou]

Here is a patch that makes the test fail rather than hang. Sébastien, can you try it out?

[sable]

Thanks Antoine, the patch solved the problem.

I have other tests locking semi-randomly on AIX 5.3 and/or AIX 6.1, like test_socket and test_io. That may be related.

[pitrou]

I have other tests locking semi-randomly on AIX 5.3 and/or AIX 6.1,
like test_socket and test_io. That may be related.

Which test cases exactly?

[sable]

Well I don't know precisely:

• when running make buildbottest, test_socket will systematically hang on AIX 5.3 and 6.1.

• but when running ./python -Wd -E -bb Lib/test/test_socket.py, the tests complete rather quickly (with one failure cf 11192).

Ran 158 tests in 16.867s

FAILED (failures=1, skipped=4)

I will try with pdb or something.

[pitrou]

Well I don't know precisely:

• when running make buildbottest, test_socket will systematically hang
  on AIX 5.3 and 6.1.

• but when running ./python -Wd -E -bb Lib/test/test_socket.py, the
  tests complete rather quickly (with one failure cf 11192).

You can run the whole test suite in verbose mode. This will pollute your
terminal a lot, but you'll see exactly where it hangs.

Try something like "./python -E -bb -m test.regrtest -uall -v"

[vstinner]

I will try with pdb or something.

You can also try to attach gdb to the running process: with
python-gdb.py, you have nice py-* commands.

Or if you don't have gdb7, you may try my faulthandler module: you will
have to modify the source code (eg. Lib/test/regrtest.py) to add at the
top:

   import faulthandler, signal; faulthandler.register(signal.SIGUSR1)

Then you can display the current Python backtrace by sending a SIGUSR1
signal to the running Python process (eg. killall -USR1 python).

https://github.com/haypo/faulthandler/wiki

[sable]

test_socket didnot lock this time (I will retry next).

But test_subprocess.ProcessTestCasePOSIXPurePython.test_leaking_fds_on_error did.

Looping forever on the following syscall:

pipe(0x2FF1FD88) = 0
kfcntl(15, F_GETFD, 0x00000000) = 0
kfcntl(15, F_SETFD, 0x00000001) = 0
kfcntl(17, F_GETFD, 0x00000000) = 0
kfcntl(17, F_SETFD, 0x00000001) = 0
pipe(0x2FF1FD88) = 0
kfcntl(18, F_GETFD, 0x00000000) = 0
kfcntl(18, F_SETFD, 0x00000001) = 0
kfcntl(19, F_GETFD, 0x00000000) = 0
kfcntl(19, F_SETFD, 0x00000001) = 0
fstatx(15, 0x2FF1FAEC, 76, 0) = 0
kioctl(15, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
fstatx(15, 0x2FF1FD7C, 76, 0) = 0
lseek(15, 0, 1) Err#29 ESPIPE
fstatx(18, 0x2FF1FAEC, 76, 0) = 0
kioctl(18, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
fstatx(18, 0x2FF1FD7C, 76, 0) = 0
lseek(18, 0, 1) Err#29 ESPIPE
pipe(0x2FF1FD08) = 0
kfcntl(20, F_GETFD, 0x00000000) = 0
kfcntl(20, F_SETFD, 0x00000001) = 0
kfcntl(21, F_GETFD, 0x00000000) = 0
kfcntl(21, F_SETFD, 0x00000001) = 0
sigprocmask(0, 0xF029C148, 0xF029C150) = 0
kfork() = 2011158
thread_setmymask_fast(0x00000000, 0x00000000, 0x00000000, 0xD0504100, 0x00000000, 0x1216F00B, 0x1216F00B, 0x00000000) = 0x00000000
close(21) = 0
close(17) = 0
close(19) = 0
kread(20, " O S E r r o r : 2 :\0 i".., 50000) = 10
kread(20, 0x33041C38, 50000) = 0
close(20) = 0
kwaitpid(0x2FF1FB50, 2011158, 4, 0x00000000, 0x00000000) = 2011158
close(15) = 0
close(18) = 0
close(15) Err#9 EBADF
close(18) Err#9 EBADF
pipe(0x2FF1FD88) = 0