Re: 3.1.16 FTP problems ..

[Amos Jeffries <squid3@xxxxxxxxxxxxx>]

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<squid3@xxxxxxxxxxxxx>  wrote:
> > On Mon, 7 Nov 2011 14:37:24 +0000, 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<mss 1460,sackOK,timestamp 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<mss 1380,nop,wscale
> > > 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
> > <snip>
> > 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<mss
> > > 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<mss 1460,nop,wscale 7>
> > > 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