2006-07-23 strange FTP problem

Introduction
I'm documenting this problem so that (a) if we manage to fix it, others with a similar problem may be able to benefit, and (b) if we don't manage to fix it, maybe someone else will be able to figure out what's going on.

Status
2006-07-25 It's looking very much like some kind of network problem over on the host's side; awaiting resolution from the web hosting people. A few mysteries remain, like why does non-PASV mode work at all, when we're operating from behind a NAT router? What is the difference between the way kio_ftp does ftp and the way everybody else seems to do it, which causes kio_ftp to fail under circumstances where other ftp clients seem to work fine? What is different about the one site which kio_ftp is totally unable to work with?

Description
Some FTP clients can connect to a particular server, while others can't. Specifically, Konqueror's ftp, which seems to use the kio_ftp kioslave, cannot; CLI-based ftp can, and so can gFTP.

Konqueror shows "Login Ok" in the taskbar, and then a dialog pops up to say it can't connect. This happens more quickly if KDE's ftp is set to not use PASV mode; if PASV mode is on, it takes 30-60 seconds.

Apparently Konqueror is actually connecting, but is unable to retrieve a directory listing.

This problem started suddenly. A similar problem had happened in the past, and had always been cured by rebooting; the similarity may be deceptive, however, as I don't remember seeing the "Login Ok".

Brief History
About 5 days ago (at a guess), Konqueror suddenly stopped being able to connect to my web server (as described above). I tried rebooting, then tried turning off and rebooting, but no go. I finally set up a completely new system (I needed to update from Ubuntu Warty or Hoary or whatever it was to the latest, Dapper). The problem remained, unaltered.

I finally tried connecting from Konqueror on a different system, and had the same problem. (An ftp server log shows much the same sequence of events for this attempt.)

Back on my system, however, the CLI version of continued to work, as did a non-kioslave-based GUI ftp program, gFTP. Neither one of them would work in PASV mode, however; they would both connect, but then time out waiting for a directory listing (issued automatically from gFTP and manually from CLI ftp).

Theories

 * The EPRT request puts ftpd into some weird state where it decides it should refuse the subsequent PORT.
 * The NAT firmware inside the router is failing to detect and update the FTP request (changing the local address, 192.168.0.103, into the public/Internet address) in some cases, but not in others. (Perhaps the router is unhappy with the EPRT command?)

ftpd logs
This is the ftp server's log of an unsuccessful connection attempt from Konqueror.


 * @4000000044c22b112afaa5bc web1.l48.net (24.136.238.245[24.136.238.245]) - PAM(): Authentication failure.
 * @4000000044c22b112b0586e4 web1.l48.net (24.136.238.245[24.136.238.245]) - USER : Login successful.
 * @4000000044c22b112b07b57c web1.l48.net (24.136.238.245[24.136.238.245]) - Preparing to chroot to directory '/hsphere/local/home/'
 * @4000000044c22b112b0b301c web1.l48.net (24.136.238.245[24.136.238.245]) - mod_delay/0.5: delaying for 80 usecs
 * @4000000044c22b113920dae4 web1.l48.net (24.136.238.245[24.136.238.245]) - Refused EPRT |1|192.168.0.103|57302| (address mismatch)
 * @4000000044c22b113b43f194 web1.l48.net (24.136.238.245[24.136.238.245]) - Refused PORT 192,168,0,103,143,41 (address mismatch)
 * @4000000044c22b1201eeaeac web1.l48.net (24.136.238.245[24.136.238.245]) - Refused PORT 192,168,0,103,223,197 (address mismatch)

This is the ftp server's log of a successful connection from gFTP:


 * @4000000044c38ab831343eac web1.l48.net (24.136.238.245[24.136.238.245]) - FTP session opened.
 * @4000000044c38ab837cb93b4 web1.l48.net (24.136.238.245[24.136.238.245]) - PAM(): Authentication failure.
 * @4000000044c38ab837d5b95c web1.l48.net (24.136.238.245[24.136.238.245]) - USER : Login successful.
 * @4000000044c38ab837d7b914 web1.l48.net (24.136.238.245[24.136.238.245]) - Preparing to chroot to directory '/hsphere/local/home/'

gFTP non-PASV
This shows gFTP's session log from a successful connection in non-PASV mode. gFTP also retrieves a directory listing, downloads a file, and then uploads it again. Note that gFTP executes a PORT command similar to the one tried by Konqueror, above; the ftp server refuses Konq's attempt, but allows gFTP's.


 * gFTP 2.0.18, Copyright (C) 1998-2003 Brian Masney &lt;masneyb@gftp&gt;. If you have any questions, comments, or suggestions about this program, please feel free to email them to me. You can always find out the latest news about gFTP from my website at http://www.gftp.org/
 * gFTP comes with ABSOLUTELY NO WARRANTY; for details, see the COPYING file. This is free software, and you are welcome to redistribute it under certain conditions; for details, see the COPYING file

