| Bug #67303 | Handlge socket.recv returning less data than requested | ||
|---|---|---|---|
| Submitted: | 19 Oct 2012 17:53 | Modified: | 20 Dec 2012 21:49 |
| Reporter: | Sye van der Veen | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | Connector / Python | Severity: | S1 (Critical) |
| Version: | 1.0.7 | OS: | Windows (Win7 x64) |
| Assigned to: | Geert Vanderkelen | CPU Architecture: | Any |
[29 Oct 2012 20:43]
Geert Vanderkelen
Thanks for the report, and I understand the problem with sock.recv(4). The suggest fix is exactly what we do later in the code to read the message: we know the length and we call recv until we got it all. So, yes, we can do it similar for the reading the first 4 bytes, but I would like to limit function calls there. If there is any more information you can provide regarding the traffic (selects, updates, or mixture, etc..), that would be great. I just want to make sure we don't have any bigger issues here.
[19 Dec 2012 9:11]
Rudy Metzger
I can confirm this issue. My application frequently had database errors, until I implemented a bugfix similar to the one suggested by the OP. The errors are unpredictable, sometimes not occurring for hours, and sometimes occur within minutes. VERY rarely they did not happen for a whole day.
My application is a GUI application (pyqt) which runs for the whole day (or longer). I also tried to produce test cases with scripts only, but it is very difficult to reproduce this behaviour - although not impossible.
My setup:
MySQL-server-community-5.1.32-0.rhel5 (RHEL 5 on a virtual machine)
myql-connector-python 1.0.7 (Windows 7/Windows XP
Python 3.2.3 (Windows 7/Windows XP)
The quickfix I implemented:
def recv_plain(self):
"""Receive packets from the MySQL server"""
try:
header = self.sock.recv(4)
if len(header) < 4:
print( "######################################################" )
print( "SHORT HEADER: {}".format(header) )
print( "SHORT LEN: {}".format(len(header)) )
print( "######################################################" )
tmpHeader = self.sock.recv( 4 - len(header) )
header = header + tmpHeader
print( "######################################################" )
print( "NEW HEADER: {}".format(header) )
print( "NEW LEN: {}".format(len(header)) )
print( "######################################################" )
if len(header) < 4:
print( "######################################################" )
print( "HEADER: {}".format(header) )
print( "LEN: {}".format(len(header)) )
print( "######################################################" )
raise errors.InterfaceError(errno=2013)
self._packet_number = header[3]
payload_length = struct.unpack("<I", header[0:3] + b'\x00')[0]
#print( payload_length, end="," )
payload = b''
And here the logging of 2 days:
2012-12-17 10:37:33,648 [INFO] SHORT HEADER: b'\x0c'
2012-12-17 10:37:33,648 [INFO] SHORT LEN: 1
2012-12-17 10:37:33,648 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-17 10:37:33,648 [INFO] NEW LEN: 4
2012-12-17 11:46:33,799 [INFO] SHORT HEADER: b'\x0c'
2012-12-17 11:46:33,799 [INFO] SHORT LEN: 1
2012-12-17 11:46:33,815 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-17 11:46:33,815 [INFO] NEW LEN: 4
2012-12-17 12:43:01,823 [INFO] SHORT HEADER: b'\x0c'
2012-12-17 12:43:01,823 [INFO] SHORT LEN: 1
2012-12-17 12:43:01,823 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-17 12:43:01,839 [INFO] NEW LEN: 4
2012-12-17 14:06:44,680 [INFO] SHORT HEADER: b'\x0c'
2012-12-17 14:06:44,680 [INFO] SHORT LEN: 1
2012-12-17 14:06:44,680 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-17 14:06:44,680 [INFO] NEW LEN: 4
2012-12-17 14:06:59,940 [INFO] SHORT HEADER: b'\x0c'
2012-12-17 14:06:59,940 [INFO] SHORT LEN: 1
2012-12-17 14:06:59,940 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-17 14:06:59,940 [INFO] NEW LEN: 4
2012-12-17 14:07:01,063 [INFO] SHORT HEADER: b'\x0c'
2012-12-17 14:07:01,063 [INFO] SHORT LEN: 1
2012-12-17 14:07:01,063 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-17 14:07:01,079 [INFO] NEW LEN: 4
2012-12-17 16:59:45,128 [INFO] SHORT HEADER: b'o\x00\x00'
2012-12-17 16:59:45,128 [INFO] SHORT LEN: 3
2012-12-17 16:59:45,128 [INFO] NEW HEADER: b'o\x00\x00&'
2012-12-17 16:59:45,128 [INFO] NEW LEN: 4
2012-12-18 10:44:37,213 [INFO] SHORT HEADER: b'\x0c'
2012-12-18 10:44:37,213 [INFO] SHORT LEN: 1
2012-12-18 10:44:37,213 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-18 10:44:37,213 [INFO] NEW LEN: 4
2012-12-18 12:24:37,388 [INFO] SHORT HEADER: b'\x0c'
2012-12-18 12:24:37,388 [INFO] SHORT LEN: 1
2012-12-18 12:24:37,404 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-18 12:24:37,404 [INFO] NEW LEN: 4
2012-12-18 12:25:40,558 [INFO] SHORT HEADER: b'\x0c'
2012-12-18 12:25:40,558 [INFO] SHORT LEN: 1
2012-12-18 12:25:40,558 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-18 12:25:40,558 [INFO] NEW LEN: 4
2012-12-18 12:40:36,372 [INFO] SHORT HEADER: b'\x0c'
2012-12-18 12:40:36,372 [INFO] SHORT LEN: 1
2012-12-18 12:40:36,372 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-18 12:40:36,372 [INFO] NEW LEN: 4
2012-12-18 12:42:14,233 [INFO] SHORT HEADER: b'\x0c'
2012-12-18 12:42:14,233 [INFO] SHORT LEN: 1
2012-12-18 12:42:14,250 [INFO] NEW HEADER: b'\x0c\x00\x00\xa2'
2012-12-18 12:42:14,250 [INFO] NEW LEN: 4
2012-12-18 17:07:23,596 [INFO] SHORT HEADER: b'[\x00\x00'
2012-12-18 17:07:23,612 [INFO] SHORT LEN: 3
2012-12-18 17:07:23,612 [INFO] NEW HEADER: b'[\x00\x00$'
2012-12-18 17:07:23,612 [INFO] NEW LEN: 4
[20 Dec 2012 21:49]
John Russell
Added to changelog for 1.0.8: Intermittent errors could occur on Windows systems: InterfaceError(errno=2013). The cause was incorrect handling of sock.recv() library calls that returned less data than was requested.
Description: socket.recv is not guaranteed to return the requested amount of data. As a result, code such as the following has been failing for me semi-consistently (with error 2013): def recv_plain(self): """Receive packets from the MySQL server""" try: header = self.sock.recv(4) if len(header) < 4: raise errors.InterfaceError(errno=2013) How to repeat: This error was occuring on about 70% of a particular web page's loads. Some environment details: - Win7 x64 on a virtual machine - Apache 2.2.22 (x86) - Python 3.2.3 (x86) - MySQL 5.5.28 (x86) - Connector/Python 1.0.7 Reproducing this bug shouldn't be required, though. The documentation is clear that recv may return less than expected: http://docs.python.org/py3k/library/socket.html#socket.socket.recv http://msdn.microsoft.com/en-us/library/windows/desktop/ms740121(v=vs.85).aspx "For connection-oriented sockets, calling recv will return as much data as is currently available—up to the size of the buffer specified. Suggested fix: All calls to sock.recv should handle the case where less data than requested is received. One suggestion is to use the following method instead of sock.recv directly: def sock_recv(self, bufsize): retval = bytearray() while len(retval) < bufsize: retval += self.sock.recv(bufsize - len(retval)) return bytes(retval)