The following program is misbehaving with python3.2

 import signal, time

 def sighandler( arg1, arg2): print("got sigint");    assert 0

 signal.signal( signal.SIGINT, sighandler)

 for i in range(1000000):
    print(i)

I'd expect Ctrl-C to terminate the program with AssertionError and that's indeed what happens under python2.7.

But with python3.2a, I get "Assertion Error" 1 out ~10 times. The other 9 times, the program locks up (goes to sleep? ps shows process status as "S"). After the program locks up, it does not respond to subsequent "Ctrl-C" presses.

This is on 64-bit Ubuntu 8.04.

I reproduce the problem, see the call stack below.
The issue is in the io module: the function _bufferedwriter_flush_unlocked() runs with the file mutex already acquired, but it calls PyErr_CheckSignals() which may run any code, including flush() on the same file...

In Modules/_io/buffereredio.c, the two callers to PyErr_CheckSignals() should ensure that 'self' is in a stable state, and release the lock while they run PyErr_CheckSignals().


#0  sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
#1  0x000000000049ac7d in PyThread_acquire_lock_timed (lock=0x21e24d0,
    microseconds=-1) at Python/thread_pthread.h:338
#2  0x00000000004c6486 in bufferedwriter_write (self=0x7f02b649d730,
    args=<value optimized out>) at ./Modules/_io/bufferedio.c:1751
#3  0x00000000004d8e29 in PyObject_Call (func=
    <built-in method write of _io.BufferedWriter object at remote 0x7f02b649d730>, arg=<unknown at remote 0x80>, kw=<value optimized out>)
    at Objects/abstract.c:2149
#4  0x00000000004db093 in PyObject_CallMethodObjArgs (callable=
    <built-in method write of _io.BufferedWriter object at remote 0x7f02b649d730>, name=<value optimized out>) at Objects/abstract.c:2350
#5  0x00000000004c9870 in _textiowrapper_writeflush (self=0x7f02b64a9530)
    at ./Modules/_io/textio.c:1237
#6  0x00000000004ca3be in textiowrapper_write (self=0x7f02b64a9530,
    args=<value optimized out>) at ./Modules/_io/textio.c:1318
#7  0x00000000004d81b7 in PyObject_Call (func=
    <built-in method write of _io.TextIOWrapper object at remote 0x7f02b64a9530>, arg=<unknown at remote 0x80>, kw=0x0) at Objects/abstract.c:2149
#8  0x000000000045e843 in PyEval_CallObjectWithKeywords (func=
    <built-in method write of _io.TextIOWrapper object at remote 0x7f02b64a9530>, arg=('\n',), kw=0x0) at Python/ceval.c:3754
#9  0x00000000004fb696 in PyFile_WriteObject (v=<value optimized out>,
    f=<value optimized out>, flags=<value optimized out>)
    at Objects/fileobject.c:156
#10 0x00000000004fb860 in PyFile_WriteString (s=<value optimized out>, f=
    <_io.TextIOWrapper at remote 0x7f02b64a9530>) at Objects/fileobject.c:181
#11 0x000000000045c49b in builtin_print (self=<value optimized out>, args=
    ('got sigint',), kwds=<value optimized out>) at Python/bltinmodule.c:1510
#12 0x0000000000465ded in call_function (f=
    Frame 0x22f28b0, for file <stdin>, line 1, in sighandler (arg1=2, arg2=Frame 0x22de7f0, for file <stdin>, line 2, in <module> ()),
    throwflag=<value optimized out>) at Python/ceval.c:3874
#13 PyEval_EvalFrameEx (f=
    Frame 0x22f28b0, for file <stdin>, line 1, in sighandler (arg1=2, arg2=Frame 0x22de7f0, for file <stdin>, line 2, in <module> ()),
    throwflag=<value optimized out>) at Python/ceval.c:2673
#14 0x0000000000466ee5 in PyEval_EvalCodeEx (co=0x7f02b5770cf0,
    globals=<value optimized out>, locals=<value optimized out>, args=0x2,
    argcount=<value optimized out>, kws=<value optimized out>, kwcount=0,
    defs=0x0, defcount=0, kwdefs=0x0, closure=0x0) at Python/ceval.c:3310
#15 0x00000000005027f4 in function_call (func=
    <function at remote 0x7f02b52e71e8>, arg=
    (2, Frame 0x22de7f0, for file <stdin>, line 2, in <module> ()), kw=0x0)
    at Objects/funcobject.c:630
#16 0x00000000004d81b7 in PyObject_Call (func=
    <function at remote 0x7f02b52e71e8>, arg=<unknown at remote 0x80>, kw=0x0)
    at Objects/abstract.c:2149
#17 0x000000000045e843 in PyEval_CallObjectWithKeywords (func=
    <function at remote 0x7f02b52e71e8>, arg=
    (2, Frame 0x22de7f0, for file <stdin>, line 2, in <module> ()), kw=0x0)
    at Python/ceval.c:3754
#18 0x00000000004a04cf in PyErr_CheckSignals ()
    at ./Modules/signalmodule.c:929
#19 0x00000000004c56cd in _bufferedwriter_flush_unlocked (self=
    0x7f02b649d730, restore_pos=0) at ./Modules/_io/bufferedio.c:1709
