classification
Title: asyncore should catch EPIPE while sending() and receiving()
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.2, Python 3.3, Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: giampaolo.rodola, josiahcarlson, neologix, python-dev, stutzbach, terry.reedy, vstinner, xdegaye
Priority: normal Keywords: patch

Created on 2009-04-02 01:03 by giampaolo.rodola, last changed 2011-10-29 13:23 by neologix. This issue is now closed.

Files
File name Uploaded Description Edit
asyncore.patch giampaolo.rodola, 2009-04-02 01:03
asyncore_epipe.py xdegaye, 2011-10-26 19:24 run this script to reproduce EPIPE error on linux
epipe-default.patch xdegaye, 2011-10-27 14:38 test case on default branch review
epipe-2.7.patch xdegaye, 2011-10-27 14:39 test case on the 2.7 branch
Messages (14)
msg85125 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2009-04-02 01:03
I received a report from a pyftpdlib user:
http://code.google.com/p/pyftpdlib/issues/detail?id=104
...complaining that an unhandled EPIPE error might be thrown by
asyncore.py on OS X in certain circumstances which are hardly reproducible.

By googling a little about it it seems that he's not the first one who
got this problem:
http://mail.python.org/pipermail/medusa-dev/2003/000852.html
https://bugs.launchpad.net/zope2/+bug/142654

I think it makes sense modifying dispatcher.send() and dispatcher.recv()
to include EPIPE as error condition to indicate that the connection has
been closed and call handle_close() as consequence.


The patch in attachment does that.
msg85127 - (view) Author: Josiah Carlson (josiahcarlson) * (Python triager) Date: 2009-04-02 01:19
I think that catching one more potential failure modes is reasonable.  
I'm probably going to apply a variant of this patch to pull the sequence 
into a frozenset for quick lookups, and so that we don't need to keep 
updating two different places if/when new failure conditions arise.
msg139199 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2011-06-26 19:26
I am not marking 'test needed' since the problem is 'hardly reproducible'.
msg146452 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2011-10-26 19:24
> I am not marking 'test needed' since the problem is 'hardly reproducible'.

The attached script named 'asyncore_epipe.py' may be used to reproduce
systematically the EPIPE error on linux with Python 3.2:

    * the Reader closes the socket after receiving the first data
    * the Writer gets an exception when attempting to write the next
      message on the closed socket

When you run 'python asyncore_epipe.py' or 'python asyncore_epipe.py
1025' you get an EPIPE error (1025 is the size of exchanged messages,
so the last Writer message has been fully read by the Reader before
closing).

When you run 'python asyncore_epipe.py 128' you get an ECONNRESET (the
Reader reads only 128 bytes before closing the socket)

Note that ECONNRESET has been removed in this script, from the
frozenset of handled errors, to make this last point visible.

