I am including logs of what happens when wget is cancelled.
FD 8 = wget
FD 9 = origin
FD 12 = ICAP
noteInitiatorAborted() is scheduled from the ClientHttpRequest
destructor for FD 8 (wget). It doesn't seem to be executed however.
Shouldn't it be?
2011/02/07 12:32:30.380| comm_select(): got FD 8 events=1
monitoring=19 F->read_handler=1 F->write_handler=0
2011/02/07 12:32:30.380| comm_select(): Calling read handler on FD 8
2011/02/07 12:32:30.380| comm_read_try: FD 8, size 4095, retval 0, errno 0
2011/02/07 12:32:30.380| commio_finish_callback: called for FD 8 (0, 0)
2011/02/07 12:32:30.380| comm.cc(165) will call
ConnStateData::clientReadRequest(FD 8, data=0xe99fb8, size=0,
buf=0xe6f560) [call25]
2011/02/07 12:32:30.381| entering ConnStateData::clientReadRequest(FD
8, data=0xe99fb8, size=0, buf=0xe6f560)
2011/02/07 12:32:30.381| AsyncCall.cc(32) make: make call
ConnStateData::clientReadRequest [call25]
2011/02/07 12:32:30.381| ConnStateData status in: [ job4]
2011/02/07 12:32:30.381| client_side.cc(2678) clientReadRequest:
clientReadRequest FD 8 size 0
2011/02/07 12:32:30.381| clientReadRequest: FD 8 closed?
2011/02/07 12:32:30.381| connFinishedWithConn: FD 8 aborted
(half_closed_clients disabled)
2011/02/07 12:32:30.381| comm_close: start closing FD 8
2011/02/07 12:32:30.381| The AsyncCall comm_close_start constructed,
this=0xc423f0 [call49419]
2011/02/07 12:32:30.381| comm.cc(1611) will call comm_close_start(FD
8) [call49419]
2011/02/07 12:32:30.381| comm.cc(1195) commSetTimeout: FD 8 timeout -1
2011/02/07 12:32:30.381| comm.cc(1206) commSetTimeout: FD 8 timeout -1
2011/02/07 12:32:30.381| commCallCloseHandlers: FD 8
2011/02/07 12:32:30.381| commCallCloseHandlers: ch->handler=0xe98870*1
2011/02/07 12:32:30.381| comm.cc(1460) will call
ConnStateData::connStateClosed(FD 8, data=0xe99fb8) [call20]
2011/02/07 12:32:30.381| The AsyncCall comm_close_complete
constructed, this=0xe99cc0 [call49420]
2011/02/07 12:32:30.381| comm.cc(1643) will call
comm_close_complete(FD 8) [call49420]
2011/02/07 12:32:30.381| ConnStateData status out: [ job4]
2011/02/07 12:32:30.381| leaving ConnStateData::clientReadRequest(FD
8, data=0xe99fb8, size=0, buf=0xe6f560)
2011/02/07 12:32:30.381| entering comm_close_start(FD 8)
2011/02/07 12:32:30.381| AsyncCall.cc(32) make: make call
comm_close_start [call49419]
2011/02/07 12:32:30.381| leaving comm_close_start(FD 8)
2011/02/07 12:32:30.381| entering ConnStateData::connStateClosed(FD 8,
data=0xe99fb8)
2011/02/07 12:32:30.381| AsyncCall.cc(32) make: make call
ConnStateData::connStateClosed [call20]
2011/02/07 12:32:30.381| ConnStateData status in: [ job4]
2011/02/07 12:32:30.381| ConnStateData will NOT delete in-call job,
reason: ConnStateData::connStateClosed
2011/02/07 12:32:30.381| ConnStateData::connStateClosed(FD 8,
data=0xe99fb8) ends job [Stopped,
reason:ConnStateData::connStateClosed job4]
2011/02/07 12:32:30.381| ConnStateData::swanSong: FD 8
2011/02/07 12:32:30.381| httpRequestFree: http://172.16.199.150/popeye.mp4
2011/02/07 12:32:30.381| clientLogRequest:
al.url='http://172.16.199.150/popeye.mp4'
2011/02/07 12:32:30.381| clientLogRequest: http.code='0'
2011/02/07 12:32:30.381| The AsyncCall Initiate::noteInitiatorAborted
constructed, this=0xc423f0 [call49421]
2011/02/07 12:32:30.381| Initiator.cc(28) will call
Initiate::noteInitiatorAborted() [call49421]
2011/02/07 12:32:30.381| AsyncJob destructed, this=0xe9a988
type=ClientHttpRequest [job5]
2011/02/07 12:32:30.381| ConnStateData::~ConnStateData: FD -1
2011/02/07 12:32:30.381| AsyncJob destructed, this=0xe9a148
type=ConnStateData [job4]
2011/02/07 12:32:30.381| AsyncJob.cc(139) callEnd:
ConnStateData::connStateClosed(FD 8, data=0xe99fb8) ended 0xe9a148
2011/02/07 12:32:30.381| leaving ConnStateData::connStateClosed(FD 8,
data=0xe99fb8)
2011/02/07 12:32:30.381| entering comm_close_complete(FD 8)
2011/02/07 12:32:30.381| AsyncCall.cc(32) make: make call
comm_close_complete [call49420]
2011/02/07 12:32:30.381| fd_close FD 8 Reading next request
2011/02/07 12:32:30.381| commSetSelect(FD
8,type=1,handler=0,client_data=0,timeout=0)
2011/02/07 12:32:30.381| commSetSelect(FD
8,type=2,handler=0,client_data=0,timeout=0)
2011/02/07 12:32:30.381| leaving comm_close_complete(FD 8)
2011/02/07 12:32:30.381| entering Initiate::noteInitiatorAborted()
2011/02/07 12:32:30.381| AsyncCall.cc(32) make: make call
Initiate::noteInitiatorAborted [call49421]
2011/02/07 12:32:30.381| AsyncCall.cc(42) make: will not call
Initiate::noteInitiatorAborted [call49421] because of job gone
2011/02/07 12:32:30.381| leaving Initiate::noteInitiatorAborted()
Thank you,
John Craws
On Wed, Feb 9, 2011 at 4:08 PM, John Craws <john.craws_at_gmail.com> wrote:
> Please disregard the part where I am asking why the close handler is
> removed when the connection to the origin server is closed because the
> complete response has been received. I understand that it cannot
> cleanup adaptation at that point as it has not completed.
>
> Sorry about that.
>
> On Wed, Feb 9, 2011 at 3:05 PM, John Craws <john.craws_at_gmail.com> wrote:
>> Hello,
>>
>> Just trying to understand correctly..
>>
>>>> Therefore:
>>>>
>>>> 1. The close handler that had been set in the HttpStateData
>>>> constructor (HttpStateData::httpStateConnClosed()) is not called
>>>> (because closeServer() removed it).
>>>
>>> Good.
>>
>> I'm not very familiar with the architecture, but how is that a good
>> thing? I thought (from analyzing non-problematic cases and the souce
>> code) that the close handler was responsible for the closing cleanup.
>> Why is it removed and not executed?
>> The close handler for HttpStateData (httpStateConnClosed) indirectly
>> calls cleanAdaptation and others (via deleteThis() -> callEnd() ->
>> ServerStateData::swanSong() -> cleanAdaptation()). That takes care of
>> the ICAP socket among other things.
>>
>>
>>>
>>>> 2. -> AsyncJob::deleteThis("HttpStateData::httpStateConnClosed") is not
>>>> called.
>>>
>>> Ambiguous whether this is needed. IIRC at this point doneAll() supposedly
>>> should return true which would lead to (3) below.
>>>
>>> The server side seems very twisted and does not appear to implement the
>>> Jobs API at the leaf HttpStateData level, doing it at the generic
>>> ServerStateData level instead.
>>
>> I thought it had to be called in order to trigger deletion / cleanup.
>>
>> If doneAll() returns true, done() will return true and that will allow
>> the body of AsyncJob::callEnd() to run, but callEnd() itself is called
>> by deleteThis() in the chain of calls initiated by the (removed) close
>> handler. ServerStateData::swanSong() will not be called unless
>> callEnd() is called. Is it supposed to be call some other way?
>>
>>
>>>> 3. -> AsyncJob::callEnd() is not called.
>>>
>>> Bad.
>>
>> See above.
>>
>>>
>>>> 4. -> ServerStateData::swanSong() is not called.
>>>
>>> Very bad.
>>>
>>
>> Again, I thought this was to be part of the chain of events initiated
>> by the close handler.
>>
>>>> 5. -> *** cleanAdaptation() is not called.
>>>> 6. -> "delete this" in AsyncJob::callEnd() is not called.
>>>> 7. -> The ICAP socket is not closed.
>>>>
>>>> If the client is not cancelled, handleAdaptationCompleted() is
>>>> eventually called and calls cleanAdaptation() itself. No visible
>>>> problem.
>>>>
>>>> With other ICAP services where cancellation occurs while the socket to
>>>> the ICAP service is still active, squid detects that the client
>>>> connection has been closed (FD closed) and the correct chain of
>>>> notification/events leads to correct ICAP cleanup. No visible problem.
>>
>> I see those scenarios clean up via the close handler (because they are
>> not closing via closeServer(). Why is it different in this case?
>>
>>>>
>>>
>>> Two problems I can see that need checking and fixing if confirmed from
>>> that:
>>>
>>> * whatever stream reader is present (here adaptation) needs a kick every
>>> time serverComplete() is called. In a way that informs it there will no
>>> more data coming but X bytes are now ready to be handled.
>>
>> Is there something already in place that does this and should be
>> executed on serverComplete()?
>>
>>>
>>> * HttpStateData needs to be left in a self-shutdown state
>>>
>>
>>
>> Thanks a lot,
>>
>> John Craws
>>
>>
>>
>>
>>
>>
>>>
>>>> I'd really appreciate your help with this.
>>>>
>>>> Thank you,
>>>>
>>>> John Craws
>>>>
>>>> ------------
>>>>
>>>> On Tue, Feb 1, 2011 at 1:59 PM, Tsantilas Christos
>>>> <chtsanti_at_users.sourceforge.net> wrote:
>>>>> Hi John,
>>>>> I did some simple tests and I am not seeing this problem on trunk or
>>> on
>>>>> the
>>>>> latest squid-3.1 on bzr repository. The connection to the icap server
>>>>> always
>>>>> closed.
>>>>> Is it possible to be an icap server bug?
>>>>>
>>>>> The debug section for the squid ICAP client is the 93. Try to enable
>>>>> debug
>>>>> to see if you can understand where the problem is:
>>>>> debug_options ALL,1 93,9
>>>>>
>>>>>
>>>>> On 02/01/2011 07:58 PM, John Craws wrote:
>>>>>>
>>>>>> Hi,
>>>>>>
>>>>>> Thanks for your reply. However, I should have added that:
>>>>>>
>>>>>> 1. I do not see FDs reused if the request is aborted. I see them
>>>>>> reused if the request completes.
>>>>>> 2. This is the case even with 'icap_persistent_connections off'.
>>>>>>
>>>>>> Thanks,
>>>>>>
>>>>>> John Craws
>>>>>>
>>>>>> ----------------
>>>>>>
>>>>>> On 01/02/11 09:04, John Craws wrote:
>>>>>>
>>>>>> Hello,
>>>>>>
>>>>>> I am going through the source code of 3.1.9/3.1.10 trying to find
>>>>>> the
>>>>>> cause of a problem I am seeing with a squid instance configured to
>>>>>> use
>>>>>> an ICAP service.
>>>>>>
>>>>>> The setup works fine, but if the client (wget) is disconnected
>>>>>> while
>>>>>> the response is being transferred (CTRL-C while receiving
>>>>>> relatively
>>>>>> large data), the ICAP socket is never disconnected. This leads to
>>> a
>>>>>> situation where the ICAP service is perpetually timing out on a
>>>>>> read
>>>>>> operation on that socket.
>>>>>>
>>>>>> I have not seen this occur with other ICAP services.
>>>>>>
>>>>>> I would definitely appreciate if someone with better knowledge of
>>>>>> this
>>>>>> part of the code could help me pinpoint where the relationship
>>>>>> between
>>>>>> those two is implemented.
>>>>>>
>>>>>> As I understand it ICAP should not be aware of the client and has an
>>>>>> independent set of persistent connections.
>>>>>>
>>>>>> The client disconnecting should set the ICAP output handlers to
>>>>>> discard the rest of the transaction and push the FD into an IdleFdList
>>>>>> waiting for another client request to use it.
>>>>>>
>>>>>> Alex or Christos know more about the finer details.
>>>>>>
>>>>>> Amos
>>>>>> --
>>>>>> Please be using
>>>>>> Current Stable Squid 2.7.STABLE9 or 3.1.10
>>>>>> Beta testers wanted for 3.2.0.4
>>>>>>
>>>>>
>>>>>
>>>
>>
>
Received on Wed Feb 09 2011 - 21:49:40 MST
This archive was generated by hypermail 2.2.0 : Tue Feb 15 2011 - 12:00:04 MST