queer ftp load configuration issue (hitting the five minute timeout in a successful transfer)

[Thomas.Meyer]

Who can help with this queer ftp transfer problem?

After moving from another non-Linux ftp server to vsftp on SLES 11,
two out of ten 2950 switches are nearly unable to load configuration
files from ftp: a file of a few KB will take five minutes to load.

This is particularly queer, as all are of the same hardware,
configuration and sw version (C2950-I6K2L2Q4-M, all Version
12.1(13)EA1c - quite old, I admit, but rock-stable).

The log files of vsftp show a file transfer starting immediately after
I issue the copy command "copy ftp://a.b.c.d/adir/afile
running-config:" on the switch:

Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16064] CONNECT: Client "e.f.g.h"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16064] FTP response: Client "e.f.g.h", "220 Welcome message"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16064] FTP command: Client "e.f.g.h", "USER auser"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16064] [auser] FTP response: Client "e.f.g.h", "331 Please specify the password."
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16064] [auser] FTP command: Client "e.f.g.h", "PASS <password>"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16063] [auser] OK LOGIN: Client "e.f.g.h"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16065] [auser] FTP response: Client "e.f.g.h", "230 Login successful."
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16065] [auser] FTP command: Client "e.f.g.h", "TYPE I"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16065] [auser] FTP response: Client "e.f.g.h", "200 Switching to Binary mode."
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16065] [auser] FTP command: Client "e.f.g.h", "PASV"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16065] [auser] FTP response: Client "e.f.g.h", "227 Entering Passive Mode (a,b,c,d,117,131)"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16065] [auser] FTP command: Client "e.f.g.h", "RETR adir/afile"
Aug  7 11:19:14 ftphost vsftpd: Thu Aug  7 11:19:14 2014 [pid 16065] [auser] FTP response: Client "e.f.g.h", "150 Opening BINARY mode data connection for adir/afile (17706 bytes)."

