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=AAAAClBiRTt7Nz59IjBscjXnrypOQWMAAwAAAAd7cnRcW3lZAAAANFd8T3t3JGtgbSxMPXFyc3RUNFhzfjR%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=AAAAClBiRTt7Nz59IjBsckIn7iooyDAAAwAAAAd7cnRcW3lZAAAANFd8T3t3JGtgbSxMPXFyc3RUNFhzfjR%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 contains "\r\n" left.

So there is no more chunk size to read and the while loop stops (in the
icapParseChunkedBody function in icap_commons.c):

2006/11/02 15:10:23| icap_reqmod.c:884 http_entity.callback=(nil)
2006/11/02 15:10:23| icap_reqmod.c:886 http_entity.buf.size=27

Here is the function icapReqModReadHttpBody (in icap_reqmod.c) which
reads data from network:

         icap->reqmod.http_entity.bytes_read +=
             icapParseChunkedBody(icap,
             icapReqModMemBufAppend, &icap->reqmod.http_entity.buf);

So, after the "dechunkization" of the body we have

icap->reqmod.http_entity.bytes_read = 27

The second problem occurs there:

     if (icap->reqmod.http_entity.bytes_read >=
icap->request->content_length)
         icap->flags.reqmod_http_entity_eof = 1;

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);

The eof flag is set so we do not read again data from webwasher
althought there is still the "\0\r\n" data waiting on the wire !

So Squid goes on to another task (in this cas this is to call a respmod
request):

2006/11/02 15:10:23| icapSendRespMod: Create a new connection to icap
server service_4/icap://10.17.30.41:1344/wwrespmod/?wwprofile=HTTP_Sortante
2006/11/02 15:10:23| icapConnect: reused pconn FD 34
2006/11/02 15:10:23| icapConnectOver: FD 34, status=0
2006/11/02 15:10:23| icapSendRespMod: new connection to icap server
(using FD=34)

and sends the request to Webwasher:

2006/11/02 15:10:23| icapSendRespModDone: FD 34: size 2746: errflag 0.
2006/11/02 15:10:23| icapSendRespModDone: FD 34: commSetSelect on read
icapRespModReadReply.

and while waiting the respmod's request answer receives the end of the
previous reqmod request:

--- begin cut ---
0\r\n\r\n
---- end cut ----

2006/11/02 15:10:23| recv(FD 34, ..., MSG_PEEK) ret 5
2006/11/02 15:10:23| headlen=5
2006/11/02 15:10:23| Parse icap header : <0

At this moment squid thinks that this is the response of the respmod
request and throws an error:

> from ICAP server
service_4/icap://10.17.30.41:1344/wwrespmod/?wwprofile=HTTP_Sortante
2006/11/02 15:10:23| BAD ICAP status line <0

> from ICAP server
service_4/icap://10.17.30.41:1344/wwrespmod/?wwprofile=HTTP_Sortante
2006/11/02 15:10:23| icapStateFree: FD 34, icap 0x8f8a5a8

I do not know if webwasher should send the last part of the chunk in a
new stream, but on the squid-icap part it cannot work this way and I do
not see an easy patch to correct this problem as the
icapParseChunkedBody returns the correct length read !

The webwasher support sads this is "a misinterpreation of the Squid client".

What is your point of view ?

Cordialement,

Christophe Boyanique.

-- 
http://www.alcove.fr - Alcôve: L'informatique est libre !
15 avenue de l'Agent Sarre - 92700 Colombes
Tél : +33 1 46 49 25 00 - Fax : +33 1 46 49 25 01