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:
None 
Category:Connector / Python Severity:S1 (Critical)
Version:1.0.7 OS:Microsoft Windows (Win7 x64)
Assigned to: Geert Vanderkelen

[19 Oct 2012 17:53] Sye van der Veen
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)
[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.