issue with ICAP message for redirecting HTTPS/CONNECT

From: Marcus Kool <marcus.kool_at_urlfilterdb.com>
Date: Sun, 08 Jun 2014 11:22:54 -0300

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]
Received on Sun Jun 08 2014 - 14:23:16 MDT

This archive was generated by hypermail 2.2.0 : Mon Jun 09 2014 - 12:00:11 MDT