classification
Title: Improve reporting of broken stdout pipe during interpreter shutdown
Type: behavior Stage:
Components: IO Versions: Python 2.7
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: Christopher.Heiny, Jeremy.Fishman, daumiller, flox, ncoghlan, pitrou, terry.reedy, ulidtko, zzzeek
Priority: normal Keywords: patch

Created on 2011-03-03 01:32 by ulidtko, last changed 2014-05-06 00:37 by Christopher.Heiny.

Files
File name Uploaded Description Edit
python-sigint_and_epipe_straces.txt Jeremy.Fishman, 2012-02-14 03:40 strace of issue in 3.2.2, 3.1.2, and 2.5.2
flush_stdout_at_shutdown.patch pitrou, 2013-09-23 20:31
Messages (11)
msg129930 - (view) Author: (ulidtko) Date: 2011-03-03 01:32
The following script fails:

from time import sleep

try:
    while True:
        sleep(0.1)
        print "blah"
except KeyboardInterrupt:
    pass


when being launched with redirections like this:
$ python test.py | tee /dev/null

and the tee process gots killed *before* the python process (by e.g. hitting ^C in most shells). The output is:

close failed in file object destructor:
sys.excepthook is missing
lost sys.stderr

When the python process is SIGINTed prior to the tee process, everything goes as expected: buffered output to stdout gots flushed and seen on the console, the script finishes successfully, with zero exit status, tee finishes too. When the tee receives SIGINT first, and then python, script loses the output and prints the mentioned message. strace shows that python is receiving (but probably not handling properly) "Broken pipe" error in response to write(2):
[pid 17874] write(1, "blah\nblah\nblah\nblah\nblah\nblah\nbl"..., 680) = -1 EPIPE (Broken pipe)
msg130083 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2011-03-04 22:50
Have you tried this with 3.2 (or 3.1)?
What behavior do you expect when pipe goes first?
msg153320 - (view) Author: Jeremy Fishman (Jeremy.Fishman) Date: 2012-02-14 03:40
The behavior under question here is how the interpreter handles a broken pipe during shutdown.  The following code behaves as expected when either (a) the process receives a SIGINT or (b) the output pipe is closed

import sys
try:
    while True:
        print 'y'
except KeyboardInterrupt:
    sys.exit(130)
except (IOError, OSError):
    sys.exit(141)

However, in the case of a SIGINT sent to the entire process group e.g. from a shell prompt, the interpreter may receive the SIGINT before detecting the broken pipe.  In this case, the interpreter prints an error somewhere during the SIGINT handler or subsequent shutdown.

In Python 2.4.6 and 2.5.2 the error is
    close failed: [Errno 32] Broken pipe

In Python 2.7.2 the error is
    close failed in file object destructor:
    sys.excepthook is missing
    lost sys.stderr

In Python 3.2 the error is
    Exception IOError: IOError(32, 'Broken pipe') in <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'> ignored

I have not succeeded in triggering the error in Python 3.1.2, despite ensuring the signal arrived before the next write(2) call after the output pipe was closed.  I have attached some straces, but this difference is probably spurious unless reproduced with one of the later bugfix 3.1 releases.

In all versions, the program properly terminates with code 130, or 141 if the write(2) error occurs first.

