Opened 11 years ago
Closed 11 years ago
#51 closed defect (fixed)
_FTPFile.close() blocks after reading only a part of a file
Reported by: | schwa | Owned by: | schwa |
---|---|---|---|
Priority: | major | Milestone: | 2.5 |
Component: | Library | Version: | 2.4.2 |
Keywords: | FTPFile, file, blocking | Cc: |
Description
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.
Attachments (1)
Change History (14)
comment:1 Changed 11 years ago by
Status: | new → assigned |
---|
comment:2 Changed 11 years ago by
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.
comment:3 Changed 11 years ago by
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.
comment:4 Changed 11 years ago by
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()
comment:5 Changed 11 years ago by
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.
comment:6 Changed 11 years ago by
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.
Changed 11 years ago by
Attachment: | test_ticket_51.py added |
---|
Helper script to find a limit where closing a remote file fails.
comment:7 Changed 11 years ago by
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.
comment:8 Changed 11 years ago by
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.
comment:9 Changed 11 years ago by
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).
comment:10 Changed 11 years ago by
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.
comment:11 Changed 11 years ago by
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.
comment:12 Changed 11 years ago by
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.
comment:13 Changed 11 years ago by
Resolution: | → fixed |
---|---|
Status: | assigned → closed |
I committed a fix for the 150 status code in changeset [4f4a4541b97a] and one for blocking close operations in changeset [dc80d10de7eb].
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.