Looking up web1.l48.net Trying web1.l48.net:21 Connected to web1.l48.net:21 220 ProFTPD 1.3.0 Server (Main FTP Server) [69.57.190.146] USER hypertwi 331 Password required for hypertwi. PASS xxxx 230 User [redacted] logged in. SYST 215 UNIX Type: L8 TYPE I 200 Type set to I PWD 257 "/" is current directory. Loading directory listing / from server (LC_TIME=en_US.UTF-8) PORT 192,168,0,103,132,153 200 PORT command successful LIST -aL 150 Opening ASCII mode data connection for file list 226 Transfer complete. CWD /psycrit.com 250 CWD command successful PWD 257 "/psycrit.com" is current directory. Loading directory listing /psycrit.com from server (LC_TIME=en_US.UTF-8) PORT 192,168,0,103,199,177 200 PORT command successful LIST -aL 150 Opening ASCII mode data connection for file list 226 Transfer complete. Successfully changed local directory to /home/woozle/Scratch PORT 192,168,0,103,175,22 200 PORT command successful RETR /psycrit.com/favicon.ico 150 Opening BINARY mode data connection for /psycrit.com/favicon.ico (2686 bytes) 226 Transfer complete. Successfully transferred /psycrit.com/favicon.ico at 19.28 KB/s Successfully changed mode of /home/woozle/Scratch/favicon.ico to 644 Loading directory listing /psycrit.com from server (LC_TIME=en_US.UTF-8) PORT 192,168,0,103,223,164 200 PORT command successful LIST -aL 150 Opening ASCII mode data connection for file list 226 Transfer complete. PORT 192,168,0,103,224,144 200 PORT command successful STOR /psycrit.com/favicon.ico 150 Opening BINARY mode data connection for /psycrit.com/favicon.ico 226 Transfer complete. Successfully transferred /home/woozle/Scratch/favicon.ico at 23.14 KB/s SITE CHMOD 644 /psycrit.com/favicon.ico 200 SITE CHMOD command successful SITE UTIME 20060716145700 /psycrit.com/favicon.ico 500 'SITE UTIME' not understood Loading directory listing /psycrit.com from server (LC_TIME=en_US.UTF-8) PORT 192,168,0,103,159,71 200 PORT command successful LIST -aL 150 Opening ASCII mode data connection for file list 226 Transfer complete.

Konq PASV unsuccessful connect to web1
This shows the highlights of a network capture (using ethereal) of an unsuccessful attempt to connect to web1 using Konqueror.

#    Time        Source              Destination        Protocol   Info 368 11.083826  192.168.0.103         69.57.190.146         TCP      49724 > ftp [SYN] Seq=0 Len=0 370 11.118788  69.57.190.146         192.168.0.103         TCP      ftp > 49724 [SYN, ACK] Seq=0 371 11.118859  192.168.0.103         69.57.190.146         TCP      49724 > ftp [ACK] Seq=1 Ack=1 Win=5840 Len=0 372 11.153749  69.57.190.146         192.168.0.103         FTP      Response: 220 ProFTPD 1.3.0 Server (Main FTP Server) [69.57.190.146] 373 11.153844  192.168.0.103         69.57.190.146         TCP      49724 > ftp [ACK] Seq=1 Ack=61 Win=5840 Len=0 374 11.154112  192.168.0.103         69.57.190.146         FTP      Request: user anonymous 375 11.192756  69.57.190.146         192.168.0.103         TCP      ftp > 49724 [ACK] Seq=61 Ack=17 Win=5840 Len=0 377 11.198699  69.57.190.146         192.168.0.103         FTP      Response: 331 Password required for anonymous. 378 11.198911  192.168.0.103         69.57.190.146         FTP      Request: pass anonymous@ 382 11.238614  69.57.190.146         192.168.0.103         FTP      Response: 530 Login incorrect. 383 11.260870  192.168.0.103         69.57.190.146         FTP      Request: user  384 11.295395  69.57.190.146         192.168.0.103         FTP      Response: 331 Password required for . 385 11.295571  192.168.0.103         69.57.190.146         FTP      Request: pass  387 11.343274  69.57.190.146         192.168.0.103         FTP      Response: 230 User  logged in. 388 11.348848  192.168.0.103         69.57.190.146         FTP      Request: syst 392 11.382635  69.57.190.146         192.168.0.103         FTP      Response: 215 UNIX Type: L8 393 11.382836   192.168.0.103         69.57.190.146         FTP      Request: pwd 394 11.417350  69.57.190.146         192.168.0.103         FTP      Response: 257 "/" is current directory. 398 11.456239  192.168.0.103         69.57.190.146         TCP      49724 > ftp [ACK] Seq=77 Ack=238 Win=5840 Len=0 400 11.569313  192.168.0.103         69.57.190.146         FTP      Request: TYPE I 403 11.603530   69.57.190.146         192.168.0.103         FTP      Response: 200 Type set to I 404 11.603639   192.168.0.103         69.57.190.146         TCP      49724 > ftp [ACK] Seq=85 Ack=257 Win=5840 Len=0 405 11.603798  192.168.0.103         69.57.190.146         FTP      Request: PASV 408 11.643373  192.168.0.103         69.57.190.146         TCP      37038 > 51482 [SYN] Seq=0 Len=0 MSS=1460 TSV=59633711 TSER=0 WS=2 409 11.680245  192.168.0.103         69.57.190.146         TCP      49724 > ftp [ACK] Seq=91 Ack=308 Win=5840 Len=0 483 13.746226  69.57.190.146         192.168.0.103         TCP      51482 > 37038 [RST] Seq=0 Len=0 505 14.640445  192.168.0.103         69.57.190.146         TCP      37038 > 51482 [SYN] Seq=0 Len=0 MSS=1460 TSV=59634461 TSER=0 WS=2 548 15.968185  69.57.190.146         192.168.0.103         TCP      51482 > 37038 [RST] Seq=0 Len=0 712 20.640799  192.168.0.103         69.57.190.146         TCP      37038 > 51482 [SYN] Seq=0 Len=0 MSS=1460 TSV=59635961 TSER=0 WS=2 776 22.641978  69.57.190.146         192.168.0.103         TCP      51482 > 37038 [RST] Seq=0 Len=0

