Re: Squid-ICAP problem (bug?)
Christophe Boyanique wrote: Yes we tried it and this leads to segfault too. :-( 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_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_ The strange here is that the http_entity.callback=(nil) In my test cases, this never happens... II don't know why . 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 ? Yes it is .
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 -
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_
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_
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://x.xxx/rtn_FR.gif'
2006/11/24 14:15:34| icapReqModParseHttpRequest: Client HTTP version 1.1.
2006/11/24 14:15:34|
Re: Squid-ICAP problem (bug?)
Hi,
From your logs what I am seeing is that the
icap-reqmod.http_entity.buf.size==0 so the icapRqModPassHttpBody must
not called, but it is called. It is strange.
Did you touch something else in code? Can you run squid in gdb and send
a backtrace after the crash?
Regards,
Christos
Christophe Boyanique wrote:
..
After the conditionnal call to commSetSelect there is a conditionnal
call to icapReqModPassHttpBody and this where is the problem:
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,
icap-reqmod.http_entity.callback,
icap-reqmod.http_entity.callback_data);
icap-reqmod.http_entity.callback = NULL;
cbdataUnlock(icap-reqmod.http_entity.callback_data);
}
When calling this function, the test is on
icap-reqmod.http_entity.buf.size but the parameter sent to the function
is cap-reqmod.http_entity.callback_bufsize. Is it normal ?
I added some logs and here is the output:\
2006/11/14 13:43:25| zero end chunk reached
2006/11/14 13:43:25| icap_reqmod.c:882 chunk_size=-2
2006/11/14 13:43:25| icap_reqmod.c:892 http_entity.callback=0x807c994
2006/11/14 13:43:25| icap_reqmod.c:894 http_entity.buf.size=0
2006/11/14 13:43:25| icap_reqmod.c:896 http_entity.callback_bufsize=8192
2006/11/14 13:43:25| icapReqModPassHttpBody: called
FATAL: Received Segment Violation...dying.
Perhaps there is a problem with parameters passed to
icapReqModPassHttpBody ?
Re: Squid-ICAP problem (bug?)
Hello,
Thanks for you support.
I tried the patch from Tsantilas:
if (icap-chunk_size 0)
icap-flags.reqmod_http_entity_eof = 1;
instead of:
if (icap-reqmod.http_entity.bytes_read = icap-request-content_length)
icap-flags.reqmod_http_entity_eof = 1;
And that corrects the initial problem: remaining data waiting on the
wire is read (\r\n0\r\n).
But there is a new problem.
After the conditionnal call to commSetSelect there is a conditionnal
call to icapReqModPassHttpBody and this where is the problem:
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,
icap-reqmod.http_entity.callback,
icap-reqmod.http_entity.callback_data);
icap-reqmod.http_entity.callback = NULL;
cbdataUnlock(icap-reqmod.http_entity.callback_data);
}
When calling this function, the test is on
icap-reqmod.http_entity.buf.size but the parameter sent to the function
is cap-reqmod.http_entity.callback_bufsize. Is it normal ?
I added some logs and here is the output:
2006/11/14 13:43:25| icapReqModReadHttpBody: FD 38 called
2006/11/14 13:43:25| icapReqModReadHttpBody: read returns 33
2006/11/14 13:43:25| icap_common.c:695: chunk_size=0
2006/11/14 13:43:25| icap_common.c:702: bufOffset=0, len=33
2006/11/14 13:43:25| icap_common.c:705: bufOffset=0, len=33
2006/11/14 13:43:25| icapParseChunkSize: buf=0x9e362d0, len=33
2006/11/14 13:43:25| icapParseChunkSize: start=0
2006/11/14 13:43:25| icapLineLength: returning 4
2006/11/14 13:43:25| icapParseChunkSize: start=0, end=2
2006/11/14 13:43:25| icapParseChunkSize: return nextStart=4
2006/11/14 13:43:25| got chunksize 27, new offset 4
2006/11/14 13:43:25| icap_common.c:723: X
2006/11/14 13:43:25| icap_common.c:705: bufOffset=31, len=33
2006/11/14 13:43:25| icapParseChunkSize: buf=0x9e362ef, len=2
2006/11/14 13:43:25| icapParseChunkSize: start=0
2006/11/14 13:43:25| icapLineLength: returning 2
2006/11/14 13:43:25| icapParseChunkSize: start=2
2006/11/14 13:43:25| icap_reqmod.c:882 chunk_size=0
2006/11/14 13:43:25| icap_reqmod.c:892 http_entity.callback=(nil)
2006/11/14 13:43:25| icap_reqmod.c:894 http_entity.buf.size=27
2006/11/14 13:43:25| icap_reqmod.c:896 http_entity.callback_bufsize=0
2006/11/14 13:43:25| icapService: type=ICAP_SERVICE_REQMOD_POSTCACHE
2006/11/14 13:43:25| icapService: checking service service_3/id=0
2006/11/14 13:43:25| icapService: checking service service_4/id=0
2006/11/14 13:43:25| icapService: no service found
2006/11/14 13:43:25| icapReqModPassHttpBody: called
2006/11/14 13:43:25| icapReqModPassHttpBody: entity buf size = 27
2006/11/14 13:43:25| icapReqModPassHttpBody: giving 27 bytes to other side
2006/11/14 13:43:25| icapReqModPassHttpBody: entity buf size now = 0
2006/11/14 13:43:25| icapReqModPassHttpBody: called
2006/11/14 13:43:25| icapReqModPassHttpBody: entity buf size = 0
2006/11/14 13:43:25| icapReqModReadHttpBody: FD 38 called
2006/11/14 13:43:25| icapReqModReadHttpBody: read returns 5
2006/11/14 13:43:25| icap_common.c:695: chunk_size=0
2006/11/14 13:43:25| icap_common.c:702: bufOffset=0, len=7
2006/11/14 13:43:25| icap_common.c:705: bufOffset=0, len=7
2006/11/14 13:43:25| icapParseChunkSize: buf=0x9e362d0, len=7
2006/11/14 13:43:25| icapParseChunkSize: start=0
2006/11/14 13:43:25| icapLineLength: returning 2
2006/11/14 13:43:25| icapParseChunkSize: start=2
2006/11/14 13:43:25| icapLineLength: returning 3
2006/11/14 13:43:25| icapParseChunkSize: start=2, end=3
2006/11/14 13:43:25| icapParseChunkSize: return nextStart=5
2006/11/14 13:43:25| got chunksize -2, new offset 5
2006/11/14 13:43:25| zero end chunk reached
2006/11/14 13:43:25| icap_reqmod.c:882 chunk_size=-2
2006/11/14 13:43:25| icap_reqmod.c:892 http_entity.callback=0x807c994
2006/11/14 13:43:25| icap_reqmod.c:894 http_entity.buf.size=0
2006/11/14 13:43:25| icap_reqmod.c:896 http_entity.callback_bufsize=8192
2006/11/14 13:43:25| icapReqModPassHttpBody: called
FATAL: Received Segment Violation...dying.
Perhaps there is a problem with parameters passed to
icapReqModPassHttpBody ?
Christophe.
Re: Squid-ICAP problem (bug?)
ons 2006-11-08 klockan 16:26 +0100 skrev Christophe Boyanique: We have read enough data (27 bytes) to have all the body (as content-length is 27), so we set the eof flag. if (!icap-flags.reqmod_http_entity_eof) commSetSelect(fd, COMM_SELECT_READ, icapReqModReadHttpBody, icap, 0); eof in ICAP is that 0 chunk... so something is not right here in the ICAP patch. Note: As Adrian said most efforts is focused on the Squid-3 release, which also includes ICAP support. Regards Henrik signature.asc Description: Detta är en digitalt signerad meddelandedel
Re: Squid-ICAP problem (bug?)
Henrik Nordstrom a écrit : We have read enough data (27 bytes) to have all the body (as content-length is 27), so we set the eof flag. if (!icap-flags.reqmod_http_entity_eof) commSetSelect(fd, COMM_SELECT_READ, icapReqModReadHttpBody, icap, 0); eof in ICAP is that 0 chunk... so something is not right here in the ICAP patch. The problem is that this 0\r\n arrives after the first read of the 27 first bytes. Note: As Adrian said most efforts is focused on the Squid-3 release, which also includes ICAP support. I understand that but the problem is that we have this bug in production on heavy loaded site (we took several weeks to find it out) and we have to correct it anyway (and I don't think think that targetting Squid3 is possible (I thought Squid3 was considered beta?)). Regards, Christophe.
Re: Squid-ICAP problem (bug?)
Hi, I send this mail from un account which is not subscribed to the mailing list so I am re-sending it. Sory about that. Please to the mailing list moderator to ingore the first mail. - Hi Christophe, First of all squid3 has a better support for icap protocol now. Maybe it is better to use squid3 as icap client. However, yes the problem looks that exists in squid25-icap and squid26-icap. In fle icap_reqmod.c, in function icapReqModReadHttpBody near line 878-880 try this small patch : -if (icap-reqmod.http_entity.bytes_read = icap-request-content_length) - icap-flags.reqmod_http_entity_eof = 1; + // if (icap-reqmod.http_entity.bytes_read = icap-request-content_length ) + if (icap-chunk_size 0 ) + icap-flags.reqmod_http_entity_eof = 1; It must marks the http_entity_eof when it has read the 0\r\n\r\n chunk. Works for me but I did not test it enough Regards, Christos Christophe Boyanique wrote: Hello, I think I have found a bug in the Squid-ICAP patch and I would like to have your opinion about it. I use a tcpdump strace and verbose log to track a problem which occurs sometimes during a respmod request but is triggered during the reqmod answer analysis I think. We use squid-2.5.STABLE14 and Squid-Icap patch from 2006/06/26. .
Re: Squid-ICAP problem (bug?)
On Thu, Nov 09, 2006, Christophe Boyanique wrote: Note: As Adrian said most efforts is focused on the Squid-3 release, which also includes ICAP support. I understand that but the problem is that we have this bug in production on heavy loaded site (we took several weeks to find it out) and we have to correct it anyway (and I don't think think that targetting Squid3 is possible (I thought Squid3 was considered beta?)). I think it'd be great if the bug were fixed in squid-2.6-icap - but this kinda stuff also needs to go into squid-3. Squid-3 won't be beta for long if I have anything to say about it in a couple of weeks. Adrian
Re: Squid-ICAP problem (bug?)
tor 2006-11-09 klockan 12:37 +0200 skrev Tsantilas Christos: + if (icap-chunk_size 0 ) + icap-flags.reqmod_http_entity_eof = 1; Shouldn't that be = 0 or maybe even == 0? Regards Henrik signature.asc Description: Detta är en digitalt signerad meddelandedel
Re: Squid-ICAP problem (bug?)
Hi, I think it should be icap-chunk_size == -2. In icapParseChunkSize function in common_icap.c file the icap-chunk_size set to -2 when the 0\r\n\r\n sequence parsed Regards, Christos Henrik Nordstrom wrote: tor 2006-11-09 klockan 12:37 +0200 skrev Tsantilas Christos: + if (icap-chunk_size 0 ) + icap-flags.reqmod_http_entity_eof = 1; Shouldn't that be = 0 or maybe even == 0? Regards Henrik
Squid-ICAP problem (bug?)
Hello, I think I have found a bug in the Squid-ICAP patch and I would like to have your opinion about it. I use a tcpdump strace and verbose log to track a problem which occurs sometimes during a respmod request but is triggered during the reqmod answer analysis I think. We use squid-2.5.STABLE14 and Squid-Icap patch from 2006/06/26. Here is the request sent by Squid to the ICAP server (webwasher): --- begin cut --- REQMOD icap://10.17.30.41:1344/wwreqmod/?wwprofile=HTTP_Sortante ICAP/1.0 Encapsulated: req-hdr=0, req-body=1021 X-Client-IP: 129.182.109.109 X-Authenticated-User: V2lOVDovL2VyaWM= POST http://bubv-u.fraz.bull.fr/ulysse/SelTypF2.jsp HTTP/1.1 Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/x-shockwave-flash, application/vnd.ms-excel, application/vnd.ms-powerpoint, application/msword, */* Referer: http://bubv-u.fraz.bull.fr/ulysse/SelTypF1.jsp Accept-Language: fr Content-Type: application/x-www-form-urlencoded Accept-Encoding: gzip, deflate User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322) Host: bubv-u.fraz.bull.fr Content-Length: 27 Proxy-Connection: Keep-Alive Pragma: no-cache Cookie: REFUTI=27930; LANGUE=FR; NOM=BUL78604FR; STE=BUL; USER=UBUL_BUL78604FR; JSESSIONID=FE83A4E238E9375B7A9C55F6EE76C7EA; WS_LastUid=frank-e; WS_UsrRef=FRANK-E; WS_UsrLng=FR; WS_UsrSid=9743; WS_UsrAut=ClBiRTt7Nz59IjBscjXnrypOQWMAAwd7cnRcW3lZNFd8T3t3JGtgbSxMPXFyc3RUNFhzfjR%2bcjxQVjRcZWEmTGBLLVI6KCM8SHYoTjhSXm97WVtBOnggb3B1KEdhbyZ7ZS1cLywvIDZoLE5lNSxtK09YXEY1QlE1fHBobztxfEsyPSxcTA== Proxy-Authorization: Basic ZXJpYzplcmlj 1b GOTO=TRI=ORDER=COD=LIB= 0 end cut The request seems ok, the string GOTO=TRI=ORDER=COD=LIB= is 27 characters long as specified in the Content-Lenght header. The request is sent successfully to webwasher: 2006/11/02 15:10:23| icapReqModSendBodyChunk: FD 34 wrote 1208 errflag 0. 2006/11/02 15:10:23| icapReqModBodyHandler: writing chunk size 27 2006/11/02 15:10:23| icapReqModSendBodyChunk: FD 34 wrote 33 errflag 0. 2006/11/02 15:10:23| icapReqModBodyHandler: writing chunk size 0 2006/11/02 15:10:23| icapSendReqModDone: FD 34: size 5: errflag 0. Then comes the response from webwasher. The problem is that the response seems to be split in several packets. Here is the first part: --- begin cut --- ICAP/1.0 200 OK Cache-Control: max-age=3600 Encapsulated: req-hdr=0, req-body=1021 ISTAG: 001-000-000162 X-Attribute-Cacheability: user=V2lOVDovL2VyaWM= X-ICAP-Profile: HTTP_Sortante POST http://bubv-u.fraz.bull.fr/ulysse/SelTypF2.jsp HTTP/1.1 Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/x-shockwave-flash, application/vnd.ms-excel, application/vnd.ms-powerpoint, application/msword, */* Accept-Encoding: gzip, deflate Accept-Language: fr Content-Length: 27 Content-Type: application/x-www-form-urlencoded Cookie: REFUTI=27930; LANGUE=FR; NOM=BUL78604FR; STE=BUL; USER=UBUL_BUL78604FR; JSESSIONID=24FE81492AD05440B0434197D087AC18; WS_LastUid=frank-e; WS_UsrRef=FRANK-E; WS_UsrLng=FR; WS_UsrSid=3168; WS_UsrAut=ClBiRTt7Nz59IjBsckIn7iooyDAAAwd7cnRcW3lZNFd8T3t3JGtgbSxMPXFyc3RUNFhzfjR%2bcjxQVjRcZWEmTGBLLVI6KCM8SHYoTjhSXm97WVtBOnggb3B1KEdhbyZ7ZS1cLywvIDZoLE5lNSxtK09YXEY1QlE1fHBobztxfEsyPSxcTA== Host: bubv-u.fraz.bull.fr Pragma: no-cache Proxy-Authorization: Basic ZXJpYzplcmlj Proxy-Connection: Keep-Alive Referer: http://bubv-u.fraz.bull.fr/ulysse/SelTypF1.jsp User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322) 1B GOTO=TRI=ORDER=COD=LIB= end cut And the second part: --- begin cut --- 0 end cut The problem is that the end of the chunk (0\r\n\r\n) is not sent (and read) in the same stream that the beginning of the chunk. If we dig in the squid-icap source code we see: 2006/11/02 15:10:23| icapReqModReadHttpBody: FD 34 called 2006/11/02 15:10:23| icapReqModReadHttpBody: read returns 33 - this is the first part read 2006/11/02 15:10:23| icap_common.c:695: chunk_size=0 2006/11/02 15:10:23| icap_common.c:702: bufOffset=0, len=33 2006/11/02 15:10:23| icap_common.c:705: bufOffset=0, len=33 2006/11/02 15:10:23| icapParseChunkSize: buf=0x8f832e8, len=33 2006/11/02 15:10:23| icapParseChunkSize: start=0 2006/11/02 15:10:23| icapLineLength: returning 4 - this is the part 1b\r\n 2006/11/02 15:10:23| icapParseChunkSize: start=0, end=2 - this is 1b 2006/11/02 15:10:23| icapParseChunkSize: return nextStart=4 2006/11/02 15:10:23| got chunksize 27, new offset 4 - 1b - 27 bytes, to read at offset 4 (after 1b\r\n) 2006/11/02 15:10:23| icap_common.c:723: X 2006/11/02 15:10:23| icap_common.c:705: bufOffset=31, len=33 2006/11/02 15:10:23| icapParseChunkSize: buf=0x8f83307, len=2 2006/11/02 15:10:23| icapParseChunkSize: start=0 2006/11/02 15:10:23| icapLineLength: returning 2 2006/11/02 15:10:23| icapParseChunkSize: start=2 This is where is the first problem: after reading the first chunk size (1b) and the 27 bytes of data, the buffer only
