Re: issue with ICAP message for redirecting HTTPS/CONNECT

[Marcus Kool]

Thanks Nathan, that helped.
Sometimes it is frustrating to just not see the small error...

Marcus

On 06/08/2014 01:02 PM, Nathan Hoad wrote:

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.k...@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]