Re: Squid-ICAP problem (bug?)

Tsantilas Christos a e'crit :

Hello Christos,

> Maybe I was not clear on my last mail. Sorry.

You were but I forgot to mention that I tried what you adviced.

> But in the same function replace the test:
> if (icap->reqmod.http_entity.callback &&
> icap->reqmod.http_entity.buf.size) {
> icapReqModPassHttpBody(icap,
> icap->reqmod.http_entity.callback_buf,
> icap->reqmod.http_entity.callback_bufsize,
>
> with:
> if (icap->reqmod.http_entity.callback) {
> icapReqModPassHttpBody(icap,
> icap->reqmod.http_entity.callback_buf,
> icap->reqmod.http_entity.callback_bufsize,
>
> Did you try it?

Yes we tried it and this leads to segfault too.

>> and we exit the icapReqModReadHttpBody function without calling
>> icapReqModPassHttpBody because http_entity.buf.size is 0.
>>
> With the previous change this function must called here.....
> Did you make this change? Are you still seeing segfaults?

I did not test extensively but it seems that calling
icapReqModPassHttpBody without testing if http_entity.buf.size is 0 will
work in this very specific case (when end chunk is read in an extra
pass) but will lead to segfault in cases which used to work perfectly
before changing this test.

> In my tests I am not seeing any problem any more. But maybe I am losing
> something....

I don't have any magic recipe to reproduce the problem but it occurs
when parsing the request's body in REQMOD and that occurs generally when
doint a POST request (as there is no body in a GET request).

With your modification, we ends with segfaults during GET request !

By reading the log I just noticed that with your modification the
icapReqModPassHttpBody is not called:

This is for the specific request (POST):

2006/11/24 14:15:22| handing request bodies in ICAP REQMOD
2006/11/24 14:15:22| icapReqModReadHttpBody: FD 38 called
2006/11/24 14:15:22| icapReqModReadHttpBody: read returns 33
2006/11/24 14:15:22| icap_common.c:695: chunk_size=0
2006/11/24 14:15:22| icap_common.c:702: bufOffset=0, len=33
2006/11/24 14:15:22| icap_common.c:705: bufOffset=0, len=33
2006/11/24 14:15:22| icapParseChunkSize: buf=0x997fbe0, len=33
2006/11/24 14:15:22| icapParseChunkSize: start=0
2006/11/24 14:15:22| icapLineLength: returning 4
2006/11/24 14:15:22| icapParseChunkSize: start=0, end=2
2006/11/24 14:15:22| icapParseChunkSize: return nextStart=4
2006/11/24 14:15:22| got chunksize 27, new offset 4
2006/11/24 14:15:22| icap_common.c:723: X
2006/11/24 14:15:22| icap_common.c:705: bufOffset=31, len=33
2006/11/24 14:15:22| icapParseChunkSize: buf=0x997fbff, len=2
2006/11/24 14:15:22| icapParseChunkSize: start=0
2006/11/24 14:15:22| icapLineLength: returning 2
2006/11/24 14:15:22| icapParseChunkSize: start=2
2006/11/24 14:15:22| icap_reqmod.c:882 chunk_size=0
2006/11/24 14:15:22| icap_reqmod.c:892 http_entity.callback=(nil)
2006/11/24 14:15:22| icap_reqmod.c:894 http_entity.buf.size=27
2006/11/24 14:15:22| icap_reqmod.c:896 http_entity.callback_bufsize=0
2006/11/24 14:15:22| icapReqModReadHttpBody: FD 38 called
2006/11/24 14:15:22| icapReqModReadHttpBody: read returns 5
2006/11/24 14:15:22| icap_common.c:695: chunk_size=0
2006/11/24 14:15:22| icap_common.c:702: bufOffset=0, len=7
2006/11/24 14:15:22| icap_common.c:705: bufOffset=0, len=7
2006/11/24 14:15:22| icapParseChunkSize: buf=0x997fbe0, len=7
2006/11/24 14:15:22| icapParseChunkSize: start=0
2006/11/24 14:15:22| icapLineLength: returning 2
2006/11/24 14:15:22| icapParseChunkSize: start=2
2006/11/24 14:15:22| icapLineLength: returning 3
2006/11/24 14:15:22| icapParseChunkSize: start=2, end=3
2006/11/24 14:15:22| icapParseChunkSize: return nextStart=5
2006/11/24 14:15:22| got chunksize -2, new offset 5
2006/11/24 14:15:22| zero end chunk reached
2006/11/24 14:15:22| icap_reqmod.c:882 chunk_size=-2
2006/11/24 14:15:22| icap_reqmod.c:892 http_entity.callback=(nil)
2006/11/24 14:15:22| icap_reqmod.c:894 http_entity.buf.size=27
2006/11/24 14:15:22| icap_reqmod.c:896 http_entity.callback_bufsize=0
2006/11/24 14:15:22| icapSendRespMod: Create a new connection to icap
server service_4/icap://xx.xx.xx.xx:1344/wwrespmod/?wwprofile=HTTP_xxxx

But what is very strange is:
- respmod seems not to be called;
- the next request which is a GET is handled strangely:

2006/11/24 14:15:34| icapParseEncapsulated: res-hdr=-1, req-hdr=0,
null-body=791, res-body=-1, req-body=-1, opt-body=-1
2006/11/24 14:15:34| icapReqModReadIcapPart: directResponse=0 from ICAP
server service_3/icap://xx.xx.xx.xx:1344/wwreqmod/?wwprofile=HTTP_xxxx
2006/11/24 14:15:34| icapReqModReadHttpHdrs:
2006/11/24 14:15:34| expect=791
2006/11/24 14:15:34| so_far=0
2006/11/24 14:15:34| needed=791
2006/11/24 14:15:34| icapReqModReadHttpHdrs: read 791 bytes
2006/11/24 14:15:34| icapReqModReadHttpHdrs: read the entire request headers
2006/11/24 14:15:34| icapReqModParseHttpRequest: URI is
'http://xxxxx.xxx/rtn_FR.gif'
2006/11/24 14:15:34| icapReqModParseHttpRequest: Client HTTP version 1.1.
2006/11/24 14:15:34| icapReqModParseHttpRequest: successfully parsed the
HTTP request
2006/11/24 14:15:34| icap_reqmod.c:404 FD 35
2006/11/24 14:15:34| icap_reqmod.c:415 no message body
2006/11/24 14:15:34| icap_reqmod.c:432 looks good, keeping alive
2006/11/24 14:15:34| icapStateFree: FD -1, icap 0x997d8a0

This is saying that there is no body and just after we have:

2006/11/24 14:15:34| icapService: type=ICAP_SERVICE_REQMOD_POSTCACHE
2006/11/24 14:15:34| icapService: checking service service_3/id=0
2006/11/24 14:15:34| icapService: checking service service_4/id=0
2006/11/24 14:15:34| icapService: no service found
2006/11/24 14:15:34| icapReqModPassHttpBody: called
2006/11/24 14:15:34| icapReqModPassHttpBody: entity buf size = 27
2006/11/24 14:15:34| icapReqModPassHttpBody: giving 27 bytes to other side
2006/11/24 14:15:34| icapReqModPassHttpBody: entity buf size now = 0
2006/11/24 14:15:34| icapReqModPassHttpBody: called
2006/11/24 14:15:34| icapReqModPassHttpBody: entity buf size = 0
2006/11/24 14:15:34| icapSendRespMod: Create a new connection to icap
server service_4/icap://xx.xx.xx.xx:1344/wwrespmod/?wwprofile=HTTP_xxxx
2006/11/24 14:15:34| icapConnect: reused pconn FD 35
2006/11/24 14:15:34| icapConnectOver: FD 35, status=0
2006/11/24 14:15:34| icapSendRespMod: new connection to icap server
(using FD=35)
2006/11/24 14:15:34| icapService: type=ICAP_SERVICE_REQMOD_POSTCACHE
2006/11/24 14:15:34| icapService: checking service service_3/id=0
2006/11/24 14:15:34| icapService: checking service service_4/id=0
2006/11/24 14:15:34| icapService: no service found

So why is called icapReqModPassHttpBody if the request does not contain
a body ? And why dos it find 27 bytes of data which is exactly the body
of the previous request ?

This looks very strange, isn't it ?

Christophe.
Received on Sun Dec 03 2006 - 14:32:52 MST