_FTPFile.close() blocks after reading only a part of a file

[schwa]

After opening a remote file for reading, a subsequent call of the file's close method blocks:

>>> h = ftputil.FTPHost("localhost", 'ftptest', password)
>>> f = h.file("debian-keyring.tar.gz", 'rb')
>>> data = f.read(100)
>>> f.close()  # blocks
^CTraceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "ftp_file.py", line 280, in close
    ftp_error._try_with_ioerror(self._session.voidresp)
  File "ftp_error.py", line 168, in _try_with_ioerror
    return callee(*args, **kwargs)
  File "/usr/lib/python2.6/ftplib.py", line 223, in voidresp
    resp = self.getresp()
  File "/usr/lib/python2.6/ftplib.py", line 209, in getresp
    resp = self.getmultiline()
  File "/usr/lib/python2.6/ftplib.py", line 195, in getmultiline
    line = self.getline()
  File "/usr/lib/python2.6/ftplib.py", line 182, in getline
    line = self.file.readline()
  File "/usr/lib/python2.6/socket.py", line 406, in readline
    data = self._sock.recv(self._rbufsize)
KeyboardInterrupt
>>> h.close()

>>> h = ftputil.FTPHost("localhost", 'ftptest', password)
>>> f = h.file("debian-keyring.tar.gz", 'rb')
>>> data = f.read()
>>> f.close()  # succeeds
>>> h.close()

Reading an incomplete file with a following close operation used to work; I noticed the problem through a failing unit test (_test_real_ftp.RealFTPTest.test_open_for_reading) which opens the above test file and immediately after that closes it.

[schwa]

Since my last work on ftputil, I updated my desktop system from Ubuntu 9.10 to 10.04. The version changes of Python and the local FTP server, PureFTPd, and maybe other components might have something to do with the bug.

[schwa]

All these tests succeed without blocking:

>>> import ftputil
>>> h = ftputil.FTPHost("ftp.gnome.org", "anonymous", "")
>>> h.listdir(h.curdir)    
['HEADER.html', ...]
>>> h.path.isfile("HEADER.html")
True
>>> h.download("HEADER.html", "HEADER.html", "b")

>>> f = h.file("HEADER.html")
>>> data = f.read()
>>> f.close()
>>> data[:20]
'<b><pre>\n           '

>>> f = h.file("HEADER.html")
>>> data = f.read(10)
>>> f.close()
>>> h.close()
 
>>> h = ftputil.FTPHost("ftp.gnome.org", "anonymous", "")
>>> f = h.file("HEADER.html")
>>> data = f.read(10)
>>> f.close()
>>> h.close()
 
>>> h = ftputil.FTPHost("ftp.gnome.org", "anonymous", "")
>>> f = h.file("HEADER.html")
>>> f.close()
>>> h.close()

>>> h = ftputil.FTPHost("ftp.gnome.org", "anonymous", "")
>>> f = h.file("HEADER.html", "rb")
>>> f.close()
>>> h.close()