It looks like the connection runs into some sort of trouble after the PASV request is acknowledged, with SYN and RST requests going back and forth...

Konq PASV successful connect to proftp
This shows the highlights of a network capture (using ethereal) of a successful connection to ftp.proftpd.org using Konqueror.

#    Time        Source              Destination        Protocol   Info 346 5.404721   192.168.0.103         81.223.20.36          FTP      Request: PASV 352 5.539651   192.168.0.103         81.223.20.36          TCP      52636 > ftp [ACK] Seq=6 Ack=51 Win=1460 Len=0 TSV=59575008 TSER=177550492 353 5.540226   192.168.0.103         81.223.20.36          TCP      38204 > 47093 [SYN] Seq=0 Len=0 MSS=1460 TSV=59575008 TSER=0 WS=2 357 5.678703   81.223.20.36          192.168.0.103         TCP      47093 > 38204 [SYN, ACK] Seq=0 Ack=1 Win=2965504 Len=0 MSS=1460 TSV=177550526 TSER=59575008 WS=9 358 5.678762   192.168.0.103         81.223.20.36          TCP      38204 > 47093 [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSV=59575042 TSER=177550526 359 5.678987   192.168.0.103         81.223.20.36          FTP      Request: list -la 362 5.812019   81.223.20.36          192.168.0.103         FTP      Response: 150 Opening ASCII mode data connection for file list 363 5.812673   192.168.0.103         81.223.20.36          TCP      52636 > ftp [ACK] Seq=16 Ack=105 Win=1460 Len=0 TSV=59575076 TSER=177550559 365 5.913310   81.223.20.36          192.168.0.103         FTP-DATA FTP Data: 395 bytes 366 5.913361   192.168.0.103         81.223.20.36          TCP      38204 > 47093 [ACK] Seq=1 Ack=396 Win=6912 Len=0 TSV=59575101 TSER=177550585 367 5.913378   81.223.20.36          192.168.0.103         TCP      47093 > 38204 [FIN, ACK] Seq=396 Ack=1 Win=6144 Len=0 TSV=177550585 TSER=59575042 368 5.913805   192.168.0.103         81.223.20.36          TCP      38204 > 47093 [FIN, ACK] Seq=1 Ack=397 Win=6912 Len=0 TSV=59575101 TSER=177550585 373 6.040581   81.223.20.36          192.168.0.103         TCP      47093 > 38204 [ACK] Seq=397 Ack=2 Win=6144 Len=0 TSV=177550617 TSER=59575101 390 6.259314   81.223.20.36          192.168.0.103         FTP      Response: 226 Transfer complete. 391 6.263031   192.168.0.103         81.223.20.36          TCP      52636 > ftp [ACK] Seq=16 Ack=129 Win=1460 Len=0 TSV=59575189 TSER=177550671

