Re: [squid-users] 3.1.16 FTP problems ..
On 8/11/2011 9:25 p.m., Paul Regan wrote: Thanks for the reply, will open the bugzilla .. Some further info is I just tried the same using a 3.0 stable13 server with the same results. I haven't run a wire trace but cache.log reports the same error : ftpDataRead: read error: (107) Transport endpoint is not connected Paul Good to know its not a new regression at least. While I think of it, with 3.1 you can get a "debug_options 9,2" trace in cache.log of the FTP control channel events. That may be useful to go with the report. Amos On 7 November 2011 22:37, Amos Jeffries wrote: On Mon, 7 Nov 2011 14:37:24 +, Paul Regan wrote: New install of 3.1.16, FTP appears to be configured correctly but hence the mail group post its not working as expected .. Using ftp.emea.ibm.com as the test destination. Active FTP from proxy server command line works fine. Via a browser& squidclient The following error was encountered while trying to retrieve the URL: ftp://ftp.emea.ibm.com/ Read Error The system returned: [No Error] An error condition occurred while reading data from the network. Please retry your request. cache.log : 2011/11/07 12:45:20| ftpDataRead: read error: (107) Transport endpoint is not connected Wire capture : 12:45:20.395751 IP proxyserver.domain.60769> ftp.emea.ibm.com.ftp: S 2543509559:2543509559(0) win 5840 12:45:20.414004 IP ftp.emea.ibm.com.ftp> proxyserver.domain.60769: S 429684985:429684985(0) ack 2543509560 win 65535 12:45:20.414012 IP proxyserver.domain.60769> ftp.emea.ibm.com.ftp: . ack 1 win 46 12:45:20.444260 IP ftp.emea.ibm.com.ftp> proxyserver.domain.60769: P 1:78(77) ack 1 win 16384 Lots of packets on control channel. Looks normal. The handshake, login, file location etc. happen about here. 12:45:20.608768 IP ftp.emea.ibm.com.ftp> proxyserver.domain.60769: P ack 78 win 16384 12:45:20.818002 IP ftp.emea.ibm.com.ftp-data> proxyserver.domain.36703: S 3997244124:3997244124(0) win 65535 Server connects in with a data connection. You configured ftp_passive OFF. So this is expected. 12:45:20.818022 IP proxyserver.domain.36703> ftp.emea.ibm.com.ftp-data: S 2004820984:2004820984(0) ack 3997244125 win 5840 12:45:20.835744 IP ftp.emea.ibm.com.ftp-data> proxyserver.domain.36703: . ack 1 win 11520 12:45:20.835804 IP ftp.emea.ibm.com.ftp-data> proxyserver.domain.36703: P 1:692(691) ack 1 win 11520 12:45:20.835809 IP proxyserver.domain.36703> ftp.emea.ibm.com.ftp-data: . ack 692 win 57 12:45:20.835812 IP ftp.emea.ibm.com.ftp-data> proxyserver.domain.36703: FP 692:692(0) ack 1 win 11520 FIN-ACK on data channel from server after 692 bytes transferred. 12:45:20.835899 IP ftp.emea.ibm.com.ftp> proxyserver.domain.60769: P 1108:1129(21) ack 78 win 16384 12:45:20.836193 IP proxyserver.domain.60769> ftp.emea.ibm.com.ftp: F 78:78(0) ack 1129 win 63 FIN on the control channel from Squid. Data file is received and connections can close. 12:45:20.836210 IP proxyserver.domain.36703> ftp.emea.ibm.com.ftp-data: R 1:1(0) ack 693 win 57 12:45:20.853549 IP ftp.emea.ibm.com.ftp> proxyserver.domain.60769: P ack 79 win 16384 12:45:20.853576 IP ftp.emea.ibm.com.ftp> proxyserver.domain.60769: P 1129:1163(34) ack 79 win 16384 Server keeps throwing data at Squid down the control channel after FIN. 12:45:20.853586 IP proxyserver.domain.60769> ftp.emea.ibm.com.ftp: R 2543509638:2543509638(0) win 0 Squid responds to the extra data with RST. 12:45:20.853603 IP ftp.emea.ibm.com.ftp> proxyserver.domain.60769: FP 1163:1163(0) ack 79 win 16384 12:45:20.853606 IP proxyserver.domain.60769> ftp.emea.ibm.com.ftp: R 2543509638:2543509638(0) win 0 More packets from the server. More RST from Squid. Only 17.41 ms have elapsed, so its within bounds of network lag. Overall this looks like proper TCP closing sequence. Except that the data channel is closed first. Before any messages on the control channel arrive to inform Squid that the transfer is completed. Can you report this with the above details in bugzilla please so this does not get lost. I think we could work around it by checking the expected object size on data closure and skip the error if they match. Amos
Re: [squid-users] 3.1.16 FTP problems ..
Thanks for the reply, will open the bugzilla .. Some further info is I just tried the same using a 3.0 stable13 server with the same results. I haven't run a wire trace but cache.log reports the same error : ftpDataRead: read error: (107) Transport endpoint is not connected Paul On 7 November 2011 22:37, Amos Jeffries wrote: > On Mon, 7 Nov 2011 14:37:24 +, Paul Regan wrote: >> >> New install of 3.1.16, FTP appears to be configured correctly but >> hence the mail group post its not working as expected .. >> >> Using ftp.emea.ibm.com as the test destination. >> >> Active FTP from proxy server command line works fine. >> >> Via a browser & squidclient >> >> The following error was encountered while trying to retrieve the URL: >> ftp://ftp.emea.ibm.com/ >> Read Error >> The system returned: [No Error] >> An error condition occurred while reading data from the network. >> Please retry your request. >> >> cache.log : >> >> 2011/11/07 12:45:20| ftpDataRead: read error: (107) Transport endpoint >> is not connected >> >> Wire capture : >> >> 12:45:20.395751 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: S >> 2543509559:2543509559(0) win 5840 > 0,nop,wscale 7> >> 12:45:20.414004 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: S >> 429684985:429684985(0) ack 2543509560 win 65535 > 5> >> 12:45:20.414012 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: . >> ack 1 win 46 >> 12:45:20.444260 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P >> 1:78(77) ack 1 win 16384 > > > Lots of packets on control channel. Looks normal. The handshake, login, file > location etc. happen about here. > >> 12:45:20.608768 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P >> ack 78 win 16384 >> 12:45:20.818002 IP ftp.emea.ibm.com.ftp-data > >> proxyserver.domain.36703: S 3997244124:3997244124(0) win 65535 > 1380,nop,wscale 5> > > Server connects in with a data connection. You configured ftp_passive OFF. > So this is expected. > > >> 12:45:20.818022 IP proxyserver.domain.36703 > >> ftp.emea.ibm.com.ftp-data: S 2004820984:2004820984(0) ack 3997244125 >> win 5840 >> 12:45:20.835744 IP ftp.emea.ibm.com.ftp-data > >> proxyserver.domain.36703: . ack 1 win 11520 >> 12:45:20.835804 IP ftp.emea.ibm.com.ftp-data > >> proxyserver.domain.36703: P 1:692(691) ack 1 win 11520 >> 12:45:20.835809 IP proxyserver.domain.36703 > >> ftp.emea.ibm.com.ftp-data: . ack 692 win 57 > >> 12:45:20.835812 IP ftp.emea.ibm.com.ftp-data > >> proxyserver.domain.36703: FP 692:692(0) ack 1 win 11520 > > FIN-ACK on data channel from server after 692 bytes transferred. > >> 12:45:20.835899 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P >> 1108:1129(21) ack 78 win 16384 >> 12:45:20.836193 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: F >> 78:78(0) ack 1129 win 63 > > FIN on the control channel from Squid. Data file is received and connections > can close. > >> 12:45:20.836210 IP proxyserver.domain.36703 > >> ftp.emea.ibm.com.ftp-data: R 1:1(0) ack 693 win 57 >> 12:45:20.853549 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P >> ack 79 win 16384 >> 12:45:20.853576 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P >> 1129:1163(34) ack 79 win 16384 > > Server keeps throwing data at Squid down the control channel after FIN. > >> 12:45:20.853586 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: R >> 2543509638:2543509638(0) win 0 > > Squid responds to the extra data with RST. > >> 12:45:20.853603 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: FP >> 1163:1163(0) ack 79 win 16384 >> 12:45:20.853606 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: R >> 2543509638:2543509638(0) win 0 > > More packets from the server. More RST from Squid. Only 17.41 ms have > elapsed, so its within bounds of network lag. > > > Overall this looks like proper TCP closing sequence. Except that the data > channel is closed first. Before any messages on the control channel arrive > to inform Squid that the transfer is completed. > > Can you report this with the above details in bugzilla please so this does > not get lost. I think we could work around it by checking the expected > object size on data closure and skip the error if they match. > > Amos > >
Re: [squid-users] 3.1.16 FTP problems ..
On Mon, 7 Nov 2011 14:37:24 +, Paul Regan wrote: New install of 3.1.16, FTP appears to be configured correctly but hence the mail group post its not working as expected .. Using ftp.emea.ibm.com as the test destination. Active FTP from proxy server command line works fine. Via a browser & squidclient The following error was encountered while trying to retrieve the URL: ftp://ftp.emea.ibm.com/ Read Error The system returned: [No Error] An error condition occurred while reading data from the network. Please retry your request. cache.log : 2011/11/07 12:45:20| ftpDataRead: read error: (107) Transport endpoint is not connected Wire capture : 12:45:20.395751 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: S 2543509559:2543509559(0) win 5840 853154020 0,nop,wscale 7> 12:45:20.414004 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: S 429684985:429684985(0) ack 2543509560 win 65535 12:45:20.414012 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: . ack 1 win 46 12:45:20.444260 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 1:78(77) ack 1 win 16384 Lots of packets on control channel. Looks normal. The handshake, login, file location etc. happen about here. 12:45:20.608768 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P ack 78 win 16384 12:45:20.818002 IP ftp.emea.ibm.com.ftp-data > proxyserver.domain.36703: S 3997244124:3997244124(0) win 65535 Server connects in with a data connection. You configured ftp_passive OFF. So this is expected. 12:45:20.818022 IP proxyserver.domain.36703 > ftp.emea.ibm.com.ftp-data: S 2004820984:2004820984(0) ack 3997244125 win 5840 12:45:20.835744 IP ftp.emea.ibm.com.ftp-data > proxyserver.domain.36703: . ack 1 win 11520 12:45:20.835804 IP ftp.emea.ibm.com.ftp-data > proxyserver.domain.36703: P 1:692(691) ack 1 win 11520 12:45:20.835809 IP proxyserver.domain.36703 > ftp.emea.ibm.com.ftp-data: . ack 692 win 57 12:45:20.835812 IP ftp.emea.ibm.com.ftp-data > proxyserver.domain.36703: FP 692:692(0) ack 1 win 11520 FIN-ACK on data channel from server after 692 bytes transferred. 12:45:20.835899 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 1108:1129(21) ack 78 win 16384 12:45:20.836193 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: F 78:78(0) ack 1129 win 63 FIN on the control channel from Squid. Data file is received and connections can close. 12:45:20.836210 IP proxyserver.domain.36703 > ftp.emea.ibm.com.ftp-data: R 1:1(0) ack 693 win 57 12:45:20.853549 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P ack 79 win 16384 12:45:20.853576 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 1129:1163(34) ack 79 win 16384 Server keeps throwing data at Squid down the control channel after FIN. 12:45:20.853586 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: R 2543509638:2543509638(0) win 0 Squid responds to the extra data with RST. 12:45:20.853603 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: FP 1163:1163(0) ack 79 win 16384 12:45:20.853606 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: R 2543509638:2543509638(0) win 0 More packets from the server. More RST from Squid. Only 17.41 ms have elapsed, so its within bounds of network lag. Overall this looks like proper TCP closing sequence. Except that the data channel is closed first. Before any messages on the control channel arrive to inform Squid that the transfer is completed. Can you report this with the above details in bugzilla please so this does not get lost. I think we could work around it by checking the expected object size on data closure and skip the error if they match. Amos
[squid-users] 3.1.16 FTP problems ..
New install of 3.1.16, FTP appears to be configured correctly but hence the mail group post its not working as expected .. Using ftp.emea.ibm.com as the test destination. Active FTP from proxy server command line works fine. Via a browser & squidclient The following error was encountered while trying to retrieve the URL: ftp://ftp.emea.ibm.com/ Read Error The system returned: [No Error] An error condition occurred while reading data from the network. Please retry your request. cache.log : 2011/11/07 12:45:20| ftpDataRead: read error: (107) Transport endpoint is not connected Wire capture : 12:45:20.395751 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: S 2543509559:2543509559(0) win 5840 12:45:20.414004 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: S 429684985:429684985(0) ack 2543509560 win 65535 12:45:20.414012 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: . ack 1 win 46 12:45:20.444260 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 1:78(77) ack 1 win 16384 12:45:20.444290 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: . ack 78 win 46 12:45:20.444295 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 78:145(67) ack 1 win 16384 12:45:20.444299 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: . ack 145 win 46 12:45:20.462391 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 145:595(450) ack 1 win 16384 12:45:20.462396 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: . ack 595 win 54 12:45:20.462464 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: P 1:17(16) ack 595 win 54 12:45:20.480374 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P ack 17 win 16384 12:45:20.517610 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 595:639(44) ack 17 win 16384 12:45:20.517667 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: P 17:41(24) ack 639 win 54 12:45:20.535681 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P ack 41 win 16384 12:45:20.536375 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 639:699(60) ack 41 win 16384 12:45:20.536392 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 699:721(22) ack 41 win 16384 12:45:20.536405 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: . ack 721 win 54 12:45:20.554833 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 721:1043(322) ack 41 win 16384 12:45:20.554873 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: P 41:49(8) ack 1043 win 63 12:45:20.572753 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P ack 49 win 16384 12:45:20.572777 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 1043:1086(43) ack 49 win 16384 12:45:20.572838 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: P 49:72(23) ack 1086 win 63 12:45:20.591096 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P ack 72 win 16384 12:45:20.591100 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 1086:1108(22) ack 72 win 16384 12:45:20.591130 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: P 72:78(6) ack 1108 win 63 12:45:20.608768 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P ack 78 win 16384 12:45:20.818002 IP ftp.emea.ibm.com.ftp-data > proxyserver.domain.36703: S 3997244124:3997244124(0) win 65535 12:45:20.818022 IP proxyserver.domain.36703 > ftp.emea.ibm.com.ftp-data: S 2004820984:2004820984(0) ack 3997244125 win 5840 12:45:20.835744 IP ftp.emea.ibm.com.ftp-data > proxyserver.domain.36703: . ack 1 win 11520 12:45:20.835804 IP ftp.emea.ibm.com.ftp-data > proxyserver.domain.36703: P 1:692(691) ack 1 win 11520 12:45:20.835809 IP proxyserver.domain.36703 > ftp.emea.ibm.com.ftp-data: . ack 692 win 57 12:45:20.835812 IP ftp.emea.ibm.com.ftp-data > proxyserver.domain.36703: FP 692:692(0) ack 1 win 11520 12:45:20.835899 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 1108:1129(21) ack 78 win 16384 12:45:20.836193 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: F 78:78(0) ack 1129 win 63 12:45:20.836210 IP proxyserver.domain.36703 > ftp.emea.ibm.com.ftp-data: R 1:1(0) ack 693 win 57 12:45:20.853549 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P ack 79 win 16384 12:45:20.853576 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: P 1129:1163(34) ack 79 win 16384 12:45:20.853586 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: R 2543509638:2543509638(0) win 0 12:45:20.853603 IP ftp.emea.ibm.com.ftp > proxyserver.domain.60769: FP 1163:1163(0) ack 79 win 16384 12:45:20.853606 IP proxyserver.domain.60769 > ftp.emea.ibm.com.ftp: R 2543509638:2543509638(0) win 0 Its not so obvious from the tcpdump (easier on wireshark) but the 3rd packet from bottom is a [RST] from the proxy server. Comparing that to a capture during an FTP connection from the command line (same server) then that equiv packet is an [ACK] - I can make the pcap file available if need be .. I dont know if thats the actual issue but its a difference between a failure and a success which I've homed in on otherwise I'm spinning my wheels on this problem Config (ftp parts): ftp_passive off ftp_sanitycheck off ftp_epsv off f