This indicates (I won't say "prove" yet) a problematic change regarding the local FTP test server or its configuration.

[schwa]

As I have my local /etc directory under version control I just checked and didn't find changes from the Ubuntu upgrade in /etc/default/pure-ftpd-common (the only PureFTPd-related file in the directory) or in the directory /etc/pure-ftpd.

There are also no signs of a problem in the log file of the local firewall.

[schwa]

I tried to access a file of several MB from ftp.debian.org and the test succeeded without blocking:

>>> h = ftputil.FTPHost("ftp.debian.org", "anonymous", "")
>>> f = h.file("debian/dists/Debian5.0.4/Contents-i386.gz", "rb")
>>> f.close()
>>> h.path.getsize("debian/dists/Debian5.0.4/Contents-i386.gz")
13824603
>>> h.close()

[schwa]

Here are two sessions which show the bug or not. The debugging info comes from an additional line

self._session.debug(1)

in ftputil.FTPHost.__init__ after

self._session = self._make_session()

(_session is an ftplib.FTP object.)

Session 1 (local, with bug):

>>> h = ftputil.FTPHost("localhost", 'ftptest', password)
*cmd* 'PWD'
*resp* '257 "/" is your current location'
>>> f = h.file("debian-keyring.tar.gz", 'rb')
*cmd* 'PWD'
*resp* '257 "/" is your current location'
*cmd* 'CWD /'
*resp* '250 OK. Current directory is /'
*cmd* 'TYPE I'
*resp* '200 TYPE is now 8-bit binary'
*cmd* 'PASV'
*resp* '227 Entering Passive Mode (127,0,0,1,18,172)'
*cmd* 'RETR debian-keyring.tar.gz'
*resp* '150-Accepted data connection\n150 13384.7 kbytes to download'
>>> f.close()
^C

Session 2 (remote, without bug):

>>> h = ftputil.FTPHost("ftp.debian.org", "anonymous", "")
*cmd* 'PWD'
*resp* '257 "/"'
>>> f = h.file("debian/dists/Debian5.0.4/Contents-i386.gz", "rb")
*cmd* 'PWD'
*resp* '257 "/"'
*cmd* 'CWD /debian/dists/Debian5.0.4'
*resp* '250 Directory successfully changed.'
*cmd* 'TYPE I'
*resp* '200 Switching to Binary mode.'
*cmd* 'PASV'
*resp* '227 Entering Passive Mode (130,89,149,226,177,188)'
*cmd* 'RETR Contents-i386.gz'
*resp* '150 Opening BINARY mode data connection for Contents-i386.gz (13824603 bytes).'
>>> f.close()
*resp* '426 Failure writing network stream.'
>>> h.close()

Both sessions look very similar; they share the same commands and return status codes. The last message from the local FTP server contains an hyphen after the status code ("150-Accepted data connection\n150 13384.7 kbytes to download") which might confuse ftplib or ftputil. Moreover, there's a line break in the message which might cause problems.

[schwa]

Here are two sessions with the data completely transferred before the remote file is closed.

Session 1, local:

>>> h = ftputil.FTPHost("localhost", 'ftptest', password)
*cmd* 'PWD'
*resp* '257 "/" is your current location'
>>> f = h.file("debian-keyring.tar.gz", 'rb')
*cmd* 'PWD'
*resp* '257 "/" is your current location'
*cmd* 'CWD /'
*resp* '250 OK. Current directory is /'
*cmd* 'TYPE I'
*resp* '200 TYPE is now 8-bit binary'
*cmd* 'PASV'
*resp* '227 Entering Passive Mode (127,0,0,1,154,160)'
*cmd* 'RETR debian-keyring.tar.gz'
*resp* '150-Accepted data connection\n150 13384.7 kbytes to download'
>>> data = f.read()
>>> f.close()
*resp* '226-File successfully transferred\n226 10.700 seconds (measured here), 1.22 Mbytes per second'
>>> h.close()
>>> 

Session 2, remote:

>>> h = ftputil.FTPHost("ftp.debian.org", "anonymous", "")
*cmd* 'PWD'
*resp* '257 "/"'
>>> f = h.file("debian/dists/Debian5.0.4/Contents-i386.gz", "rb")
*cmd* 'PWD'
*resp* '257 "/"'
*cmd* 'CWD /debian/dists/Debian5.0.4'
*resp* '250 Directory successfully changed.'
*cmd* 'TYPE I'
*resp* '200 Switching to Binary mode.'
*cmd* 'PASV'
*resp* '227 Entering Passive Mode (130,89,149,226,29,216)'
*cmd* 'RETR Contents-i386.gz'
*resp* '150 Opening BINARY mode data connection for Contents-i386.gz (13824603 bytes).'
>>> data = f.read()
>>> f.close()
*resp* '226 File send OK.'
>>> h.close()
>>> 

Again, both sessions look very similar.

[schwa]

Helper script to find a limit where closing a remote file fails.

[schwa]

I used the attached helper script test_ticket_51.py to find a threshold above which closing a file blocks with my local FTP server.

I find that a file of size 65536 (2**16) is opened for reading and is closed successfully whereas closing a file with 65537 bytes fails. For comparison, the value _rbufsize from the above traceback, aka _FTPFile._fo._rbufsize, is 8192 (2**13). I had assumed the size threshold to be _rbufsize. Maybe all files with a size a multiple of 8192 are closed fine; I'll look at that next.

[schwa]

Here's the output from the test script with a slightly changed size calculation:

Testing testdata_0
Testing testdata_8192
Testing testdata_16384
Testing testdata_24576
Testing testdata_32768
Testing testdata_40960
Testing testdata_49152
Testing testdata_57344
Testing testdata_65536
Testing testdata_73728

So seemingly there's in fact a limit at 65536 as indicated in comment 7.

[schwa]

Note: In the above comment, the output blocked after the last line (saying "testdata_73728"). The last size tried would have been 155648 (19 * 8192).

[schwa]

The tests run on the notebook with Ubuntu 9.10 - no blocking.

The version of PureFTPd on my notebook is 1.0.22-1 whereas on the desktop it's 1.0.24-1. I downloaded PureFTPd from ​http://download.pureftpd.org/pub/pure-ftpd/releases/pure-ftpd-1.0.24.tar.bz2 and did

$ ./configure --prefix=<somewhere_under_my_home_dir> --with-puredb
$ make
$ make install

After that, I stopped the "native" daemon installed with aptitude, started the new daemon and entered this test in the Python interpreter:

>>> h = ftputil.FTPHost("localhost", 'ftptest', password)
>>> f = h.file("debian-keyring.tar.gz", 'rb')
>>> f.close()

Result: The call f.close() blocked. So the blocking appears to be an effect of Ubuntu's new(er) version of PureFTPd! For the record, the current PureFTPd version is 1.0.29.

[schwa]

A test with PureFTPd 1.0.29 on my desktop system gives me:

>>> h = ftputil.FTPHost("localhost", 'ftptest', password)
>>> f = h.file("debian-keyring.tar.gz", 'rb')
>>> f.close()
Traceback (most recent call last):
  File "<ipython console>", line 1, in <module>
  File "ftp_file.py", line 280, in close
    ftp_error._try_with_ioerror(self._session.voidresp)
  File "ftp_error.py", line 173, in _try_with_ioerror
    raise FTPIOError(*exc.args)
FTPIOError: 150 3.250 seconds (measured here), 39.39 Kbytes per second
Debugging info: ftputil 2.4.2, Python 2.6.5 (linux2)

A debugging print statement reveals that the exception on the ftplib side is a ftplib.error_reply whose comment says "unexpected [123]xx reply" which makes perfect sense from the view of ftplib. Normally, a client would expect a complete transfer and then a 226 status code when the connection is closed.

[schwa]

The traceback with the FTPIOError for PureFTPd 1.0.29 (see comment 11) occurs only if there's a pause between opening the file and closing it. If the open and close operations follow immediately after each other, the connection just blocks and finally results in a timeout from the FTP server side.

[schwa]

I committed a fix for the 150 status code in changeset [4f4a4541b97a] and one for blocking close operations in changeset [dc80d10de7eb].