gFTP successful connect to proftp
314 6.910068   192.168.0.103         81.223.20.36          TCP      55520 > ftp [SYN] Seq=0 Len=0 MSS=1460 TSV=61997693 TSER=0 WS=2 321 7.034283   81.223.20.36          192.168.0.103         TCP      ftp > 55520 [SYN, ACK] Seq=0 Ack=1 Win=2965504 Len=0 MSS=1460 TSV=179972097 TSER=61997693 WS=9 322 7.034350   192.168.0.103         81.223.20.36          TCP      55520 > ftp [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSV=61997724 TSER=179972097 329 7.162815   81.223.20.36          192.168.0.103         FTP      Response: 220 ProFTPD 1.3.0 Server (proftpd.org Project) [81.223.20.36] 330 7.162840   192.168.0.103         81.223.20.36          TCP      55520 > ftp [ACK] Seq=1 Ack=64 Win=5840 Len=0 TSV=61997756 TSER=179972130 331 7.162957   192.168.0.103         81.223.20.36          FTP      Request: USER anonymous 337 7.298095   81.223.20.36          192.168.0.103         TCP      ftp > 55520 [ACK] Seq=64 Ack=17 Win=6144 Len=0 TSV=179972163 TSER=61997756 338 7.302613   81.223.20.36          192.168.0.103         FTP      Response: 331 Anonymous login ok, send your complete email address as your password. 339 7.306667   192.168.0.103         81.223.20.36          FTP      Request: PASS woozle@gonzo 344 7.435320   81.223.20.36          192.168.0.103         FTP      Response: 230 Anonymous access granted, restrictions apply. 345 7.438445   192.168.0.103         81.223.20.36          FTP      Request: SYST 351 7.563930   81.223.20.36          192.168.0.103         FTP      Response: 215 UNIX Type: L8 352 7.564345    192.168.0.103         81.223.20.36          FTP      Request: TYPE I 356 7.697765    81.223.20.36          192.168.0.103         FTP      Response: 200 Type set to I 357 7.697920    192.168.0.103         81.223.20.36          FTP      Request: PWD 363 7.822278   81.223.20.36          192.168.0.103         FTP      Response: 257 "/" is current directory. 371 7.859706   192.168.0.103         81.223.20.36          TCP      55520 > ftp [ACK] Seq=55 Ack=260 Win=5840 Len=0 TSV=61997931 TSER=179972294 372 7.864242   192.168.0.103         81.223.20.36          FTP      Request: PASV 379 7.988521   192.168.0.103         81.223.20.36          TCP      55520 > ftp [ACK] Seq=61 Ack=311 Win=5840 Len=0 TSV=61997963 TSER=179972336 380 7.988625   192.168.0.103         81.223.20.36          TCP      37975 > 49293 [SYN] Seq=0 Len=0 MSS=1460 TSV=61997963 TSER=0 WS=2 390 8.115522   81.223.20.36          192.168.0.103         TCP      49293 > 37975 [SYN, ACK] Seq=0 Ack=1 Win=2965504 Len=0 MSS=1460 TSV=179972368 TSER=61997963 WS=9 391 8.115589   192.168.0.103         81.223.20.36          TCP      37975 > 49293 [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSV=61997994 TSER=179972368 392 8.115742   192.168.0.103         81.223.20.36          FTP      Request: LIST -aL 394 8.246438   81.223.20.36          192.168.0.103         FTP      Response: 150 Opening ASCII mode data connection for file list 395 8.246553   192.168.0.103         81.223.20.36          TCP      55520 > ftp [ACK] Seq=71 Ack=365 Win=5840 Len=0 TSV=61998027 TSER=179972400 396 8.256017   81.223.20.36          192.168.0.103         FTP-DATA FTP Data: 395 bytes 397 8.256048   192.168.0.103         81.223.20.36          TCP      37975 > 49293 [ACK] Seq=1 Ack=396 Win=6912 Len=0 TSV=61998030 TSER=179972403 398 8.256091   81.223.20.36          192.168.0.103         TCP      49293 > 37975 [FIN, ACK] Seq=396 Ack=1 Win=6144 Len=0 TSV=179972403 TSER=61997994 399 8.256459   192.168.0.103         81.223.20.36          TCP      37975 > 49293 [FIN, ACK] Seq=1 Ack=397 Win=6912 Len=0 TSV=61998030 TSER=179972403 403 8.383292   81.223.20.36          192.168.0.103         TCP      49293 > 37975 [ACK] Seq=397 Ack=2 Win=6144 Len=0 TSV=179972435 TSER=61998030 404 8.383700   81.223.20.36          192.168.0.103         FTP      Response: 226 Transfer complete. 405 8.383772   192.168.0.103         81.223.20.36          TCP      55520 > ftp [ACK] Seq=71 Ack=389 Win=5840 Len=0 TSV=61998062 TSER=179972435

Different Servers
Comparison of web1 versus two other servers, trying 3 different FTP programs: