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.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]
>>
>
>
Received on Sun Jun 08 2014 - 21:54:33 MDT
This archive was generated by hypermail 2.2.0 : Mon Jun 09 2014 - 12:00:11 MDT