#20 0x00000000004c5b3e in buffered_flush (self=0x7f02b649d730,
    args=<value optimized out>) at ./Modules/_io/bufferedio.c:709

Wow. The lock is precisely there so that the buffered object doesn't have to be MT-safe or reentrant. It doesn't seem reasonable to attempt to restore the file to a "stable" state in the middle of an inner routine.

Also, the outer TextIOWrapper (we're talking about sys.stdout here) is not designed to MT-safe at all and is probably in an inconsistent state itself.

I would rather detect that the lock is already taken by the current thread and raise a RuntimeError. I don't think it's a good idea to do buffered I/O in a signal handler. Unbuffered I/O probably works.

(in a more sophisticated version, we could store pending writes so that they get committed at the end of the currently executing write)

Here is a patch raising RuntimeError on reentrant calls to a buffered object. I haven't touched _pyio; I wonder how to do it without making it even slower.

Would avoiding PyErr_CheckSignals() while the file object is in inconsistent state be a reasonable alternative?

I am guessing that it's not that uncommon for a signal handler to need IO (e.g to log a signal). 

If making IO safer is not an option, then I think, this limitation needs to be documented (especially, given that this seems to be a behavior change from Python 2.x).

> Would avoiding PyErr_CheckSignals() while the file object is in
> inconsistent state be a reasonable alternative?

No, because we'd like IO operations to be interruptible by the user
(e.g. pressing Ctrl-C) when they would otherwise block indefinitely.

> I am guessing that it's not that uncommon for a signal handler to need
> IO (e.g to log a signal).

In C, it is recommended that signal handlers be minimal. In Python,
there is no explicit recommendation but, given they execute
semi-asynchronously, I personally wouldn't put too much code in them :)

That said, there's no problem doing IO as long as you're not doing
reentrant calls to the *same* file object. I agree that for logging this
is not always practical...

> If making IO safer is not an option, then I think, this limitation
> needs to be documented (especially, given that this seems to be a
> behavior change from Python 2.x).

Perhaps the IO documentation needs an "advanced topics" section. I'll
see if I get some time.

Dummy question: why don't you use KeyboardInterrupt instead of a custom SIGINT handler?

try:
    for i in range(1000000):
        print(i)
except KeyboardInterrupt:
    print("got sigint")

Python SIGINT handler raises a KeyboardInterrupt (the handler is written in C, not in Python) which is safe, whereas writing to sys.stdout doesn't look to be a good idea :-)

This issue remembers me #3618 (opened 2 years ago): I proposed to use RLock instead of Lock, but RLock was implemented in Python and were too slow. Today, we have RLock implemented in C and it may be possible to use them. Would it solve this issue?

--

There are at least two deadlocks, both in _bufferedwriter_flush_unlocked():
 - call to _bufferedwriter_raw_write()
 - call to PyErr_CheckSignals()

> The lock is precisely there so that the buffered object doesn't 
> have to be MT-safe or reentrant. It doesn't seem reasonable
> to attempt to restore the file to a "stable" state in the middle
> of an inner routine.

Oh, so release the lock around the calls to _bufferedwriter_raw_write() (aorund PyObject_CallMethodObjArgs() in _bufferedwriter_raw_write()) and PyErr_CheckSignals() is not a good idea? Or is it just complex because the buffer object have to be in a consistent state?

> (in a more sophisticated version, we could store pending writes 
> so that they get committed at the end of the currently 
> executing write)

If the pending write fails, who gets the error?

> This issue remembers me #3618 (opened 2 years ago): I proposed to use
> RLock instead of Lock, but RLock was implemented in Python and were
> too slow. Today, we have RLock implemented in C and it may be possible
> to use them. Would it solve this issue?

I think it's more complicated. If you use an RLock, you can reenter the
routine while the object is in an unknown state, so the behaviour can be
all kinds of wrong.

> > The lock is precisely there so that the buffered object doesn't 
> > have to be MT-safe or reentrant. It doesn't seem reasonable
> > to attempt to restore the file to a "stable" state in the middle
> > of an inner routine.
> 
> Oh, so release the lock around the calls to
> _bufferedwriter_raw_write() (aorund PyObject_CallMethodObjArgs() in
> _bufferedwriter_raw_write()) and PyErr_CheckSignals() is not a good
> idea? Or is it just complex because the buffer object have to be in a
> consistent state?

Both :)

> > (in a more sophisticated version, we could store pending writes 
> > so that they get committed at the end of the currently 
> > executing write)
> 
> If the pending write fails, who gets the error?

Yes, I finally think it's not a good idea. flush() couldn't work
properly anyway, because it *has* to flush the buffer before returning.

Ok, so +1 to apply immediatly your patch which "fixes" the deadlock. If someone is motived to make Buffered* classes reentrant, (s)he can remove this exception.

io and signal documentation should also be improved to indicate that using buffered I/O in a signal handler may raise a RuntimeError on reentrant call (and give an example to explain the problem?).

About the patch: can't you move "&& (self->owner = PyThread_get_thread_ident(), 1) )" in _enter_buffered_busy()?

Fixed in r86981 (3.2), r86987 (3.1) and r86992 (2.7). Thanks!