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<squid3_at_treenet.co.nz> 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
>>
>>
Received on Tue Nov 08 2011 - 09:35:31 MST