I would say the bug here if any is inconsistent behavior, though that isn't surprising between major versions.  The 2.7 error message is the only misleading one - stderr was never "lost", and we don't really care about sys.excepthook here.
msg198316 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2013-09-23 07:53
It seems this can be triggered easily with echo, since that appears to reliably close stdin on startup (Discovered via http://stackoverflow.com/questions/16314321).

Compare (using a recent trunk build, although I see the same behaviour with the system 3.3 installation):

$ ../py3k/python -c 'print("Hello world!")' | echo

Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>
BrokenPipeError: [Errno 32] Broken pipe

$ ../py3k/python -c 'print("Hello world!")' | xargs echo
Hello world!

$ ../py3k/python -c 'print("Hello world!")' | cat
Hello world!

Given that flush/close related exceptions are automatically ignored in destructors, something else must be going on here.

It turns out that the *explicit* flush calls during interpreter finalization use PyErr_WriteUnraisable on failure to flush stdout instead of silently ignoring the exceptions (http://hg.python.org/cpython/file/ed011b0d7daf/Python/pythonrun.c#l457).

This is reasonable, since a broken pipeline *is* an error that the user may need to do something about (e.g. as with echo, they next pipeline stage may not being invoked correctly, thus breaking the pipe)

However, in the specific case of a broken pipe, I believe it is desirable for us to write out a cleaner message than the generic PyErr_WriteUnraisable output.
msg198332 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-23 19:58
I'm not sure I understand Nick's suggestion. As far as I can tell, the issue is to detect that write() (really fwrite() in 2.x) failed and output the error.
msg198338 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-23 20:26
Ah, actually, the real issue is that sys.stderr is gone by the time we try to print the exception (which explains the "lost sys.stderr" message).
msg198339 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-23 20:31
Here is a patch, lacking tests.
How important it is to fix this in 2.7 I'm not sure. People are certainly used to the quirk now, and it's generally harmless.
msg198345 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2013-09-23 23:03
My specific suggestion was aimed at 3.4 - I think reporting the failure to
flush stdout on stderr is the right thing to do (since data may have been
lost and people can suppress it by closing stdout early, including in an
atexit handler), but I also think it's worth improving the error message in
the specific case of a broken pipe error.

However, I also agree the error output is more wrong in 2.7, so improving
that would be good, too.
msg198347 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-23 23:05
> My specific suggestion was aimed at 3.4 - I think reporting the failure to
> flush stdout on stderr is the right thing to do (since data may have been
> lost and people can suppress it by closing stdout early, including in an
> atexit handler), but I also think it's worth improving the error message in
> the specific case of a broken pipe error.

How would you improve it?
msg198349 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2013-09-23 23:12
Suppress the traceback, avoid printing the exception repr and instead
display something more like "Broken pipe: receiving end of stdout closed
prior to interpreter shutdown"
msg213109 - (view) Author: mike bayer (zzzeek) Date: 2014-03-11 00:25
my users are reporting one of these issues, and while I can easily catch IOError on Python 2, I can't catch anything on Python 3, and pointing SIGPIPE to SIG_DFL isn't an option because this is for Alembic migrations and the command needs to complete its work.

What is/will be the recommended solution for people who want their programs to finish totally but not complain when their pipe is cut off in Python 3?
History
Date User Action Args
2014-05-06 00:37:12Christopher.Heinysetnosy: + Christopher.Heiny
2014-04-18 10:46:10floxsetnosy: + flox
2014-03-21 13:44:45daumillersetnosy: + daumiller
2014-03-11 00:25:06zzzeeksetnosy: + zzzeek
messages: + msg213109
2013-09-23 23:12:32ncoghlansetmessages: + msg198349
2013-09-23 23:05:55pitrousetmessages: + msg198347
2013-09-23 23:03:21ncoghlansetmessages: + msg198345
2013-09-23 20:31:07pitrousetfiles: + flush_stdout_at_shutdown.patch
keywords: + patch
messages: + msg198339
2013-09-23 20:26:11pitrousetmessages: + msg198338
2013-09-23 19:58:24pitrousetmessages: + msg198332
2013-09-23 07:53:49ncoghlansetnosy: + ncoghlan, pitrou

messages: + msg198316
title: "close failed in file object destructor" when "Broken pipe" happens on stdout -> Improve reporting of broken stdout pipe during interpreter shutdown
2012-02-14 03:40:14Jeremy.Fishmansetfiles: + python-sigint_and_epipe_straces.txt
nosy: + Jeremy.Fishman
messages: + msg153320

2011-03-04 22:50:46terry.reedysetnosy: + terry.reedy
messages: + msg130083
2011-03-03 01:32:45ulidtkocreate