So it seems that, on linux, when writing to a closed socket, you get
an ECONNRESET when there is still data in the socket, and an EPIPE
otherwise. In the first case the tcp connection ends with a single
RESET, and in the second case it ends with the sequence FIN-ACK-RESET.
msg146487 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2011-10-27 14:38
Uploaded the patch 'epipe-default.patch' with a test case that breaks
on linux when EPIPE is not handled by asyncore, which is the case with
Python 3.2 and previous versions.
msg146488 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2011-10-27 14:39
Uploaded the same test case for Python 2.7.
msg146510 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2011-10-27 17:58
Did you try with the current branches?
AFAICT, this should have been solved by 208a5290fd38 (issue #11265), and I did a quick test with default and it seems to be fixed.
In any case, it's probably a good idea to add this test to test_asyncore.

> So it seems that, on linux, when writing to a closed socket, you get
> an ECONNRESET when there is still data in the socket, and an EPIPE
> otherwise. In the first case the tcp connection ends with a single
> RESET, and in the second case it ends with the sequence FIN-ACK-RESET.

Yes, see RFC1122 section 4.2.2.13:
"""
            A host MAY implement a "half-duplex" TCP close sequence, so
            that an application that has called CLOSE cannot continue to
            read data from the connection.  If such a host issues a
            CLOSE call while received data is still pending in TCP, or
            if new data is received after CLOSE is called, its TCP
            SHOULD send a RST to show that data was lost.
"""
msg146514 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2011-10-27 18:37
> Did you try with the current branches?

Yes, the test is pass against the current default and 2.7 branches.
One must remove EPIPE from the asyncore._DISCONNECTED frozenset to
make the test to fail.


> Yes, see RFC1122 section 4.2.2.13:
> """
>             A host MAY implement a "half-duplex" TCP close sequence, so
>             that an application that has called CLOSE cannot continue to
>             read data from the connection.  If such a host issues a
>             CLOSE call while received data is still pending in TCP, or
>             if new data is received after CLOSE is called, its TCP
>             SHOULD send a RST to show that data was lost.
> """

Thanks for the pointer. Note that the "half-duplex" FIN-ACK-RESET
occurs when all received data has been read, and a single RESET is
sent when received data is still pending in the stream.
msg146537 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2011-10-28 06:38
>> Did you try with the current branches?
>
> Yes, the test is pass against the current default and 2.7 branches.
> One must remove EPIPE from the asyncore._DISCONNECTED frozenset to
> make the test to fail.

OK. Then I'll add this test to test_asyncore.
msg146602 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-10-29 10:42
New changeset bf1c4984d4e5 by Charles-François Natali in branch 'default':
Issue #5661: Add a test for ECONNRESET/EPIPE handling to test_asyncore. Patch
http://hg.python.org/cpython/rev/bf1c4984d4e5
msg146604 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2011-10-29 11:37
The test fails on OS X:
"""
======================================================================
ERROR: test_handle_close_after_conn_broken (test.test_asyncore.TestAPI_UseIPv4Poll)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.parc-snowleopard-1/build/Lib/test/test_asyncore.py", line 661, in test_handle_close_after_conn_broken
    self.loop_waiting_for_flag(client)
  File "/Users/buildbot/buildarea/3.x.parc-snowleopard-1/build/Lib/test/test_asyncore.py", line 523, in loop_waiting_for_flag
    asyncore.loop(timeout=0.01, count=1, use_poll=self.use_poll)
  File "/Users/buildbot/buildarea/3.x.parc-snowleopard-1/build/Lib/asyncore.py", line 215, in loop
    poll_fun(timeout, map)
  File "/Users/buildbot/buildarea/3.x.parc-snowleopard-1/build/Lib/asyncore.py", line 196, in poll2
    readwrite(obj, flags)
  File "/Users/buildbot/buildarea/3.x.parc-snowleopard-1/build/Lib/asyncore.py", line 123, in readwrite
    obj.handle_error()
  File "/Users/buildbot/buildarea/3.x.parc-snowleopard-1/build/Lib/asyncore.py", line 112, in readwrite
    obj.handle_expt_event()
  File "/Users/buildbot/buildarea/3.x.parc-snowleopard-1/build/Lib/asyncore.py", line 476, in handle_expt_event
    self.handle_expt()
  File "/Users/buildbot/buildarea/3.x.parc-snowleopard-1/build/Lib/test/test_asyncore.py", line 470, in handle_expt
    raise Exception("handle_expt not supposed to be called")
Exception: handle_expt not supposed to be called
"""

Looks like the FD is returned in the exception set on OS X...
msg146605 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-10-29 12:26
New changeset 507dfb0ceb3b by Charles-François Natali in branch 'default':
Issue #5661: on EPIPE/ECONNRESET, OS X returns the FD with the POLLPRI flag...
http://hg.python.org/cpython/rev/507dfb0ceb3b
msg146606 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2011-10-29 12:27
The test fails when use_poll is True.
The difference between using poll() and poll2():

    poll: All the read events are processed before the write events,
    so the close after the first recv by TestHandler will be followed
    by a send by TestClient within the same call to poll(). The
    test is deterministic.

    poll2: The order in which events are received is os dependent. So
    it is possible that the first recv by TestHandler is the last
    event in the 'r' list, so that after the close, a new call to
    poll2() is done and the first event in this new 'r' list, is not
    the expected write event for TestClient.

What about forcing self.use_poll to False, before calling
loop_waiting_for_flag() ? The drawback being that the test will be run
twice with the same environment.
msg146607 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2011-10-29 13:23
> The test fails when use_poll is True.
> The difference between using poll() and poll2():

poll uses select(2), while poll2 uses poll(2) (duh, that's confusing).
It seems that on OS X Snow Leopard, poll(2) sets the POLLPRI flag upon EPIPE (and probably doesn't return the FD in the exception set for select(2)...).
Not sure whether it's legal, but it's the only OS to do that (POLLPRI usually used for OOB data). Also, note that Tiger doesn't behave that way.
OS X often offers such surprises :-)

> What about forcing self.use_poll to False, before calling
> loop_waiting_for_flag() ? The drawback being that the test will be run
> twice with the same environment.

I just added an handle_expt() handler, and it works fine.

Closing, thanks for the patch!
History
Date User Action Args
2011-10-29 13:23:43neologixsetstatus: open -> closed
messages: + msg146607

assignee: josiahcarlson ->
resolution: fixed
stage: patch review -> resolved
2011-10-29 12:27:20xdegayesetmessages: + msg146606
2011-10-29 12:26:39python-devsetmessages: + msg146605
2011-10-29 11:37:46neologixsetmessages: + msg146604
2011-10-29 10:42:48python-devsetnosy: + python-dev
messages: + msg146602
2011-10-28 06:38:33neologixsetmessages: + msg146537
2011-10-27 18:37:30xdegayesetmessages: + msg146514
2011-10-27 17:58:17neologixsetnosy: + neologix
messages: + msg146510
2011-10-27 14:42:15vstinnersetnosy: + vstinner
2011-10-27 14:39:34xdegayesetfiles: + epipe-2.7.patch

messages: + msg146488
2011-10-27 14:38:04xdegayesetfiles: + epipe-default.patch

messages: + msg146487
2011-10-26 19:24:57xdegayesetfiles: + asyncore_epipe.py
nosy: + xdegaye
messages: + msg146452

2011-06-26 19:26:00terry.reedysetversions: + Python 3.2, Python 3.3, - Python 2.6, Python 3.0, Python 3.1
nosy: + stutzbach, terry.reedy, - josiah.carlson

messages: + msg139199

stage: patch review
2009-04-02 01:19:40josiahcarlsonsetassignee: josiahcarlson
messages: + msg85127
2009-04-02 01:03:25giampaolo.rodolacreate