Then, after five (!) long minutes, the transfer will complete, with
some ever so queer abort commands:

Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16065] [auser] OK DOWNLOAD: Client "e.f.g.h", "/adis/afile", 17706 bytes, 0.06Kbyte/sec
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16065] [auser] FTP response: Client "e.f.g.h", "226 File send OK."
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16065] [auser] FTP command: Client "e.f.g.h", "ÿôÿòABOR"
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16065] [auser] FTP response: Client "e.f.g.h", "225 No transfer to ABOR."
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16065] [auser] FTP command: Client "e.f.g.h", "QUIT"
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16065] [auser] FTP response: Client "e.f.g.h", "221 Goodbye."
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16081] CONNECT: Client "e.f.g.h"
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16081] FTP response: Client "e.f.g.h", "220 Welcome message"
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16081] FTP command: Client "e.f.g.h", "USER auser"
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16081] [auser] FTP response: Client "e.f.g.h", "331 Please specify the password."
Aug  7 11:24:14 ftphost vsftpd: Thu Aug  7 11:24:14 2014 [pid 16081] [auser] FTP command: Client "e.f.g.h", "PASS <password>"
Aug  7 11:24:15 ftphost vsftpd: Thu Aug  7 11:24:15 2014 [pid 16080] [auser] OK LOGIN: Client "e.f.g.h"
Aug  7 11:24:15 ftphost vsftpd: Thu Aug  7 11:24:15 2014 [pid 16082] [auser] FTP response: Client "e.f.g.h", "230 Login successful."
Aug  7 11:24:15 ftphost vsftpd: Thu Aug  7 11:24:15 2014 [pid 16082] [auser] FTP command: Client "e.f.g.h", "TYPE I"
Aug  7 11:24:15 ftphost vsftpd: Thu Aug  7 11:24:15 2014 [pid 16082] [auser] FTP response: Client "e.f.g.h", "200 Switching to Binary mode."
Aug  7 11:24:15 ftphost vsftpd: Thu Aug  7 11:24:15 2014 [pid 16082] [auser] FTP command: Client "e.f.g.h", "PASV"
Aug  7 11:24:15 ftphost vsftpd: Thu Aug  7 11:24:15 2014 [pid 16082] [auser] FTP response: Client "e.f.g.h", "227 Entering Passive Mode (a,b,c,d,117,63)"
Aug  7 11:24:15 ftphost vsftpd: Thu Aug  7 11:24:15 2014 [pid 16082] [auser] FTP command: Client "e.f.g.h", "RETR adis/afile"
Aug  7 11:24:15 ftphost vsftpd: Thu Aug  7 11:24:15 2014 [pid 16082] [auser] FTP response: Client "e.f.g.h", "150 Opening BINARY mode data connection for adis/afile (17706 bytes)."
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16085] CONNECT: Client "e.f.g.h"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16085] FTP response: Client "e.f.g.h", "220 Welcome message"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16085] FTP command: Client "e.f.g.h", "USER auser"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16085] [auser] FTP response: Client "e.f.g.h", "331 Please specify the password."
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16085] [auser] FTP command: Client "e.f.g.h", "PASS <password>"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16084] [auser] OK LOGIN: Client "e.f.g.h"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16086] [auser] FTP response: Client "e.f.g.h", "230 Login successful."
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16086] [auser] FTP command: Client "e.f.g.h", "TYPE I"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16086] [auser] FTP response: Client "e.f.g.h", "200 Switching to Binary mode."
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16086] [auser] FTP command: Client "e.f.g.h", "PASV"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16086] [auser] FTP response: Client "e.f.g.h", "227 Entering Passive Mode (a,b,c,d,117,55)"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16086] [auser] FTP command: Client "e.f.g.h", "RETR adis/afile"
Aug  7 11:24:35 ftphost vsftpd: Thu Aug  7 11:24:35 2014 [pid 16086] [auser] FTP response: Client "e.f.g.h", "150 Opening BINARY mode data connection for adis/afile (17706 bytes)."
Aug  7 11:29:15 ftphost vsftpd: Thu Aug  7 11:29:15 2014 [pid 16082] [auser] OK DOWNLOAD: Client "e.f.g.h", "/adis/afile", 17706 bytes, 0.06Kbyte/sec
Aug  7 11:29:15 ftphost vsftpd: Thu Aug  7 11:29:15 2014 [pid 16082] [auser] FTP response: Client "e.f.g.h", "226 File send OK."
Aug  7 11:29:15 ftphost vsftpd: Thu Aug  7 11:29:15 2014 [pid 16082] [auser] FTP command: Client "e.f.g.h", "ÿôÿòABOR"
Aug  7 11:29:15 ftphost vsftpd: Thu Aug  7 11:29:15 2014 [pid 16082] [auser] FTP response: Client "e.f.g.h", "225 No transfer to ABOR."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16086] [auser] OK DOWNLOAD: Client "e.f.g.h", "/adis/afile", 17706 bytes, 0.06Kbyte/sec
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16086] [auser] FTP response: Client "e.f.g.h", "226 File send OK."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16086] [auser] FTP command: Client "e.f.g.h", "ÿôÿòABOR"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16086] [auser] FTP response: Client "e.f.g.h", "225 No transfer to ABOR."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16086] [auser] FTP command: Client "e.f.g.h", "QUIT"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16086] [auser] FTP response: Client "e.f.g.h", "221 Goodbye."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16100] CONNECT: Client "e.f.g.h"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16100] FTP response: Client "e.f.g.h", "220 Welcome message"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16100] FTP command: Client "e.f.g.h", "USER auser"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16100] [auser] FTP response: Client "e.f.g.h", "331 Please specify the password."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16100] [auser] FTP command: Client "e.f.g.h", "PASS <password>"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16099] [auser] OK LOGIN: Client "e.f.g.h"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP response: Client "e.f.g.h", "230 Login successful."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP command: Client "e.f.g.h", "TYPE I"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP response: Client "e.f.g.h", "200 Switching to Binary mode."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP command: Client "e.f.g.h", "PASV"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP response: Client "e.f.g.h", "227 Entering Passive Mode (a,b,c,d,117,97)"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP command: Client "e.f.g.h", "RETR adis/afile"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP response: Client "e.f.g.h", "150 Opening BINARY mode data connection for adis/afile (17706 bytes)."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] OK DOWNLOAD: Client "e.f.g.h", "/adis/afile", 17706 bytes, 409.88Kbyte/sec
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP response: Client "e.f.g.h", "226 File send OK."
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP command: Client "e.f.g.h", "QUIT"
Aug  7 11:29:35 ftphost vsftpd: Thu Aug  7 11:29:35 2014 [pid 16101] [auser] FTP response: Client "e.f.g.h", "221 Goodbye."

The switch will report a successful download:

aprompt# copy ftp://a.b.c.d/adir/afile running-config:
Destination filename [running-config]?
Accessing ftp://a.b.c.d/adir/afile...
Loading adis/afile !!!!
[OK - 17706/1024 bytes]

17706 bytes copied in 312.420 secs (57 bytes/sec)
aprompt#

I already tried many things like reloading the switch, restarting the
vsftp server, trying many paramters, but to no avail.

Reducing the "size" of the config file helped, like dividing it into
two files. But 17 KB shouldn't really be a problem, I think. :-)

Any hints appreciated,

Regards, Thomas

[Thomas.Meyer]

In a crosspost
(https://forums.suse.com/showthread.php?5144-weird-vsftp-timeout&p=23001#post23001),
I found out the following, with the help of Jens-U. Mozdzen
(jmozdzen@nde.ag):

The traces showed some peculiarities, like a [TCP Window Full] when
the ftp transfer was delayed. Also the Cisco client is using an "ABOR"
statement in each transfer, probably to make sure that connection is
cleaned up after the transfer.

Anyway, the issue only hits when the size of the downloaded file
exceeds 16 KB.

As the old ftp server still works well with these files, it appears to
be an issue with this quite old version of IOS 12.1(13)EA1c together
with the version of vsftpd: 2.0.7-4.25.1.

It also is not an host-dependant issue, as I tried several other
virtual and physical hosts.

As these switches will be replaced by newer ones in one or two years,
the following workaround would suffice for us: the generated config
file will now contain abbreviated versions of frequent keywords,
e.g. "int" for "interface" or "switchp" for "switchport". Thus we
managed to decrease the file size and the download will succeed
swiftly.