Re: Squid-ICAP problem (bug?)

Hi all,

Tsantilas Christos wrote :

> If you are still looking for the solution, try the following patch in
> icap_reqmod.c file. With this patch the icapReqModPassHttpBody function
> called if the icap->reqmod.http_entity.buf.size is zero, and at this
> phase can handle correctly, the case that the
> icap->flags.reqmod_http_entity_eof==1.

Unfortunately it still segfaults.

But, I had time to work on my client's test platform and I spent a whole
day hacking icap_reqmod.c.

The only modification (except adding excessive debug logging) is that one:

in icapReqModReadHttpBody function replacing the test

if (icap->reqmod.http_entity.bytes_read >= icap->request->content_length)

by

if (icap->chunk_size < 0)

which correct the initial problem ie not reading the 0\r\n marking thee
end of the chunk.

The new problem is that squid correctly reads the end of the chunk but
dies immediatly.

The dying occurs in the icapReqModPassHttpBody function and I spent many
time to find why. In fact I focussed on the call of this function from
the icapReqModReadHttpBody function and I didn't manage to find the
logic of the test and the function parameters (because I don't know well
the squid and icap patch code).

Anyway this I found that the function was called with icap = 0 parameter
(I spent too more time to search a buf=0 or callback=0); so I added a
simple test in the beginning of the function:

static void
icapReqModPassHttpBody(IcapStateData * icap, char *buf, size_t size,
     CBCB * callback, void *cbdata)
{
     debug(81, 3) ("%s:%d: icapReqModPassHttpBody: called\n", __FILE__,
__LINE__);
     if (!icap) {
         debug(81, 1) ("%s:%d: icapReqModPassHttpBody: FD %d called with
icap = (nil) !\n", __FILE__, __LINE__);
         return;
     }

I added this to prevent segfaulting but without knowing if the return
would lead to a correct behaviour. And it seems that is is ok. We made
some tests and we did not have any more segfaults.

I then tried with gdb (I should have used it before but I am not
familiar with it) to get a backtrace as you asked in a previous mail and
I saw that the icapReqModPassHttpBody call with icap=0 is not called
from the icapReqModReadHttpBody:

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread -1218496992 (LWP 9508)]
0x08087411 in icapReqModPassHttpBody (icap=0x0, buf=0x0,
size=4294967295, callback=0, cbdata=0x8c95e00) at icap_reqmod.c:933
933 icap_reqmod.c: Aucun fichier ou repertoire de ce type.
         in icap_reqmod.c
(gdb) bt
#0 0x08087411 in icapReqModPassHttpBody (icap=0x0, buf=0x0,
size=4294967295, callback=0, cbdata=0x8c95e00) at icap_reqmod.c:933
#1 0x08083905 in requestAbortBody (request=0x8c94578) at HttpRequest.c:215
#2 0x0807a183 in httpStateFree (fd=9, data=0x8cc72a0) at http.c:69
#3 0x08065ccd in commCallCloseHandlers (fd=44) at comm.c:573
#4 0x08065dec in comm_close (fd=44) at comm.c:655
#5 0x0807b32c in httpReadReply (fd=44, data=0x8cc72a0) at http.c:852
#6 0x08067749 in comm_poll (msec=13) at comm_select.c:445
#7 0x0808fc77 in main (argc=4, argv=0xbfff9494) at main.c:754

Here is a sumup of the logs when icap value is tested and squid does not
segfault anymore:

