Re: issue with ICAP message for redirecting HTTPS/CONNECT

Hi Marcus,

There's a bug in your ICAP server with how it's handling the
Encapsulated header that it sends back to Squid. This is what your
server sent back to Squid for a REQMOD request:

Encapsulated: res-hdr=0, null-body=193<0d>
X-Next-Services: <0d>
<0d>
CONNECT blockedhttps.urlfilterdb.com:443 HTTP/1.0<0d>
  -- NOTE: also fails: CONNECT https://blockedhttps.urlfilterdb.com
HTTP/1.0<0d>

<snipped for brevity>

The Encapsulated header says that the HTTP object that has been sent
back contains HTTP response headers, and no body. This leads Squid to
believe it should be parsing a HTTP response, which expects the first
token of the first line to begin with HTTP/, which is failing because
the server has actually sent back a HTTP request. This explains the
error in the logs, and why it's working for your GET and POST
responses, which do indeed contain HTTP response objects.

So for this particular example, the correct Encapsulated header value
would be 'req-hdr=0, null-body=193'.

I hope that helps,

Nathan.

--
Nathan Hoad
Software Developer
www.getoffmalawn.com
On 9 June 2014 00:22, Marcus Kool <marcus.kool_at_urlfilterdb.com> wrote:
> I ran into an issue with the ICAP interface.
> The issue is that a GET/HTTP-based URL can be successfully rewritten but a
> CONNECT/HTTPS-based URL cannot.  I used debug_options ALL,9 to find out what
> is going wrong
> but I fail to understand Squid.
>
> GET/HTTP to http://googleads.g.doubleclick.net works:
>
> Squid writes:
> REQMOD icap://127.0.0.1:1344/reqmod_icapd_squid34 ICAP/1.0<0d>
> Host: 127.0.0.1:1344<0d>
> Date: Sun, 08 Jun 2014 13:54:09 GMT<0d>
> Encapsulated: req-hdr=0, null-body=135<0d>
> Preview: 0<0d>
> Allow: 204<0d>
> X-Client-IP: 127.0.0.1<0d>
> <0d>
> GET http://googleads.g.doubleclick.net/ HTTP/1.0<0d>
> User-Agent: Wget/1.12 (linux-gnu)<0d>
> Accept: */*<0d>
> Host: googleads.g.doubleclick.net<0d>
> <0d>
>
> ICAP daemon responds:
> ICAP/1.0 200 OK<0d>
> Server: ufdbICAPd/1.0<0d>
> Date: Sun, 08 Jun 2014 13:54:09 GMT<0d>
> ISTag: "5394572c-4567"<0d>
> Connection: keep-alive<0d>
> Encapsulated: res-hdr=0, null-body=233<0d>
> X-Next-Services: <0d>
> <0d>
> HTTP/1.0 200 OK<0d>
> Date: Sun, 08 Jun 2014 13:54:09 GMT<0d>
> Server: ufdbICAPd/1.0<0d>
> Last-Modified: Sun, 08 Jun 2014 13:54:09 GMT<0d>
> ETag: "498a-00000001-5394572c-4567"<0d>
> Cache-Control: max-age=10<0d>
> Content-Length: 0<0d>
> Content-Type: text/html<0d>
> <0d>
> 0<0d>
> <0d>
>
>
> CONNECT/HTTPS does not work:
>
> Squid writes:
> REQMOD icap://127.0.0.1:1344/reqmod_icapd_squid34 ICAP/1.0<0d>
> Host: 127.0.0.1:1344<0d>
> Date: Sun, 08 Jun 2014 12:29:32 GMT<0d>
> Encapsulated: req-hdr=0, null-body=87<0d>
> Preview: 0<0d>
> Allow: 204<0d>
> X-Client-IP: 127.0.0.1<0d>
> <0d>
> CONNECT googleads.g.doubleclick.net:443 HTTP/1.0<0d>
> User-Agent: Wget/1.12 (linux-gnu)<0d>
> <0d>
>
> ICAP daemon responds:
> ICAP/1.0 200 OK<0d>
> Server: ufdbICAPd/1.0<0d>
> Date: Sun, 08 Jun 2014 12:29:32 GMT<0d>
> ISTag: "5394572c-4567"<0d>
> Connection: keep-alive<0d>
> Encapsulated: res-hdr=0, null-body=193<0d>
> X-Next-Services: <0d>
> <0d>
> CONNECT blockedhttps.urlfilterdb.com:443 HTTP/1.0<0d>                    --
> NOTE: also fails: CONNECT https://blockedhttps.urlfilterdb.com HTTP/1.0<0d>
> Host: blockedhttps.urlfilterdb.com<0d>
> User-Agent: Wget/1.12 (linux-gnu)<0d>
> X-blocked-URL: googleads.g.doubleclick.net<0d>
> X-blocked-category: ads<0d>
> <0d>
> 0<0d>
> <0d>
>
> and Squid in the end responds to wget:
> HTTP/1.1 500 Internal Server Error
> Server: squid/3.4.5
> Mime-Version: 1.0
> Date: Sun, 08 Jun 2014 13:59:27 GMT
> Content-Type: text/html
> Content-Length: 2804
> X-Squid-Error: ERR_ICAP_FAILURE 0
> Vary: Accept-Language
> Content-Language: en
> X-Cache: MISS from XXX
> X-Cache-Lookup: NONE from XXX:3128
> Via: 1.1 XXX (squid/3.4.5)
> Connection: close
>
> A fragment of cache.log is below.
> I think that the line
> HttpReply.cc(460) sanityCheckStartLine: HttpReply::sanityCheckStartLine:
> missing protocol prefix (HTTP/) in 'CONNECT blockedhttps.urlfilterdb.com:443
> HTTP/1.0<0d>
> indicates where the problem is.
>
> Questions:
> The ICAP reply has a HTTP/ "protocol prefix" so does Squid have a problem
> parsing the reply?
>
> What is the issue with the reply of the ICAP daemon?
>
> Not directly related, but interesting: why does Squid sends
>    CONNECT googleads.g.doubleclick.net:443 HTTP/1.0
> to the ICAP daemon instead of
>    CONNECT https://googleads.g.doubleclick.net HTTP/1.0
>
> Thanks
> Marcus
>
> ------------------------ cache.log:
> -----------------------------------------
> 2014/06/08 09:29:32.224 kid1| Xaction.cc(413) noteCommRead: read 384 bytes
> 2014/06/08 09:29:32.224 kid1| Xaction.cc(73) disableRetries:
> Adaptation::Icap::ModXact from now on cannot be retried  [FD 12;rG/RwP(ieof)
> job9]
> 2014/06/08 09:29:32.224 kid1| ModXact.cc(646) parseMore: have 384 bytes to
> parse [FD 12;rG/RwP(ieof) job9]
> 2014/06/08 09:29:32.224 kid1| ModXact.cc(647) parseMore:
> ICAP/1.0 200 OK<0d>
> Server: ufdbICAPd/1.0<0d>
> Date: Sun, 08 Jun 2014 12:29:32 GMT<0d>
> ISTag: "5394572c-4567"<0d>
> Connection: keep-alive<0d>
> Encapsulated: res-hdr=0, null-body=193<0d>
> X-Next-Services: <0d>
> <0d>
> CONNECT blockedhttps.urlfilterdb.com:443 HTTP/1.0<0d>
> Host: blockedhttps.urlfilterdb.com<0d>
> User-Agent: Wget/1.12 (linux-gnu)<0d>
> X-blocked-URL: googleads.g.doubleclick.net<0d>
> X-blocked-category: ads<0d>
> <0d>
> 0<0d>
> <0d>
>
> 2014/06/08 09:29:32.224 kid1| ModXact.cc(742) parseHeaders: parse ICAP
> headers
> 2014/06/08 09:29:32.224 kid1| ModXact.cc(1072) parseHead: have 384 head
> bytes to parse; state: 0
> 2014/06/08 09:29:32.224 kid1| HttpHeader.cc(557) parse: parsing hdr:
> (0x1f3e978)
> Server: ufdbICAPd/1.0<0d>
> Date: Sun, 08 Jun 2014 12:29:32 GMT<0d>
> ISTag: "5394572c-4567"<0d>
> Connection: keep-alive<0d>
> Encapsulated: res-hdr=0, null-body=193<0d>
> X-Next-Services: <0d>
>
> 2014/06/08 09:29:32.224 kid1| HttpHeader.cc(1582) parse: parsing
> HttpHeaderEntry: near 'Server: ufdbICAPd/1.0'
> 2014/06/08 09:29:32.224 kid1| HttpHeader.cc(1624) parse: parsed
> HttpHeaderEntry: 'Server: ufdbICAPd/1.0'
> 2014/06/08 09:29:32.224 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f61a10: 'Server : ufdbICAPd/1.0
> 2014/06/08 09:29:32.224 kid1| HttpHeader.cc(907) addEntry: 0x1f3e978 adding
> entry: 52 at 0
> 2014/06/08 09:29:32.224 kid1| HttpHeader.cc(1582) parse: parsing
> HttpHeaderEntry: near 'Date: Sun, 08 Jun 2014 12:29:32 GMT'
> 2014/06/08 09:29:32.224 kid1| HttpHeader.cc(1624) parse: parsed
> HttpHeaderEntry: 'Date: Sun, 08 Jun 2014 12:29:32 GMT'
> 2014/06/08 09:29:32.224 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f3f420: 'Date : Sun, 08 Jun 2014 12:29:32 GMT
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(907) addEntry: 0x1f3e978 adding
> entry: 21 at 1
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1582) parse: parsing
> HttpHeaderEntry: near 'ISTag: "5394572c-4567"'
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1624) parse: parsed
> HttpHeaderEntry: 'ISTag: "5394572c-4567"'
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f83550: 'ISTag : "5394572c-4567"
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(907) addEntry: 0x1f3e978 adding
> entry: 77 at 2
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1582) parse: parsing
> HttpHeaderEntry: near 'Connection: keep-alive'
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1624) parse: parsed
> HttpHeaderEntry: 'Connection: keep-alive'
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f835f0: 'Connection : keep-alive
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(907) addEntry: 0x1f3e978 adding
> entry: 9 at 3
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1582) parse: parsing
> HttpHeaderEntry: near 'Encapsulated: res-hdr=0, null-body=193'
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1624) parse: parsed
> HttpHeaderEntry: 'Encapsulated: res-hdr=0, null-body=193'
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f61b40: 'Encapsulated : res-hdr=0, null-body=193
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(907) addEntry: 0x1f3e978 adding
> entry: 77 at 4
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1582) parse: parsing
> HttpHeaderEntry: near 'X-Next-Services: '
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1624) parse: parsed
> HttpHeaderEntry: 'X-Next-Services: '
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f61be0: 'X-Next-Services :
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(907) addEntry: 0x1f3e978 adding
> entry: 73 at 5
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1127) has: 0x1f3e978 lookup for
> 58
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1127) has: 0x1f3e978 lookup for
> 45
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1127) has: 0x1f3e978 lookup for
> 9
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(979) getList: 0x1f3e978joining
> for id 9
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1002) getList: 0x1f3e978: joined
> for id 9: keep-alive
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1127) has: 0x1f3e978 lookup for
> 24
> 2014/06/08 09:29:32.225 kid1| HttpMsg.cc(199) parse: HttpMsg::parse success
> (186 bytes) near 'ICAP/1.0 200 OK<0d>
> Server: ufdbICAPd/1.0<0d>
> Date: Sun, 08 Jun 2014 12:29:32 GMT<0d>
> ISTag: "5394572c-4567"<0d>
> Connection: keep-alive<0d>
> Encapsulated: res-hdr=0, null-body=193<0d>
> X-Next-Services: <0d>
> <0d>
> CONNECT blockedhttps.urlfilterdb.com:443 HTTP/1.0<0d>
> Host: blockedhttps.urlfilterdb.com<0d>
> User-Agent: Wget/1.12 (linux-gnu)<0d>
> X-blocked-URL: googleads.g.doubleclick.net<0d>
> X-blocked-category: ads<0d>
> <0d>
> 0<0d>
> <0d>
> '
> 2014/06/08 09:29:32.225 kid1| ModXact.cc(1087) parseHead: parse success,
> consume 186 bytes, return true
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1127) has: 0x1f3e978 lookup for
> 45
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1127) has: 0x1f3e978 lookup for
> 9
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(979) getList: 0x1f3e978joining
> for id 9
> 2014/06/08 09:29:32.225 kid1| HttpHeader.cc(1002) getList: 0x1f3e978: joined
> for id 9: keep-alive
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(947) getList: 0x1f3e978 joining
> for id 73
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(966) getList: empty list header:
> X-Next-Services(73)
> 2014/06/08 09:29:32.226 kid1| History.cc(127) updateNextServices: new
> services:
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(442) clean: cleaning hdr:
> 0x1f40008 owner: 3
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(837) delById: 0x1f40008
> del-by-id 52
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(837) delById: 0x1f40008
> del-by-id 21
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(818) delByName: deleting 'ISTag'
> fields in hdr 0x1f40008
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(837) delById: 0x1f40008
> del-by-id 9
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(818) delByName: deleting
> 'Encapsulated' fields in hdr 0x1f40008
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(837) delById: 0x1f40008
> del-by-id 73
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(533) update: Updating header
> 'Server' in cached entry
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f61c80: 'Server : ufdbICAPd/1.0
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(907) addEntry: 0x1f40008 adding
> entry: 52 at 0
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(533) update: Updating header
> 'Date' in cached entry
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f61d50: 'Date : Sun, 08 Jun 2014 12:29:32 GMT
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(907) addEntry: 0x1f40008 adding
> entry: 21 at 1
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(533) update: Updating header
> 'Other:' in cached entry
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f61dc0: 'ISTag : "5394572c-4567"
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(907) addEntry: 0x1f40008 adding
> entry: 77 at 2
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(533) update: Updating header
> 'Connection' in cached entry
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f61e60: 'Connection : keep-alive
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(907) addEntry: 0x1f40008 adding
> entry: 9 at 3
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(533) update: Updating header
> 'Other:' in cached entry
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f829c0: 'Encapsulated : res-hdr=0, null-body=193
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(907) addEntry: 0x1f40008 adding
> entry: 77 at 4
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(533) update: Updating header
> 'X-Next-Services' in cached entry
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f82a60: 'X-Next-Services :
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(907) addEntry: 0x1f40008 adding
> entry: 73 at 5
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(837) delById: 0x1f40038
> del-by-id 52
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(837) delById: 0x1f40038
> del-by-id 21
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(818) delByName: deleting 'ISTag'
> fields in hdr 0x1f40038
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(837) delById: 0x1f40038
> del-by-id 9
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(818) delByName: deleting
> 'Encapsulated' fields in hdr 0x1f40038
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(837) delById: 0x1f40038
> del-by-id 73
> 2014/06/08 09:29:32.226 kid1| HttpHeader.cc(533) update: Updating header
> 'Server' in cached entry
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f82b00: 'Server : ufdbICAPd/1.0
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(907) addEntry: 0x1f40038 adding
> entry: 52 at 0
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(533) update: Updating header
> 'Date' in cached entry
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f82c30: 'Date : Sun, 08 Jun 2014 12:29:32 GMT
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(907) addEntry: 0x1f40038 adding
> entry: 21 at 1
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(533) update: Updating header
> 'Other:' in cached entry
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f82cd0: 'ISTag : "5394572c-4567"
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(907) addEntry: 0x1f40038 adding
> entry: 77 at 2
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(533) update: Updating header
> 'Connection' in cached entry
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f82d70: 'Connection : keep-alive
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(907) addEntry: 0x1f40038 adding
> entry: 9 at 3
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(533) update: Updating header
> 'Other:' in cached entry
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f82e10: 'Encapsulated : res-hdr=0, null-body=193
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(907) addEntry: 0x1f40038 adding
> entry: 77 at 4
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(533) update: Updating header
> 'X-Next-Services' in cached entry
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created
> HttpHeaderEntry 0x1f82eb0: 'X-Next-Services :
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(907) addEntry: 0x1f40038 adding
> entry: 73 at 5
> 2014/06/08 09:29:32.227 kid1| ModXact.cc(747) parseHeaders: parse HTTP
> headers
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(407) HttpHeader: init-ing hdr:
> 0x1f82fc8 owner: 3
> 2014/06/08 09:29:32.227 kid1| cbdata.cc(324) cbdataInternalAlloc:
> cbdataAlloc: 0x1f3f3e8
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1127) has: 0x1f82fc8 lookup for
> 45
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1127) has: 0x1f82fc8 lookup for
> 9
> 2014/06/08 09:29:32.227 kid1| HttpHeader.cc(1127) has: 0x1f82fc8 lookup for
> 24
> 2014/06/08 09:29:32.227 kid1| Xaction.cc(502) setOutcome: ICAP_SAT
> 2014/06/08 09:29:32.227 kid1| ModXact.cc(1072) parseHead: have 198 head
> bytes to parse; state: 1
> 2014/06/08 09:29:32.227 kid1| HttpReply.cc(460) sanityCheckStartLine:
> HttpReply::sanityCheckStartLine: missing protocol prefix (HTTP/) in 'CONNECT
> blockedhttps.urlfilterdb.com:443 HTTP/1.0<0d>
> Host: blockedhttps.urlfilterdb.com<0d>
> User-Agent: Wget/1.12 (linux-gnu)<0d>
> X-blocked-URL: googleads.g.doubleclick.net<0d>
> X-blocked-category: ads<0d>
> <0d>
> 0<0d>
> <0d>
> '
> 2014/06/08 09:29:32.227 kid1| TextException.cc(79) Throw: ModXact.cc:1076:
> exception: parsed || !error
> 2014/06/08 09:29:32.228 kid1| ../../../src/base/AsyncJobCalls.h(169) dial:
> Adaptation::Icap::Xaction::noteCommRead threw exception: parsed || !error
> 2014/06/08 09:29:32.228 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3f188
> 2014/06/08 09:29:32.228 kid1| HttpRequest.cc(496) detailError: current error
> details: 35/396407268
> 2014/06/08 09:29:32.228 kid1| Xaction.cc(500) setOutcome: Warning: reseting
> outcome: from ICAP_SAT to ICAP_ERR_OTHER
> 2014/06/08 09:29:32.228 kid1| ServiceRep.cc(74) noteFailure:  failure 1 out
> of 10 allowed in 0sec [up,fail1]
> 2014/06/08 09:29:32.228 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3f188
> 2014/06/08 09:29:32.228 kid1| AsyncJob.cc(78) mustStop:
> Adaptation::Icap::ModXact will stop, reason: exception
> 2014/06/08 09:29:32.228 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3f188
> 2014/06/08 09:29:32.228 kid1| AsyncJob.cc(131) callEnd:
> Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:39225
> remote=127.0.0.1:1344 FD 12 flags=1, data=0x1f3f188, size=384,
> buf=0x1f50bc0) ends job [FD 12;rp(1)S(2)G/RwP(ieof) job9]
> 2014/06/08 09:29:32.228 kid1| ModXact.cc(1235) swanSong: swan sings [FD
> 12;rp(1)S(2)G/RwP(ieof) job9]
> 2014/06/08 09:29:32.228 kid1| ModXact.cc(609) stopSending: Enter stop
> sending
> 2014/06/08 09:29:32.228 kid1| ModXact.cc(612) stopSending: Proceed with stop
> sending
> 2014/06/08 09:29:32.228 kid1| ModXact.cc(615) stopSending: will no longer
> send [FD 12;rp(1)S(2)G/RwP(ieof) job9]
> 2014/06/08 09:29:32.228 kid1| HttpRequest.cc(495) detailError: old error
> details: 35/396407268
> 2014/06/08 09:29:32.228 kid1| HttpRequest.cc(496) detailError: current error
> details: 35/100013
> 2014/06/08 09:29:32.228 kid1| comm.cc(1253) comm_remove_close_handler:
> comm_remove_close_handler: FD 12, AsyncCall=0x1f3e670*2
> 2014/06/08 09:29:32.228 kid1| AsyncCall.cc(48) cancel: will not call
> Adaptation::Icap::Xaction::noteCommClosed [call47] because
> comm_remove_close_handler
> 2014/06/08 09:29:32.228 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3f188=4
> 2014/06/08 09:29:32.228 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3f188=3
> 2014/06/08 09:29:32.228 kid1| Xaction.cc(205) closeConnection: not reusing
> pconn due to pending I/O [FD 12;rp(1)G/RwP(ieof)S job9]
> 2014/06/08 09:29:32.228 kid1| ServiceRep.cc(131) putConnection: RST-closing
> [FD 12;rp(1)G/RwP(ieof)S job9]
> 2014/06/08 09:29:32.228 kid1| comm.cc(1080) _comm_close: comm_close: start
> closing FD 12
> 2014/06/08 09:29:32.228 kid1| comm.cc(755) commUnsetFdTimeout: Remove
> timeout for FD 12
> 2014/06/08 09:29:32.228 kid1| comm.cc(933) commCallCloseHandlers:
> commCallCloseHandlers: FD 12
> 2014/06/08 09:29:32.228 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall
> comm_close_complete constructed, this=0x1f61eb0 [call53]
> 2014/06/08 09:29:32.228 kid1| AsyncCall.cc(85) ScheduleCall: comm.cc(1156)
> will call comm_close_complete(FD 12) [call53]
> 2014/06/08 09:29:32.228 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.228 kid1| cbdata.cc(419) cbdataInternalLock: cbdataLock:
> 0x1f3e758=3
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(419) cbdataInternalLock: cbdataLock:
> 0x1f3e758=4
> 2014/06/08 09:29:32.229 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall
> Launcher::noteXactAbort constructed, this=0x1f3e670 [call54]
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(419) cbdataInternalLock: cbdataLock:
> 0x1f3e758=5
> 2014/06/08 09:29:32.229 kid1| AsyncCall.cc(85) ScheduleCall: Xaction.cc(543)
> will call Launcher::noteXactAbort(0,0) [call54]
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3e758=4
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3e758=3
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3e758=2
> 2014/06/08 09:29:32.229 kid1| HttpHeader.cc(713) packInto: packing hdr:
> (0x1f82fc8)
> 2014/06/08 09:29:32.229 kid1| HttpHeader.cc(713) packInto: packing hdr:
> (0x1f3dc48)
> 2014/06/08 09:29:32.229 kid1| HttpHeader.cc(713) packInto: packing hdr:
> (0x1f3dc48)
> 2014/06/08 09:29:32.229 kid1| HttpHeader.cc(713) packInto: packing hdr:
> (0x1f40008)
> 2014/06/08 09:29:32.229 kid1| History.cc(40) processingTime:  current total:
> 48 0x1f3e7e0
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f38378
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f38378
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(419) cbdataInternalLock: cbdataLock:
> 0x1f38378=5
> 2014/06/08 09:29:32.229 kid1| Checklist.cc(62) preCheck: 0x7fff798456b0
> checking fast ACLs
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(419) cbdataInternalLock: cbdataLock:
> 0x199c668=1
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x199c668
> 2014/06/08 09:29:32.229 kid1| Acl.cc(157) matches: checking icap_log
> /local/squid34/logs/icap.log
> 2014/06/08 09:29:32.229 kid1| Acl.cc(157) matches: checking (icap_log
> /local/squid34/logs/icap.log line)
> 2014/06/08 09:29:32.229 kid1| Acl.cc(177) matches: checked: (icap_log
> /local/squid34/logs/icap.log line) = 1
> 2014/06/08 09:29:32.229 kid1| Acl.cc(177) matches: checked: icap_log
> /local/squid34/logs/icap.log = 1
> 2014/06/08 09:29:32.229 kid1| Checklist.cc(55) markFinished: 0x7fff798456b0
> answer ALLOWED for match
> 2014/06/08 09:29:32.229 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x199c668=0
> 2014/06/08 09:29:32.230 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f38378=4
> 2014/06/08 09:29:32.230 kid1| FilledChecklist.cc(61) ~ACLFilledChecklist:
> ACLFilledChecklist destroyed 0x7fff798456b0
> 2014/06/08 09:29:32.230 kid1| Checklist.cc(189) ~ACLChecklist:
> ACLChecklist::~ACLChecklist: destroyed 0x7fff798456b0
> 2014/06/08 09:29:32.230 kid1| Initiate.cc(58) swanSong: swan sings
> [p(1)G/RwP(ieof)S job9]
> 2014/06/08 09:29:32.230 kid1| Initiate.cc(65) swanSong: swan sang
> [p(1)G/RwP(ieof)S job9]
> 2014/06/08 09:29:32.230 kid1| Xaction.cc(59) ~Xaction:
> Adaptation::Icap::ModXact destructed, this=0x1f3f188 [icapxjob9]
> 2014/06/08 09:29:32.230 kid1| HttpHeader.cc(442) clean: cleaning hdr:
> 0x1f82fc8 owner: 3
> 2014/06/08 09:29:32.230 kid1| cbdata.cc(348) cbdataInternalFree: cbdataFree:
> 0x1f3f3e8
> 2014/06/08 09:29:32.230 kid1| cbdata.cc(365) cbdataInternalFree: cbdataFree:
> Freeing 0x1f3f3e8
> 2014/06/08 09:29:32.230 kid1| HttpHeader.cc(442) clean: cleaning hdr:
> 0x1f82fc8 owner: 3
> 2014/06/08 09:29:32.230 kid1| AsyncJob.cc(34) ~AsyncJob: AsyncJob
> destructed, this=0x1f3f338 type=Adaptation::Icap::ModXact [job9]
> 2014/06/08 09:29:32.230 kid1| cbdata.cc(348) cbdataInternalFree: cbdataFree:
> 0x1f3f188
> 2014/06/08 09:29:32.230 kid1| cbdata.cc(360) cbdataInternalFree: cbdataFree:
> 0x1f3f188 has 3 locks, not freeing
> 2014/06/08 09:29:32.230 kid1| AsyncJob.cc(141) callEnd:
> Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:39225
> remote=127.0.0.1:1344 flags=1, data=0x1f3f188, size=384, buf=0x1f50bc0)
> ended 0x1f3f338
> 2014/06/08 09:29:32.230 kid1| AsyncCallQueue.cc(53) fireNext: leaving
> Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:39225
> remote=127.0.0.1:1344 flags=1, data=0x1f3f188, size=384, buf=0x1f50bc0)
> 2014/06/08 09:29:32.230 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3f188=2
> 2014/06/08 09:29:32.230 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3f188=1
> 2014/06/08 09:29:32.230 kid1| AsyncCallQueue.cc(51) fireNext: entering
> comm_close_complete(FD 12)
> 2014/06/08 09:29:32.230 kid1| AsyncCall.cc(30) make: make call
> comm_close_complete [call53]
> 2014/06/08 09:29:32.230 kid1| fd.cc(116) fd_close: fd_close FD 12 127.0.0.1
> 2014/06/08 09:29:32.230 kid1| ModEpoll.cc(139) SetSelect: FD 12, type=1,
> handler=0, client_data=0, timeout=0
> 2014/06/08 09:29:32.230 kid1| ModEpoll.cc(139) SetSelect: FD 12, type=2,
> handler=0, client_data=0, timeout=0
> 2014/06/08 09:29:32.230 kid1| AcceptLimiter.cc(47) kick: size=0
> 2014/06/08 09:29:32.230 kid1| AsyncCallQueue.cc(53) fireNext: leaving
> comm_close_complete(FD 12)
> 2014/06/08 09:29:32.230 kid1| AsyncCallQueue.cc(51) fireNext: entering
> Launcher::noteXactAbort(0,0)
> 2014/06/08 09:29:32.230 kid1| AsyncCall.cc(30) make: make call
> Launcher::noteXactAbort [call54]
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.231 kid1| AsyncJob.cc(117) callStart:
> Adaptation::Icap::ModXactLauncher status in: [ job8]
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.231 kid1| Launcher.cc(79) noteXactAbort:
> theXaction:0x1f3f188/0x1f3f188 launches: 1
> 2014/06/08 09:29:32.231 kid1| Launcher.cc(121) canRepeat: 0
> 2014/06/08 09:29:32.231 kid1| Launcher.cc(89) noteXactAbort: cannot retry or
> repeat a failed transaction
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3f188=0
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(473) cbdataInternalUnlock:
> cbdataUnlock: Freeing 0x1f3f188
> 2014/06/08 09:29:32.231 kid1| Answer.cc(14) Error: error: 0
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3eda8
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(419) cbdataInternalLock: cbdataLock:
> 0x1f3eda8=3
> 2014/06/08 09:29:32.231 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall
> Initiator::noteAdaptationAnswer constructed, this=0x1f83340 [call55]
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3eda8
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(419) cbdataInternalLock: cbdataLock:
> 0x1f3eda8=4
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3eda8=3
> 2014/06/08 09:29:32.231 kid1| AsyncCall.cc(85) ScheduleCall: Initiate.cc(77)
> will call Initiator::noteAdaptationAnswer(2) [call55]
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(456) cbdataInternalUnlock:
> cbdataUnlock: 0x1f3eda8=2
> 2014/06/08 09:29:32.231 kid1| cbdata.cc(510) cbdataReferenceValid:
> cbdataReferenceValid: 0x1f3e758
> 2014/06/08 09:29:32.231 kid1| AsyncJob.cc(131) callEnd:
> Launcher::noteXactAbort(0,0) ends job [ job8]
> 2014/06/08 09:29:32.231 kid1| ModXact.cc(1966) swanSong: swan sings
> 2014/06/08 09:29:32.231 kid1| History.cc(31) stop: stop ICAPModXactLauncher
> level=1 time=3+48 0x1f3e7e0
> 2014/06/08 09:29:32.231 kid1| Initiate.cc(58) swanSong: swan sings [ job8]
> 2014/06/08 09:29:32.231 kid1| Initiate.cc(65) swanSong: swan sang [ job8]
> 2014/06/08 09:29:32.231 kid1| AsyncJob.cc(34) ~AsyncJob: AsyncJob
> destructed, this=0x1f3e7b0 type=Adaptation::Icap::ModXactLauncher [job8]
>