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
