2006-07-23 strange FTP problem

from HTYP, the free directory anyone can edit if they can prove to me that they're not a spambot
Jump to navigation Jump to search

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 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.

gFTP 2.0.18, Copyright (C) 1998-2003 Brian Masney <masneybspam@spamgftpspam.spamorg>. 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 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...

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
351 5.539531    81.223.20.36          192.168.0.103         FTP      Response: 227 Entering Passive Mode (81,223,20,36,183,245).
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
378 7.988448    81.223.20.36          192.168.0.103         FTP      Response: 227 Entering Passive Mode (81,223,20,36,192,141).
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:

web1 "fitness" "coachsucks"
FTP app PASV non PASV non PASV non
Konqueror n n Y n Y n
gFTP n Y Y n Y Y
ftp n Y Y n Y Y
Retrieved from "https://htyp.org/mw/index.php?title=2006-07-23_strange_FTP_problem&oldid=7018"