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.
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 ftp 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?)
Session Logs
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(username): Authentication failure.
- @4000000044c22b112b0586e4 web1.l48.net (24.136.238.245[24.136.238.245]) - USER username: Login successful.
- @4000000044c22b112b07b57c web1.l48.net (24.136.238.245[24.136.238.245]) - Preparing to chroot to directory '/hsphere/local/home/username'
- @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(username): Authentication failure.
- @4000000044c38ab837d5b95c web1.l48.net (24.136.238.245[24.136.238.245]) - USER username: Login successful.
- @4000000044c38ab837d7b914 web1.l48.net (24.136.238.245[24.136.238.245]) - Preparing to chroot to directory '/hsphere/local/home/username'
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.
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 unsuccessfull attempt to connect to web1 using Konqueror.
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 username 384 11.295395 69.57.190.146 192.168.0.103 FTP Response: 331 Password required for username. 385 11.295571 192.168.0.103 69.57.190.146 FTP Request: pass password 387 11.343274 69.57.190.146 192.168.0.103 FTP Response: 230 User username 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 407 11.642731 69.57.190.146 192.168.0.103 FTP Response: 227 Entering Passive Mode (69,57,190,146,201,26). 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...