classification
Title: signal.signal/signal.alarm not working as expected
Type: behavior Stage: needs patch
Components: Versions: Python 3.3, Python 3.2, Python 2.7
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: alanwilter, georg.brandl, neologix, nirai, pitrou
Priority: normal Keywords: patch

Created on 2010-08-04 08:33 by alanwilter, last changed 2011-06-30 17:58 by pitrou.

Files
File name Uploaded Description Edit
io_signal.diff neologix, 2011-01-09 18:36
Messages (8)
msg112771 - (view) Author: Alan Wilter (alanwilter) Date: 2010-08-04 08:33
I have this example code to illustrate a problem I am having with python3. It works fine with python 2.6 and 2.7 but does not with python 3.1.

from __future__ import print_function
import os, subprocess, signal

def signal_handler( signum, frame ):

    print( "PID: %s" % pid )
    print( "Timed out! Process %s killed, max exec time (%ss) exceeded" % (pid, timeTol ) )
    os.kill( int( pid ), 15 )
    raise Exception( "Taking too long to finish... aborting!" )

if __name__ == '__main__':

    timeTol = 5

    cmd = 'find /'

    signal.signal(signal.SIGALRM, signal_handler)
    signal.alarm(timeTol)

    p = subprocess.Popen(cmd, shell=True, stderr = subprocess.STDOUT, stdout = subprocess.PIPE)
    pid = p.pid

    out = str( p.communicate()[0].decode() )
    print(out)


Executing it:

time python3.1 timout.py
PID: 27687
Timed out! Process 27687 killed, max exec time (5s) exceeded
Traceback (most recent call last):
  File "timout.py", line 23, in <module>
    out = str( p.communicate()[0].decode() )
  File "/sw/lib/python3.1/subprocess.py", line 719, in communicate
    stdout = self.stdout.read()
  File "timout.py", line 9, in signal_handler
    raise Exception( "Taking too long to finish... aborting!" )
Exception: Taking too long to finish... aborting!
python3.1 timout.py  0.52s user 3.88s system 19% cpu 22.841 total

#### It prints essentially the same thing with a *very* *big* difference it takes 22 seconds and actually the alarm only works when the whole task ('find /') is finished.
msg125815 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2011-01-09 00:26
It's due to the way the python interpreter handles signals: when the signal is received, python runs a stub signal handler that just sets a flag indicating that the signal has been received: the actual handler is executed later, synchronously, mainly from the main evaluation loop.
The problem here is that since the main process is performing a read until EOF is reached (i.e. until the subprocess exits), the C code loops around the read(2) call without giving a chance for the handler to run.
A patch for is similar issue has been applied, see http://bugs.python.org/issue9617#

But it only fixed writes, not reads.
I think _bufferedreader_read_all and _bufferedreader_read_generic should be fixed too to call PyErr_CheckSignals().
msg125830 - (view) Author: Georg Brandl (georg.brandl) * (Python committer) Date: 2011-01-09 07:43
Antoine?
msg125845 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-01-09 15:13
Charles-François' analysis seems to be right. Note that the actual issue here is that read() always succeeds, returning a partial result (because you're executing a command, 'find /', which outputs a lot of data). If read() were interrupted before anything could be read, it would return EINTR and the handler would get executed immediately.

Anyone wants to propose a patch + tests?
msg125851 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2011-01-09 18:36
> Antoine Pitrou <pitrou@free.fr> added the comment:
>
> Charles-François' analysis seems to be right. Note that the actual issue here is that read() always succeeds, returning a partial result (because you're executing a command, 'find /', which outputs a lot of data). If read() were interrupted before anything could be read, it would return EINTR and the handler would get executed immediately.
>
> Anyone wants to propose a patch + tests?
>

Attached is a tentative patch: it checks for pending signals inside
_bufferedreader_read_generic, fileio_readall, and rawiobase_readall.
I tested quickly on regular files and on pipes, and handlers are now
called on time. As a an obvious bonus, it's also easier to interrupt a
script doing I/O with a KeyboardInterrupt (SIGINT).
If nothing seems blatantly wrong about this patch, I will go ahead and
try to write some tests for this.

Charles

> ----------
> versions: +Python 3.2
>
> _______________________________________
> Python tracker <report@bugs.python.org>
> <http://bugs.python.org/issue9504>
> _______________________________________
>
msg125863 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-01-09 20:59
> Attached is a tentative patch: it checks for pending signals inside
> _bufferedreader_read_generic, fileio_readall, and rawiobase_readall.
> I tested quickly on regular files and on pipes, and handlers are now
> called on time. As a an obvious bonus, it's also easier to interrupt a
> script doing I/O with a KeyboardInterrupt (SIGINT).
> If nothing seems blatantly wrong about this patch, I will go ahead and
> try to write some tests for this.

A potential downside is that the bytes which have been read simply get
lost. But since a signal can happen at any moment I guess nothing can be
done to protect from it in the general case, anyway.

As for the tests, the SignalsTest class in test_io.py is a natural
recipient.
msg127960 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-02-05 01:05
It seems that my patch for issue10956 also fixes this issue (although it doesn't try to fix FileIO). It also has tests and fixes read() as well as write().
I'm sorry for not noticing that the two issues were so similar. Suggest closing this issue as duplicate.
msg127964 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-02-05 01:12
Sorry, bad analysis. The patch in issue10956 only seemed to work because my system is too fast and "find /" in the script returned in less than 5 seconds. Replacing it with "yes" shows that the two issued are actually independent.
History
Date User Action Args
2011-06-30 17:58:24pitrousetassignee: pitrou ->
stage: patch review -> needs patch
versions: + Python 3.3, - Python 3.1
2011-05-10 02:30:36niraisetnosy: + nirai
2011-02-05 01:12:58pitrousetversions: + Python 2.7
nosy: georg.brandl, pitrou, neologix, alanwilter
messages: + msg127964
resolution: duplicate ->

superseder: file.write and file.read don't handle EINTR ->
stage: patch review
2011-02-05 01:05:51pitrousetnosy: georg.brandl, pitrou, neologix, alanwilter
resolution: duplicate
superseder: file.write and file.read don't handle EINTR
messages: + msg127960
2011-01-09 20:59:24pitrousetnosy: georg.brandl, pitrou, neologix, alanwilter
messages: + msg125863
2011-01-09 18:36:40neologixsetfiles: + io_signal.diff

messages: + msg125851
keywords: + patch
nosy: georg.brandl, pitrou, neologix, alanwilter
2011-01-09 15:13:57pitrousetnosy: georg.brandl, pitrou, neologix, alanwilter
messages: + msg125845
versions: + Python 3.2
2011-01-09 07:43:29georg.brandlsetassignee: pitrou

messages: + msg125830
nosy: + georg.brandl
2011-01-09 01:41:53eric.araujosetnosy: + pitrou
2011-01-09 00:26:56neologixsetnosy: + neologix
messages: + msg125815
2010-08-04 08:33:55alanwiltercreate