weird vsftp timeout

SUSE Linux Enterprise Server SLES Configure-Administer
1

see also https://supportforums.cisco.com/discussion/12273846/queer-ftp-load-configuration-issue-hitting-five-minute-timeout-successful

Who can help with this queer ftp transfer problem?

After moving from another non-Linux ftp server to vsftp on SLES 11
(version is vsftpd-2.0.7-4.25.1), two out of ten Cisco catalyst 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 these switches 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:

[CODE]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#
[/CODE]
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. :slight_smile:

Any hints appreciated,

Regards, Thomas

2

Hi Thomas,

were you able to capture the actual network traffic, at least from the FTP server side? It should be interesting to see if there are any errors reported, or where the actual delay comes from (does the server hand out packets immediately upon request, are ACKs send timely from the switches etc)…

With 17kB, you should be able to capture all related traffic :wink:

Regards,
Jens

3

Jens, thanks for replying.

I captured both a “normal” ftp transfer from one of the unproblematic
switches and one of the five-minute-delay switches. Wireshark shows a
[TCP Window Full] after a few exchanges on “FTP Data channel”.

While the Expert info of the normal transmission will list no errors
and no warnings, for the problematic one, we see three warnings:

TCP: Window is full
TCP: Zero window
TCP: ACKed segment that wasn’t captured (common at capture start)

How would you suggest to proceed further in the analysis of this
issue?

Regards, Thomas

4

Hi Thomas,

[QUOTE=swadm;23013]Jens, thanks for replying.

I captured both a “normal” ftp transfer from one of the unproblematic
switches and one of the five-minute-delay switches. Wireshark shows a
[TCP Window Full] after a few exchanges on “FTP Data channel”.

While the Expert info of the normal transmission will list no errors
and no warnings, for the problematic one, we see three warnings:

TCP: Window is full
TCP: Zero window
TCP: ACKed segment that wasn’t captured (common at capture start)

How would you suggest to proceed further in the analysis of this
issue?

Regards, Thomas[/QUOTE]

the question is, which side does not respond (or not timely). I can offer to take a close look if you’re free to send me the trace (might contain sensitive data - FYI: I’m under NDA from Novell).

Are you familiar with what should be going on at the wire level? Then try to compare that to what you actually see in the trace - who’s behaving “bad”? If it’s the server side, your trace should be helpful to get an idea of what happens. If it’s the client (switch) side that is not responding correctly, then the problem might be the switch - but it might be some part of the infrastructure as well.

Have you run a longer-term ping from the server to the switch lately, to see if during some 5 or 10 minute interval, all ICMP requests got a proper response? That could serve to rule out the very basic network problems, like routing loops and duplicate IPs.

Regards,
Jens

5

Jens, thanks for looking at the traces.
With your help, I came to the following facts and conclusions:

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.

Thanks, again, Jens!