The following trace shows an FTP upload failing. The client (66.20.130.31) is a Windows ME client, the server is a Windows 2000 server running WAR-FTP.
Note in frame 20, the client has appended an extra carriage-return as indicated
by the '<0D>'.
The FTP server accepts this command, but then immediately generates
an error 500: 'Dunno how to inerperet (sp) empty lines'
Frame Status Source Address Dest. Address Size Rel. Time Delta Time Abs. Time Summary
[snip]
5 [66.20.130.31] [208.61.64.87] 74 0:00:05.055 0.076.793 02/22/2001 08:45:03 PM TCP: D=21 S=1044 SYN SEQ=225380419 LEN=0 WIN=60352
6 [208.61.64.87] [66.20.130.31] 74 0:00:05.055 0.000.543 02/22/2001 08:45:03 PM TCP: D=1044 S=21 SYN ACK=225380420 SEQ=3241861962 LEN=0 WIN=16384
7 [66.20.130.31] [208.61.64.87] 62 0:00:05.091 0.035.890 02/22/2001 08:45:03 PM TCP: D=21 S=1044 ACK=3241861963 WIN=64240
8 [208.61.64.87] [205.152.0.5] 93 0:00:05.122 0.030.386 02/22/2001 08:45:03 PM DNS: C ID=1077 OP=QUERY NAME=31.130.20.66.in-addr.arpa
9 [205.152.0.5] [208.61.64.87] 139 0:00:05.135 0.013.784 02/22/2001 08:45:03 PM DNS: R ID=1077 STAT=OK NAME=31.130.20.66.in-addr.arpa
10 [216.78.248.124] [208.61.64.87] 62 0:00:05.185 0.049.169 02/22/2001 08:45:03 PM TCP: D=80 S=1159 ACK=3236814260 WIN=64261
11 [208.61.64.87] [66.20.130.31] 233 0:00:05.583 0.398.194 02/22/2001 08:45:04 PM FTP: R PORT=1044 220-myNetwatchman
12 [66.20.130.31] [208.61.64.87] 77 0:00:05.625 0.041.875 02/22/2001 08:45:04 PM FTP: C PORT=1044 USER XXXXXXXX
13 [208.61.64.87] [66.20.130.31] 98 0:00:05.626 0.000.969 02/22/2001 08:45:04 PM FTP: R PORT=1044 331 User name okay, Need password.
14 [66.20.130.31] [208.61.64.87] 77 0:00:05.662 0.036.255 02/22/2001 08:45:04 PM FTP: C PORT=1044 PASS YYYYYYYY
15 [208.61.64.87] [66.20.130.31] 84 0:00:05.671 0.009.066 02/22/2001 08:45:04 PM FTP: R PORT=1044 230 User logged in.
16 [66.20.130.31] [208.61.64.87] 80 0:00:05.715 0.044.402 02/22/2001 08:45:04 PM FTP: C PORT=1044 CWD pub/incoming
17 [208.61.64.87] [66.20.130.31] 105 0:00:05.717 0.001.747 02/22/2001 08:45:04 PM FTP: R PORT=1044 250 "/pub/incoming" is current directory.
18 [66.20.130.31] [208.61.64.87] 70 0:00:05.760 0.042.620 02/22/2001 08:45:04 PM FTP: C PORT=1044 TYPE A
19 [208.61.64.87] [66.20.130.31] 82 0:00:05.760 0.000.831 02/22/2001 08:45:04 PM FTP: R PORT=1044 200 Type set to A.
20 [66.20.130.31] [208.61.64.87] 87 0:00:05.809 0.048.655 02/22/2001 08:45:04 PM FTP: C PORT=1044 PORT 66,20,130,31,4,21<0D>
21 [208.61.64.87] [66.20.130.31] 92 0:00:05.810 0.001.040 02/22/2001 08:45:04 PM FTP: R PORT=1044 200 PORT command successful.
22 [66.20.130.31] [208.61.64.87] 104 0:00:05.846 0.035.965 02/22/2001 08:45:04 PM FTP: C PORT=1044 STOR 2001022200username@bellsouth.net.ice
23 [208.61.64.87] [66.20.130.31] 130 0:00:05.847 0.000.431 02/22/2001 08:45:04 PM FTP: R PORT=1044 500 Please enter a command. Dunno how to interperet empty lines...
24 [208.61.64.87] [66.20.130.31] 70 0:00:05.850 0.003.063 02/22/2001 08:45:04 PM TCP: D=1045 S=20 SYN SEQ=3242108379 LEN=0 WIN=16384
25 [66.20.130.31] [208.61.64.87] 70 0:00:05.885 0.034.898 02/22/2001 08:45:04 PM TCP: D=20 S=1045 SYN ACK=3242108380 SEQ=225669211 LEN=0 WIN=65535
26 [208.61.64.87] [66.20.130.31] 62 0:00:05.885 0.000.358 02/22/2001 08:45:04 PM TCP: D=1045 S=20 ACK=225669212 WIN=16384
27 [66.20.130.31] [208.61.64.87] 104 0:00:05.888 0.003.378 02/22/2001 08:45:04 PM FTP: C PORT=1044 DELE 2001022200username@bellsouth.net.ice
28 [208.61.64.87] [66.20.130.31] 148 0:00:05.889 0.000.415 02/22/2001 08:45:04 PM FTP: R PORT=1044 125 Ready to receive "2001022200username@bellsouth.net.ice" . Mode STREAM Type ASCII.
29 [66.20.130.31] [208.61.64.87] 62 0:00:05.921 0.032.495 02/22/2001 08:45:04 PM TCP: D=20 S=1045 FIN ACK=3242108380 SEQ=225669212 LEN=0 WIN=65535
30 [208.61.64.87] [66.20.130.31] 62 0:00:05.921 0.000.304 02/22/2001 08:45:04 PM TCP: D=1045 S=20 ACK=225669213 WIN=16384
31 [66.20.130.31] [208.61.64.87] 62 0:00:05.947 0.025.111 02/22/2001 08:45:04 PM TCP: D=21 S=1044 FIN ACK=3241862439 SEQ=225380585 LEN=0 WIN=64121
32 [208.61.64.87] [66.20.130.31] 62 0:00:05.947 0.000.323 02/22/2001 08:45:04 PM TCP: D=1044 S=21 ACK=225380586 WIN=16219
33 [208.61.64.87] [66.20.130.31] 62 0:00:05.953 0.006.242 02/22/2001 08:45:04 PM TCP: D=1045 S=20 FIN ACK=225669213 SEQ=3242108380 LEN=0 WIN=16384
34 [208.61.64.87] [66.20.130.31] 120 0:00:05.955 0.001.410 02/22/2001 08:45:04 PM FTP: R PORT=1044 226 Transfer complete. 0 bytes in 0.08 sec. (0.000 Kb/s)
35 [208.61.64.87] [66.20.130.31] 141 0:00:05.963 0.008.879 02/22/2001 08:45:04 PM FTP: R PORT=1044 250 "/pub/incoming/2001022200username@bellsouth.net.ice" successfully deleted.
36 [66.20.130.31] [208.61.64.87] 62 0:00:05.986 0.022.317 02/22/2001 08:45:04 PM TCP: D=20 S=1045 ACK=3242108381 WIN=65535
37 [66.20.130.31] [208.61.64.87] 62 0:00:05.992 0.005.900 02/22/2001 08:45:04 PM TCP: D=21 S=1044 RST WIN=0
38 [66.20.130.31] [208.61.64.87] 62 0:00:06.001 0.009.618 02/22/2001 08:45:04 PM TCP: D=21 S=1044 RST WIN=0
Section 4.1.3 of RFC 959
indicates that all FTP commands should be terminated with a single <CR><LF>.
This supurious <CR> appears to be a protocol violation.
Here is the detail of Frame 20:
Frame Status Source Address Dest. Address Size Rel. Time Delta Time Abs. Time Summary
20 [66.20.130.31] [208.61.64.87] 87 0:00:05.809 0.048.655 02/22/2001 08:45:04 PM FTP: C PORT=1044 PORT 66,20,130,31,4,21<0D>
DLC: ----- DLC Header -----
DLC:
DLC: Frame 20 arrived at 20:45:04.5169; frame size is 87 (0057 hex) bytes.
DLC: Destination = Station Intel 2411A7
DLC: Source = Station 001067008D8A
DLC: Ethertype = 8864
DLC:
PPPOE: ----- PPPoE Header -----
PPPOE:
PPPOE: Ethernet Type= (0x8864) "PPP Session Stage"
PPPOE: Version = 1
PPPOE: Type = 1
PPPOE: Code = 0
PPPOE: Session ID = 15626
PPPOE: Payload length = 67
PPPOE: --- Payload In Session Stage---
PPPOE:
PPP: ----- Point-to-Point Protocol -----
PPP:
PPP: Protocol = 0021 (Internet)
PPP:
IP: ----- IP Header -----
IP:
IP: Version = 4, header length = 20 bytes
IP: Type of service = 00
IP: 000. .... = routine
IP: ...0 .... = normal delay
IP: .... 0... = normal throughput
IP: .... .0.. = normal reliability
IP: .... ..0. = ECT bit - transport protocol will ignore the CE bit
IP: .... ...0 = CE bit - no congestion
IP: Total length = 65 bytes
IP: Identification = 608
IP: Flags = 4X
IP: .1.. .... = don't fragment
IP: ..0. .... = last fragment
IP: Fragment offset = 0 bytes
IP: Time to live = 55 seconds/hops
IP: Protocol = 6 (TCP)
IP: Header checksum = 6C8F (correct)
IP: Source address = [66.20.130.31]
IP: Destination address = [208.61.64.87]
IP: No options
IP:
TCP: ----- TCP header -----
TCP:
TCP: Source port = 1044
TCP: Destination port = 21 (FTP)
TCP: Sequence number = 225380476
TCP: Next expected Seq number= 225380501
TCP: Acknowledgment number = 3241862255
TCP: Data offset = 20 bytes
TCP: Flags = 18
TCP: ..0. .... = (No urgent pointer)
TCP: ...1 .... = Acknowledgment
TCP: .... 1... = Push
TCP: .... .0.. = (No reset)
TCP: .... ..0. = (No SYN)
TCP: .... ...0 = (No FIN)
TCP: Window = 64167
TCP: Checksum = BB23 (correct)
TCP: No TCP options
TCP: [25 Bytes of data]
TCP:
FTP: ----- File Transfer Data Protocol -----
FTP:
FTP: Line 1: PORT 66,20,130,31,4,21<0D>
FTP:
ADDR HEX ASCII
0000: 00 a0 c9 24 11 a7 00 10 67 00 8d 8a 88 64 11 00 | .$...g.d..
0010: 0a 3d 00 43 00 21 45 00 00 41 02 60 40 00 37 06 | .=.C.!E..A.`@.7.
0020: 6c 8f 42 14 82 1f d0 3d 40 57 04 14 00 15 0d 6f | lB..=@W.....o
0030: 08 7c c1 3a e4 6f 50 18 fa a7 bb 23 00 00 50 4f | .|:oP.#..PO
0040: 52 54 20 36 36 2c 32 30 2c 31 33 30 2c 33 31 2c | RT 66,20,130,31,
0050: 34 2c 32 31 0d 0d 0a | 4,21...
But what is causing it?
Kudos to Josh Rhinehart for theorizing that Microsoft Internet Connection Sharing (ICS) could be at play.
Sure enough, here is the same point in the trace but with ICS is disabled:
Frame Status Source Address Dest. Address Size Rel. Time Delta Time Abs. Time Summary
143 [66.20.130.60] [208.61.64.87] 87 0:02:44.317 0.048.326 02/23/2001 11:32:31 AM FTP: C PORT=1248 PORT 66,20,130,60,4,225
DLC: ----- DLC Header -----
DLC:
DLC: Frame 143 arrived at 11:32:31.4602; frame size is 87 (0057 hex) bytes.
DLC: Destination = Station Intel 2411A7
DLC: Source = Station 001067008D8A
DLC: Ethertype = 8864
DLC:
PPPOE: ----- PPPoE Header -----
PPPOE:
PPPOE: Ethernet Type= (0x8864) "PPP Session Stage"
PPPOE: Version = 1
PPPOE: Type = 1
PPPOE: Code = 0
PPPOE: Session ID = 15626
PPPOE: Payload length = 67
PPPOE: --- Payload In Session Stage---
PPPOE:
PPP: ----- Point-to-Point Protocol -----
PPP:
PPP: Protocol = 0021 (Internet)
PPP:
IP: ----- IP Header -----
IP:
IP: Version = 4, header length = 20 bytes
IP: Type of service = 00
IP: 000. .... = routine
IP: ...0 .... = normal delay
IP: .... 0... = normal throughput
IP: .... .0.. = normal reliability
IP: .... ..0. = ECT bit - transport protocol will ignore the CE bit
IP: .... ...0 = CE bit - no congestion
IP: Total length = 65 bytes
IP: Identification = 19490
IP: Flags = 4X
IP: .1.. .... = don't fragment
IP: ..0. .... = last fragment
IP: Fragment offset = 0 bytes
IP: Time to live = 55 seconds/hops
IP: Protocol = 6 (TCP)
IP: Header checksum = 22B0 (correct)
IP: Source address = [66.20.130.60]
IP: Destination address = [208.61.64.87]
IP: No options
IP:
TCP: ----- TCP header -----
TCP:
TCP: Source port = 1248
TCP: Destination port = 21 (FTP)
TCP: Sequence number = 588815783
TCP: Next expected Seq number= 588815808
TCP: Acknowledgment number = 3903336860
TCP: Data offset = 20 bytes
TCP: Flags = 18
TCP: ..0. .... = (No urgent pointer)
TCP: ...1 .... = Acknowledgment
TCP: .... 1... = Push
TCP: .... .0.. = (No reset)
TCP: .... ..0. = (No SYN)
TCP: .... ...0 = (No FIN)
TCP: Window = 64167
TCP: Checksum = 73C7 (correct)
TCP: No TCP options
TCP: [25 Bytes of data]
TCP:
FTP: ----- File Transfer Data Protocol -----
FTP:
FTP: Line 1: PORT 66,20,130,60,4,225
FTP:
ADDR HEX ASCII
0000: 00 a0 c9 24 11 a7 00 10 67 00 8d 8a 88 64 11 00 | .$...g.d..
0010: 0a 3d 00 43 00 21 45 00 00 41 4c 22 40 00 37 06 | .=.C.!E..AL"@.7.
0020: 22 b0 42 14 82 3c d0 3d 40 57 04 e0 00 15 23 18 | "B.<=@W...#.
0030: 9d a7 e8 a8 31 9c 50 18 fa a7 73 c7 00 00 50 4f | 1P.s..PO
0040: 52 54 20 36 36 2c 32 30 2c 31 33 30 2c 36 30 2c | RT 66,20,130,60,
0050: 34 2c 32 32 35 0d 0a | 4,225..
And, as you can see, now the upload is successful:
Frame Status Source Address Dest. Address Size Rel. Time Delta Time Abs. Time Summary 134 [208.61.64.87] [66.20.130.60] 233 0:02:44.037 0.653.452 02/23/2001 11:32:31 AM FTP: R PORT=1248 220-myNetwatchman 135 [66.20.130.60] [208.61.64.87] 77 0:02:44.087 0.049.944 02/23/2001 11:32:31 AM FTP: C PORT=1248 USER XXXXXXXXXXX 136 [208.61.64.87] [66.20.130.60] 98 0:02:44.099 0.012.299 02/23/2001 11:32:31 AM FTP: R PORT=1248 331 User name okay, Need password. 137 [66.20.130.60] [208.61.64.87] 77 0:02:44.154 0.054.512 02/23/2001 11:32:31 AM FTP: C PORT=1248 PASS YYYYYYYYYYY 138 [208.61.64.87] [66.20.130.60] 84 0:02:44.162 0.008.714 02/23/2001 11:32:31 AM FTP: R PORT=1248 230 User logged in. 139 [66.20.130.60] [208.61.64.87] 80 0:02:44.207 0.044.955 02/23/2001 11:32:31 AM FTP: C PORT=1248 CWD pub/incoming 140 [208.61.64.87] [66.20.130.60] 105 0:02:44.209 0.001.556 02/23/2001 11:32:31 AM FTP: R PORT=1248 250 "/pub/incoming" is current directory. 141 [66.20.130.60] [208.61.64.87] 70 0:02:44.266 0.056.865 02/23/2001 11:32:31 AM FTP: C PORT=1248 TYPE A 142 [208.61.64.87] [66.20.130.60] 82 0:02:44.269 0.003.157 02/23/2001 11:32:31 AM FTP: R PORT=1248 200 Type set to A. 143 [66.20.130.60] [208.61.64.87] 87 0:02:44.317 0.048.326 02/23/2001 11:32:31 AM FTP: C PORT=1248 PORT 66,20,130,60,4,225 144 [208.61.64.87] [66.20.130.60] 92 0:02:44.318 0.001.046 02/23/2001 11:32:31 AM FTP: R PORT=1248 200 PORT command successful. 145 [66.20.130.60] [208.61.64.87] 104 0:02:44.367 0.049.248 02/23/2001 11:32:31 AM FTP: C PORT=1248 STOR 2001022300username@bellsouth.net.ice 146 [208.61.64.87] [66.20.130.60] 148 0:02:44.370 0.002.464 02/23/2001 11:32:31 AM FTP: R PORT=1248 125 Ready to receive "2001022300username@bellsouth.net.ice" . Mode STREAM Type ASCII. 147 [208.61.64.87] [66.20.130.60] 70 0:02:44.371 0.001.412 02/23/2001 11:32:31 AM TCP: D=1249 S=20 SYN SEQ=3903668203 LEN=0 WIN=16384 148 [66.20.130.60] [208.61.64.87] 70 0:02:44.422 0.050.545 02/23/2001 11:32:31 AM TCP: D=20 S=1249 SYN ACK=3903668204 SEQ=589129296 LEN=0 WIN=65535 149 [208.61.64.87] [66.20.130.60] 62 0:02:44.422 0.000.380 02/23/2001 11:32:31 AM TCP: D=1249 S=20 ACK=589129297 WIN=16968 150 [66.20.130.60] [208.61.64.87] 137 0:02:44.477 0.054.657 02/23/2001 11:32:31 AM FTP: C PORT=20 Text Data 151 [66.20.130.60] [208.61.64.87] 62 0:02:44.572 0.095.224 02/23/2001 11:32:31 AM TCP: D=21 S=1248 ACK=3903336976 WIN=64138 152 [208.61.64.87] [66.20.130.60] 62 0:02:44.640 0.067.390 02/23/2001 11:32:31 AM TCP: D=1249 S=20 ACK=589129372 WIN=16893 153 [66.20.130.60] [208.61.64.87] 434 0:02:44.699 0.059.731 02/23/2001 11:32:31 AM FTP: C PORT=20 Text Data 154 [208.61.64.87] [66.20.130.60] 62 0:02:44.841 0.141.462 02/23/2001 11:32:31 AM TCP: D=1249 S=20 ACK=589129744 WIN=16521 155 [66.20.130.60] [208.61.64.87] 62 0:02:44.888 0.047.282 02/23/2001 11:32:32 AM TCP: D=20 S=1249 FIN ACK=3903668204 SEQ=589129744 LEN=0 WIN=65535 156 [208.61.64.87] [66.20.130.60] 62 0:02:44.888 0.000.396 02/23/2001 11:32:32 AM TCP: D=1249 S=20 ACK=589129745 WIN=16521 157 [208.61.64.87] [66.20.130.60] 62 0:02:44.889 0.000.600 02/23/2001 11:32:32 AM TCP: D=1249 S=20 FIN ACK=589129745 SEQ=3903668204 LEN=0 WIN=16521 158 [208.61.64.87] [66.20.130.60] 122 0:02:44.891 0.001.732 02/23/2001 11:32:32 AM FTP: R PORT=1248 226 Transfer complete. 447 bytes in 0.47 sec. (0.931 Kb/s)
In conclusion, this appears to be an ICS bug which I will be reporting to Microsoft. This particular case shows the problems that happen specifically when uploading to a WAR-FTP server. Similar behavior may or may not occur with other FTP server implementations.