2006/12/01 18:18:19| icapReqModParseHttpRequest: successfully parsed the
HTTP request
2006/12/01 18:18:19| handing request bodies in ICAP REQMOD
2006/12/01 18:18:19| icap_reqmod.c:859: icapReqModReadHttpBody: FD 53 called
2006/12/01 18:18:19| icap_reqmod.c:861: icapReqModReadHttpBody: read
returns 33
2006/12/01 18:18:19| icap_reqmod.c:872: icapReqModReadHttpBody: Before
icapParseChunkedBody bytes_read = 0
2006/12/01 18:18:19| icap_common.c:695: chunk_size=0
2006/12/01 18:18:19| icap_common.c:702: bufOffset=0, len=33
2006/12/01 18:18:19| icap_common.c:705: bufOffset=0, len=33
2006/12/01 18:18:19| icap_common.c:604: icapParseChunkSize:
buf=0x8ccd1b8, len=33
2006/12/01 18:18:19| icap_common.c:607: icapParseChunkSize: start=0
2006/12/01 18:18:19| icapLineLength: returning 4
2006/12/01 18:18:19| icap_common.c:646: icapParseChunkSize: start=0, end=2
2006/12/01 18:18:19| icap_common.c:672: icapParseChunkSize: return
nextStart=4
2006/12/01 18:18:19| icap_common.c:716: got chunksize 27, new offset 4
2006/12/01 18:18:19| icap_common.c:723: X
2006/12/01 18:18:19| icap_common.c:705: bufOffset=31, len=33
2006/12/01 18:18:19| icap_common.c:604: icapParseChunkSize:
buf=0x8ccd1d7, len=2
2006/12/01 18:18:19| icap_common.c:607: icapParseChunkSize: start=0
2006/12/01 18:18:19| icapLineLength: returning 2
2006/12/01 18:18:19| icap_common.c:607: icapParseChunkSize: start=2
2006/12/01 18:18:19| icap_reqmod.c:876: icapReqModReadHttpBody: After
icapParseChunkedBody bytes_read = 27
2006/12/01 18:18:19| icap_reqmod.c:884 icapReqModReadHttpBody: chunk_size=0

Here is the first modification: even if we read the 27 bytes of the body
we continue reading because chunk_size is not -2:

2006/12/01 18:18:19| icap_reqmod.c:892 icapReqModReadHttpBody: call
commSetSelect -> icapReqModReadHttpBody
2006/12/01 18:18:19| icap_reqmod.c:894 icapReqModReadHttpBody: back from
commSetSelect -> icapReqModReadHttpBody
2006/12/01 18:18:19| icap_reqmod.c:917 icapReqModReadHttpBody: end of
function

As we don't have an eof we call commSetSelect to read further.

2006/12/01 18:18:19| icapService: type=ICAP_SERVICE_REQMOD_POSTCACHE
2006/12/01 18:18:19| icapService: checking service service_3/id=0
2006/12/01 18:18:19| icapService: checking service service_4/id=0
2006/12/01 18:18:19| icapService: no service found
2006/12/01 18:18:19| icap_reqmod.c:931: icapReqModPassHttpBody: called
2006/12/01 18:18:19| icap_reqmod.c:932 icap =
0x8c95e00
2006/12/01 18:18:19| icap_reqmod.c:933 http_entity.buf =
0x8c89b40
2006/12/01 18:18:19| icap_reqmod.c:934 http_entity.buf.size = 27
2006/12/01 18:18:19| icap_reqmod.c:935 http_entity.callback = (nil)
2006/12/01 18:18:19| icap_reqmod.c:936 http_entity.callback_bufsize = 0
2006/12/01 18:18:19| icap_reqmod.c:937 buf = 0x8cb5a80
2006/12/01 18:18:19| icap_reqmod.c:938 size = 8192
2006/12/01 18:18:19| icap_reqmod.c:939 callback = 0x807c994
2006/12/01 18:18:19| icap_reqmod.c:940 cbdata = 0x8cc72a0
2006/12/01 18:18:19| icap_reqmod.c:962: icapReqModPassHttpBody: entity
buf size = 27
2006/12/01 18:18:19| icap_reqmod.c:974: icapReqModPassHttpBody: giving
27 bytes to other side
2006/12/01 18:18:19| icap_reqmod.c:976: icapReqModPassHttpBody:

