Error code 10035 calling socket.recv() on a socket with a timeout (WSAEWOULDBLOCK - A non-blocking socket operation could not be completed immediately)

[ehohenstein]

BPO	9090
Nosy	@gpshead, @jcea, @pitrou, @kristjanvalur, @giampaolo
Files	sock_recv.patch: Fix for 10035 error calling recv() on Windows selectretry.patch selectretry2.patch socket_10035.patch socket.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 2013-03-22.17:27:24.016>
created_at = <Date 2010-06-27.01:38:45.961>
labels = ['type-bug', 'expert-IO', 'OS-windows']
title = 'Error code 10035 calling socket.recv() on a socket with a timeout (WSAEWOULDBLOCK - A non-blocking socket operation could not be completed immediately)'
updated_at = <Date 2013-03-22.17:27:24.015>
user = 'https://bugs.python.org/ehohenstein'

bugs.python.org fields:

activity = <Date 2013-03-22.17:27:24.015>
actor = 'kristjan.jonsson'
assignee = 'none'
closed = True
closed_date = <Date 2013-03-22.17:27:24.016>
closer = 'kristjan.jonsson'
components = ['Windows', 'IO']
creation = <Date 2010-06-27.01:38:45.961>
creator = 'ehohenstein'
dependencies = []
files = ['17780', '18926', '19046', '20142', '29453']
hgrepos = []
issue_num = 9090
keywords = ['patch']
message_count = 25.0
messages = ['108770', '116498', '116499', '116553', '116554', '116814', '116815', '116816', '116817', '116820', '116830', '117535', '117549', '124515', '124607', '125674', '141221', '148736', '173351', '184390', '184511', '184654', '184667', '184679', '184990']
nosy_count = 12.0
nosy_names = ['gregory.p.smith', 'jcea', 'exarkun', 'pitrou', 'kristjan.jonsson', 'giampaolo.rodola', 'bjourne', 'neologix', 'ehohenstein', 'Ben.Smith', 'python-dev', 'Okko.Willeboordse']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'patch review'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue9090'
versions = ['Python 2.7']

[ehohenstein]

This error is unfortunately difficult to reproduce. I've only seen it happen on Windows XP running on a dual core VMWare VM. I haven't been able to reproduce it on a non-VM system running Windows 7. The only way I've been able to reproduce it is to run the following unit test repeatedly on the XP VM repeatedly until it fails:

import unittest
import urllib2

class DownloadUrlTest(unittest.TestCase):
    def testDownloadUrl(self):
        opener = urllib2.build_opener()
        handle = opener.open('http://localhost/', timeout=60)
        handle.info()
        data = handle.read()
        self.assertNotEqual(data, '')

if __name__ == "__main__":
    unittest.main()

This unit test obviously depends on a web server running on localhost. In the test environment where I was able to reproduce this problem the web server is Win32 Apache 2.0.54 with mod_php. When the test fails, it fails with Windows error code 10035 (WSAEWOULDBLOCK) being generated by the call to the recv() method rougly once every 50-100 times the test is run. The following is a the final entry in the stack when the error occurs:

File "c:\slave\h05b15\build\Ext\Python26\lib\socket.py", line 353, in read (self=<socket._fileobject ...03B78170>, size=1027091)
data = self._sock.recv(left)

The thing to note is that the socket is being created with a timeout of 60. The implementation of the socket.recv() method in socketmodule.c in the _socket import module is to use select() to wait for a socket to become readable for socket objects with a timeout and then to call recv() on the socket only if select() did not return indicating that the timeout period elapsed without the socket becoming readable. The fact that Windows error code 10035 (WSAEWOULDBLOCK) is being generated in the sock_recv_guts() method in socketmodule.c indicates that select() returned without timing out which means that Windows must have indicated that the socket is readable when in fact it wasn't. It appears that there is a known issue with Windows sockets where this type of problem may occur with non-blocking sockets. It is described in the msdn documentation for WSAAsyncSelect() (http://msdn.microsoft.com/en-us/library/ms741540%28VS.85%29.aspx). The code for socketmodule.c doesn't seem to handle this type of situation correctly. The patch I've included with this issue report retries the select() if the recv() call fails with WSAWOULDBLOCK (only if MS_WINDOWS is defined). With the patch in place the test ran approximately 23000 times without failure on the system where it was failing without the patch.

[BenSmith]

I also see this issue on occasion on windows XP SP 3, using python 2.6.5 to fetch large files via http.

The error is infrequent, but it is happening in my situation without a VM.

[pitrou]

It appears that there is a known issue with Windows sockets where this
type of problem may occur with non-blocking sockets. It is described in
the msdn documentation for WSAAsyncSelect()
(http://msdn.microsoft.com/en-us/library/ms741540%28VS.85%29.aspx).

That documentation doesn't seem to describe the same kind of situation; it is about delayed notification through Windows messages (if you read the sequence they given in example, it's quite logical why it can fail).

Have you tried instrumenting sock_recv_guts() and dumping the actual return values and errnos (from both internal_select() and recv())?

[neologix]

Actually, it's possible that select(2) incorrectly reports sockets as ready for reading : for example if the socket receives data, but then discards it because of an invalid checksum (and I guess you're more likely to get this type of problem on a VM or while copying large files).

[pitrou]

So it means we should indeed retry on a socket with timeout... But we must take care not to exceed the original timeout, so we must measure the time taken by each select() call.

[neologix]

Unfortunately, select doesn't necessarily update the timeout variable with the remaining time, so we can't rely on this. This would mean having the select enclosed within gettimeofday and friends, which seems a bit overkill...

[exarkun]

Unfortunately, select doesn't necessarily update the timeout variable with the remaining time, so we can't rely on this. This would mean having the select enclosed within gettimeofday and friends, which seems a bit overkill...

How is it "overkill" to be correct?

[pitrou]

Unfortunately, select doesn't necessarily update the timeout variable
with the remaining time, so we can't rely on this. This would mean
having the select enclosed within gettimeofday and friends, which
seems a bit overkill...

Well, given the general cost of Python function calls and bytecode
interpretation, it would probably not be much of a runtime overhead. So
it's mainly some additional, not very exciting code to write :-)

(luckily, in 3.2 we have a cross-platform gettimeofday() abstraction in
pytime.h which will ease things quite a bit)

[neologix]

Yes, I was concerned with the runtime overhead (especially under VMs, where clocks are emulated) and strace output ;-)
As for the dull code writting, I could give it a shot unless someone else wants to go ahead.

[neologix]

@ehohenstein: sorry, I hadn't seen you'd already submitted a patch, so you may as well update it to take into account what was said above. Also, please note that this issue is not specific to windows, so it would be nice to fix it for Unices too.

[pitrou]

Here is a proof of concept patch for Python 3.2. It only wraps recv() and recv_into(). recvfrom() and recvfrom_into() should receive the same treatment, at least.

[pitrou]

Here is an updated patch wrapping all variants of recv() and send(), except sendall() which already has its own retry loop.