----
GOTO=&TRI=&ORDER=&COD=&LIB=
----
2006/12/01 18:18:19| icap_reqmod.c:978: icapReqModPassHttpBody: entity 
buf size now = 0
2006/12/01 18:18:19| icap_reqmod.c:931: icapReqModPassHttpBody: called
2006/12/01 18:18:19| icap_reqmod.c:932 icap                         = 
0x8c95e00
2006/12/01 18:18:19| icap_reqmod.c:933 http_entity.buf              = 
0x8c89b40
2006/12/01 18:18:19| icap_reqmod.c:934 http_entity.buf.size         = 0
2006/12/01 18:18:19| icap_reqmod.c:935 http_entity.callback         = (nil)
2006/12/01 18:18:19| icap_reqmod.c:936 http_entity.callback_bufsize = 0
2006/12/01 18:18:19| icap_reqmod.c:937 buf      = 0x8cb5a80
2006/12/01 18:18:19| icap_reqmod.c:938 size     = 8192
2006/12/01 18:18:19| icap_reqmod.c:939 callback = 0x807c994
2006/12/01 18:18:19| icap_reqmod.c:940 cbdata   = 0x8cc72a0
2006/12/01 18:18:19| icap_reqmod.c:859: icapReqModReadHttpBody: FD 53 called
2006/12/01 18:18:19| icap_reqmod.c:861: icapReqModReadHttpBody: read 
returns 5
2006/12/01 18:18:19| icap_reqmod.c:872: icapReqModReadHttpBody: Before 
icapParseChunkedBody bytes_read = 27
We read the next 5 bytes
2006/12/01 18:18:19| icap_common.c:695: chunk_size=0
2006/12/01 18:18:19| icap_common.c:702: bufOffset=0, len=7
2006/12/01 18:18:19| icap_common.c:705: bufOffset=0, len=7
2006/12/01 18:18:19| icap_common.c:604: icapParseChunkSize: 
buf=0x8ccd1b8, len=7
2006/12/01 18:18:19| icap_common.c:607: icapParseChunkSize: start=0
2006/12/01 18:18:19| icapLineLength: returning 2
2006/12/01 18:18:19| icap_common.c:607: icapParseChunkSize: start=2
2006/12/01 18:18:19| icapLineLength: returning 3
2006/12/01 18:18:19| icap_common.c:646: icapParseChunkSize: start=2, end=3
2006/12/01 18:18:19| icap_common.c:672: icapParseChunkSize: return 
nextStart=5
2006/12/01 18:18:19| icap_common.c:716: got chunksize -2, new offset 5
2006/12/01 18:18:19| icap_common.c:719: zero end chunk reached
which are parsed as the 0 end chunk
2006/12/01 18:18:19| icap_reqmod.c:876: icapReqModReadHttpBody: After 
icapParseChunkedBody bytes_read = 27
2006/12/01 18:18:19| icap_reqmod.c:884 icapReqModReadHttpBody: chunk_size=-2
2006/12/01 18:18:19| icap_reqmod.c:888 icapReqModReadHttpBody: setting 
reqmod_http_entity_eof
So we set eof
2006/12/01 18:18:19| icap_reqmod.c:899 icap                         = 
0x8c95e00
2006/12/01 18:18:19| icap_reqmod.c:900 http_entity.buf              = 
0x8c89b40
2006/12/01 18:18:19| icap_reqmod.c:901 http_entity.buf.size         = 0
2006/12/01 18:18:19| icap_reqmod.c:902 http_entity.callback         = 
0x807c994
2006/12/01 18:18:19| icap_reqmod.c:903 http_entity.callback_bufsize = 8192
2006/12/01 18:18:19| icap_reqmod.c:917 icapReqModReadHttpBody: end of 
function
and we exit the icapReqModReadHttpBody function without calling 
icapReqModPassHttpBody because http_entity.buf.size is 0.
2006/12/01 18:18:19| icap_reqmod.c:931: icapReqModPassHttpBody: called
2006/12/01 18:18:19| icap_reqmod.c:933: icapReqModPassHttpBody: FD 0 
called with icap = (nil) !
And here is the call of icapReqModPassHttpBody with icap = 0 calld from 
somewhere.
Christophe.