Recent squid-3.HEAD-BZR failed to accessing https://mail.google.com,
but was ok prior to March 19. Attached is the cache.log with this line in
particular ...
assertion failed: comm.cc:216: "fd_table[fd].halfClosedReader != NULL"
Thanks,
Jeff
2011/04/04 09:55:26.234 kid1| IoCallback.cc(120) will call
ConnStateData::clientReadRequest(FD 11, data=0x23e0548, size=183,
buf=0x238b410) [call19]
2011/04/04 09:55:26.234 kid1| entering ConnStateData::clientReadRequest(FD 11,
data=0x23e0548, size=183, buf=0x238b410)
2011/04/04 09:55:26.234 kid1| AsyncCall.cc(32) make: make call
ConnStateData::clientReadRequest [call19]
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| ConnStateData status in: [ job2]
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| client_side.cc(2765) clientReadRequest:
clientReadRequest FD 11 size 183
2011/04/04 09:55:26.234 kid1| client_side.cc(2705) clientParseRequest: FD 11:
attempting to parse
2011/04/04 09:55:26.234 kid1| httpParseInit: Request buffer is CONNECT
mail.google.com:443 HTTP/1.1
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:2.2a1pre) Gecko/20110402
Firefox/4.2a1pre
Proxy-Connection: keep-alive
Host: mail.google.com
2011/04/04 09:55:26.234 kid1| HttpMsg.cc(458) parseRequestFirstLine: parsing
possible request: CONNECT mail.google.com:443 HTTP/1.1
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:2.2a1pre) Gecko/20110402
Firefox/4.2a1pre
Proxy-Connection: keep-alive
Host: mail.google.com
2011/04/04 09:55:26.234 kid1| Parser: retval 1: from 0->37: method 0->6; url
8->26; version 28->35 (1/1)
2011/04/04 09:55:26.234 kid1| parseHttpRequest: req_hdr = {User-Agent:
Mozilla/5.0 (X11; Linux x86_64; rv:2.2a1pre) Gecko/20110402 Firefox/4.2a1pre
Proxy-Connection: keep-alive
Host: mail.google.com
}
2011/04/04 09:55:26.234 kid1| parseHttpRequest: end = {
}
2011/04/04 09:55:26.234 kid1| parseHttpRequest: prefix_sz = 183, req_line_sz =
38
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e0548=7
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e0a78=1
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x22946d8=1
2011/04/04 09:55:26.234 kid1| clientStreamInsertHead: Inserted node 0x23e3518
with data 0x23e2128 after head
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e3518=1
2011/04/04 09:55:26.234 kid1| parseHttpRequest: Request Header is
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:2.2a1pre) Gecko/20110402
Firefox/4.2a1pre
Proxy-Connection: keep-alive
Host: mail.google.com
2011/04/04 09:55:26.234 kid1| parseHttpRequest: Complete request received
2011/04/04 09:55:26.234 kid1| client_side.cc(2743) clientParseRequest: FD 11:
parsed a request
2011/04/04 09:55:26.234 kid1| comm.cc(1116) commSetTimeout: FD 11 timeout 86400
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e0a78=2
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e0a78=3
2011/04/04 09:55:26.234 kid1| The AsyncCall SomeTimeoutHandler constructed,
this=0x21297a0 [call20]
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e0a78=4
2011/04/04 09:55:26.234 kid1| cbdataUnlock: 0x23e0a78=3
2011/04/04 09:55:26.234 kid1| cbdataUnlock: 0x23e0a78=2
2011/04/04 09:55:26.234 kid1| comm.cc(1127) commSetTimeout: FD 11 timeout 86400
2011/04/04 09:55:26.234 kid1| cbdataUnlock: 0x23e0548=6
2011/04/04 09:55:26.234 kid1| cbdataUnlock: 0x23e0548=5
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| urlParse: Split URL 'mail.google.com:443' into
proto='', host='mail.google.com', port='443', path=''
2011/04/04 09:55:26.234 kid1| init-ing hdr: 0x2388740 owner: 2
2011/04/04 09:55:26.234 kid1| HttpRequest.cc(59) HttpRequest: constructed,
this=0x2388730 id=54
2011/04/04 09:55:26.234 kid1| Address.cc(409) LookupHostIP: Given Non-IP
'mail.google.com': Name or service not known
2011/04/04 09:55:26.234 kid1| parsing hdr: (0x2388740)
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:2.2a1pre) Gecko/20110402
Firefox/4.2a1pre
Proxy-Connection: keep-alive
Host: mail.google.com
2011/04/04 09:55:26.234 kid1| parsing HttpHeaderEntry: near 'User-Agent:
Mozilla/5.0 (X11; Linux x86_64; rv:2.2a1pre) Gecko/20110402 Firefox/4.2a1pre'
2011/04/04 09:55:26.234 kid1| parsed HttpHeaderEntry: 'User-Agent: Mozilla/5.0
(X11; Linux x86_64; rv:2.2a1pre) Gecko/20110402 Firefox/4.2a1pre'
2011/04/04 09:55:26.234 kid1| created HttpHeaderEntry 0x2295990: 'User-Agent :
Mozilla/5.0 (X11; Linux x86_64; rv:2.2a1pre) Gecko/20110402 Firefox/4.2a1pre
2011/04/04 09:55:26.234 kid1| 0x2388740 adding entry: 58 at 0
2011/04/04 09:55:26.234 kid1| parsing HttpHeaderEntry: near 'Proxy-Connection:
keep-alive'
2011/04/04 09:55:26.234 kid1| parsed HttpHeaderEntry: 'Proxy-Connection:
keep-alive'
2011/04/04 09:55:26.234 kid1| created HttpHeaderEntry 0x23e3930:
'Proxy-Connection : keep-alive
2011/04/04 09:55:26.234 kid1| 0x2388740 adding entry: 41 at 1
2011/04/04 09:55:26.234 kid1| parsing HttpHeaderEntry: near 'Host:
mail.google.com'
2011/04/04 09:55:26.234 kid1| parsed HttpHeaderEntry: 'Host: mail.google.com'
2011/04/04 09:55:26.234 kid1| created HttpHeaderEntry 0x23e3820: 'Host :
mail.google.com
2011/04/04 09:55:26.234 kid1| 0x2388740 adding entry: 26 at 2
2011/04/04 09:55:26.234 kid1| 0x2388740 lookup for 54
2011/04/04 09:55:26.234 kid1| 0x2388740 lookup for 54
2011/04/04 09:55:26.234 kid1| 0x2388740 lookup for 54
2011/04/04 09:55:26.234 kid1| 0x2388740 lookup for 24
2011/04/04 09:55:26.234 kid1| clientSetKeepaliveFlag: http_ver = 1.1
2011/04/04 09:55:26.234 kid1| clientSetKeepaliveFlag: method = CONNECT
2011/04/04 09:55:26.234 kid1| 0x2388740 lookup for 41
2011/04/04 09:55:26.234 kid1| 0x2388740joining for id 41
2011/04/04 09:55:26.234 kid1| 0x2388740: joined for id 41: keep-alive
2011/04/04 09:55:26.234 kid1| client_side.h(82) mayUseConnection: This
0x23e10b8 marked 1
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e0a78=3
2011/04/04 09:55:26.234 kid1| client_side_request.cc(143) ClientRequestContext:
0x23e1058 ClientRequestContext constructed
2011/04/04 09:55:26.234 kid1| client_side_request.cc(1296) doCallouts: Doing
calloutContext->clientAccessCheck()
2011/04/04 09:55:26.234 kid1| 0x2388740 lookup for 66
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x20bf4a8=1
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e0548=6
2011/04/04 09:55:26.234 kid1| cbdataLock: 0x23e1058=1
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x23e1058
2011/04/04 09:55:26.234 kid1| cbdataReferenceValid: 0x20bf4a8
2011/04/04 09:55:26.234 kid1| ACLChecklist::preCheck: 0x23e3b18 checking
'http_access allow manager clients'
2011/04/04 09:55:26.234 kid1| ACLList::matches: checking manager
2011/04/04 09:55:26.234 kid1| ACL::checklistMatches: checking 'manager'
2011/04/04 09:55:26.234 kid1| ACL::ChecklistMatches: result for 'manager' is 0
2011/04/04 09:55:26.234 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.234 kid1| aclmatchAclList: 0x23e3b18 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.235 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.235 kid1| cbdataLock: 0x20bfc58=1
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x20bf4a8=0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x20bfc58
2011/04/04 09:55:26.235 kid1| ACLChecklist::preCheck: 0x23e3b18 checking
'http_access deny manager'
2011/04/04 09:55:26.235 kid1| ACLList::matches: checking manager
2011/04/04 09:55:26.235 kid1| ACL::checklistMatches: checking 'manager'
2011/04/04 09:55:26.235 kid1| ACL::ChecklistMatches: result for 'manager' is 0
2011/04/04 09:55:26.235 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.235 kid1| aclmatchAclList: 0x23e3b18 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.235 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.235 kid1| cbdataLock: 0x20c01a8=1
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x20bfc58=0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x20c01a8
2011/04/04 09:55:26.235 kid1| ACLChecklist::preCheck: 0x23e3b18 checking
'http_access deny asia1'
2011/04/04 09:55:26.235 kid1| ACLList::matches: checking asia1
2011/04/04 09:55:26.235 kid1| ACL::checklistMatches: checking 'asia1'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: checking 'mail.google.com'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: 'mail.google.com' NOT found
2011/04/04 09:55:26.235 kid1| ACL::ChecklistMatches: result for 'asia1' is 0
2011/04/04 09:55:26.235 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.235 kid1| aclmatchAclList: 0x23e3b18 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.235 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.235 kid1| cbdataLock: 0x20c04b8=1
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x20c01a8=0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x20c04b8
2011/04/04 09:55:26.235 kid1| ACLChecklist::preCheck: 0x23e3b18 checking
'http_access deny atwola'
2011/04/04 09:55:26.235 kid1| ACLList::matches: checking atwola
2011/04/04 09:55:26.235 kid1| ACL::checklistMatches: checking 'atwola'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: checking 'mail.google.com'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: 'mail.google.com' NOT found
2011/04/04 09:55:26.235 kid1| ACL::ChecklistMatches: result for 'atwola' is 0
2011/04/04 09:55:26.235 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.235 kid1| aclmatchAclList: 0x23e3b18 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.235 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.235 kid1| cbdataLock: 0x20c0548=1
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x20c04b8=0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x20c0548
2011/04/04 09:55:26.235 kid1| ACLChecklist::preCheck: 0x23e3b18 checking
'http_access deny doubleclick'
2011/04/04 09:55:26.235 kid1| ACLList::matches: checking doubleclick
2011/04/04 09:55:26.235 kid1| ACL::checklistMatches: checking 'doubleclick'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: checking 'mail.google.com'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: 'mail.google.com' NOT found
2011/04/04 09:55:26.235 kid1| ACL::ChecklistMatches: result for 'doubleclick'
is 0
2011/04/04 09:55:26.235 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.235 kid1| aclmatchAclList: 0x23e3b18 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.235 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.235 kid1| cbdataLock: 0x20c06e8=1
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x20c0548=0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x20c06e8
2011/04/04 09:55:26.235 kid1| ACLChecklist::preCheck: 0x23e3b18 checking
'http_access deny hitua'
2011/04/04 09:55:26.235 kid1| ACLList::matches: checking hitua
2011/04/04 09:55:26.235 kid1| ACL::checklistMatches: checking 'hitua'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: checking 'mail.google.com'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: 'mail.google.com' NOT found
2011/04/04 09:55:26.235 kid1| ACL::ChecklistMatches: result for 'hitua' is 0
2011/04/04 09:55:26.235 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.235 kid1| aclmatchAclList: 0x23e3b18 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.235 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.235 kid1| cbdataLock: 0x20c0ac8=1
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x20c06e8=0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x20c0ac8
2011/04/04 09:55:26.235 kid1| ACLChecklist::preCheck: 0x23e3b18 checking
'http_access deny cna'
2011/04/04 09:55:26.235 kid1| ACLList::matches: checking cna
2011/04/04 09:55:26.235 kid1| ACL::checklistMatches: checking 'cna'
2011/04/04 09:55:26.235 kid1| aclRegexData::match: checking 'mail.google.com'
2011/04/04 09:55:26.235 kid1| aclRegexData::match: looking for
'ad01\.mediacorp.*\.com'
2011/04/04 09:55:26.235 kid1| ACL::ChecklistMatches: result for 'cna' is 0
2011/04/04 09:55:26.235 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.235 kid1| aclmatchAclList: 0x23e3b18 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.235 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.235 kid1| cbdataLock: 0x20c1278=1
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x20c0ac8=0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x20c1278
2011/04/04 09:55:26.235 kid1| ACLChecklist::preCheck: 0x23e3b18 checking
'http_access deny razor razordst'
2011/04/04 09:55:26.235 kid1| ACLList::matches: checking razor
2011/04/04 09:55:26.235 kid1| ACL::checklistMatches: checking 'razor'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: checking 'mail.google.com'
2011/04/04 09:55:26.235 kid1| aclMatchDomainList: 'mail.google.com' NOT found
2011/04/04 09:55:26.235 kid1| ACL::ChecklistMatches: result for 'razor' is 0
2011/04/04 09:55:26.235 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.235 kid1| aclmatchAclList: 0x23e3b18 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.235 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x20c1278=0
2011/04/04 09:55:26.235 kid1| Checklist.cc(124) check: 0x23e3b18 NO match
found, returning 1
2011/04/04 09:55:26.235 kid1| FilledChecklist.cc(16) checkCallback: 0x23e3b18
answer=1
2011/04/04 09:55:26.235 kid1| ACLChecklist::checkCallback: 0x23e3b18 answer=1
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e1058
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x23e1058=0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e0a78
2011/04/04 09:55:26.235 kid1| The request CONNECT mail.google.com:443 is
ALLOWED, because it matched 'razor'
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.235 kid1| client_side_request.cc(1325) doCallouts: Doing
calloutContext->clientAccessCheck2()
2011/04/04 09:55:26.235 kid1| client_side_request.cc(554) clientAccessCheck2:
No adapted_http_access configuration.
2011/04/04 09:55:26.235 kid1| The request CONNECT mail.google.com:443 is
ALLOWED, because it matched 'razor'
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.235 kid1| client_side_request.cc(1332) doCallouts: Doing
clientInterpretRequestHeaders()
2011/04/04 09:55:26.235 kid1| 0x2388740 lookup for 37
2011/04/04 09:55:26.235 kid1| 0x2388740 del-by-id 44
2011/04/04 09:55:26.235 kid1| 0x2388740 del-by-id 45
2011/04/04 09:55:26.235 kid1| 0x2388740 lookup for 7
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.235 kid1| 0x2388740 lookup for 7
2011/04/04 09:55:26.235 kid1| 0x2388740 lookup for 40
2011/04/04 09:55:26.235 kid1| 0x2388740 lookup for 60
2011/04/04 09:55:26.235 kid1| clientInterpretRequestHeaders: REQ_NOCACHE = NOT
SET
2011/04/04 09:55:26.235 kid1| clientInterpretRequestHeaders: REQ_CACHABLE = NOT
SET
2011/04/04 09:55:26.235 kid1| clientInterpretRequestHeaders: REQ_HIERARCHICAL =
NOT SET
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.235 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist:
ACLFilledChecklist destroyed 0x7fff6cadeaa0
2011/04/04 09:55:26.235 kid1| ACLChecklist::~ACLChecklist: destroyed
0x7fff6cadeaa0
2011/04/04 09:55:26.235 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.235 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist:
ACLFilledChecklist destroyed 0x7fff6cade990
2011/04/04 09:55:26.235 kid1| ACLChecklist::~ACLChecklist: destroyed
0x7fff6cade990
2011/04/04 09:55:26.235 kid1| cbdataUnlock: 0x23e0a78=2
2011/04/04 09:55:26.235 kid1| client_side_request.cc(134)
~ClientRequestContext: 0x23e1058 ClientRequestContext destructed
2011/04/04 09:55:26.235 kid1| cbdataFree: 0x23e1058
2011/04/04 09:55:26.235 kid1| cbdataFree: Freeing 0x23e1058
2011/04/04 09:55:26.235 kid1| client_side_request.cc(1379) doCallouts: calling
processRequest()
2011/04/04 09:55:26.236 kid1| clientProcessRequest: CONNECT
'mail.google.com:443'
2011/04/04 09:55:26.236 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.236 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.236 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x20ba608=1
2011/04/04 09:55:26.236 kid1| aclCheckFast: list: 0x20ba608
2011/04/04 09:55:26.236 kid1| ACLChecklist::preCheck: 0x7fff6cade800 checking
'miss_access allow all'
2011/04/04 09:55:26.236 kid1| ACLList::matches: checking all
2011/04/04 09:55:26.236 kid1| ACL::checklistMatches: checking 'all'
2011/04/04 09:55:26.236 kid1| aclIpAddrNetworkCompare: compare:
192.168.243.1:54622/[::] ([::]:54622) vs [::]-[::]/[::]
2011/04/04 09:55:26.236 kid1| aclIpMatchIp: '192.168.243.1:54622' found
2011/04/04 09:55:26.236 kid1| ACL::ChecklistMatches: result for 'all' is 1
2011/04/04 09:55:26.236 kid1| ACLList::matches: result is true
2011/04/04 09:55:26.236 kid1| aclmatchAclList: 0x7fff6cade800 returning true
(AND list satisfied)
2011/04/04 09:55:26.236 kid1| ACLChecklist::markFinished: 0x7fff6cade800
checklist processing finished
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x20ba608=0
2011/04/04 09:55:26.236 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist:
ACLFilledChecklist destroyed 0x7fff6cade800
2011/04/04 09:55:26.236 kid1| ACLChecklist::~ACLChecklist: destroyed
0x7fff6cade800
2011/04/04 09:55:26.236 kid1| tunnelStart: 'CONNECT mail.google.com:443'
2011/04/04 09:55:26.236 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist:
ACLFilledChecklist destroyed 0x7fff6cade6b0
2011/04/04 09:55:26.236 kid1| ACLChecklist::~ACLChecklist: destroyed
0x7fff6cade6b0
2011/04/04 09:55:26.236 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist:
ACLFilledChecklist destroyed 0x7fff6cade6b0
2011/04/04 09:55:26.236 kid1| ACLChecklist::~ACLChecklist: destroyed
0x7fff6cade6b0
2011/04/04 09:55:26.236 kid1| comm_openex: Attempt open socket for: 0.0.0.0
2011/04/04 09:55:26.236 kid1| comm_openex: Opened socket FD 14 : family=2,
type=1, protocol=6
2011/04/04 09:55:26.236 kid1| comm_open: FD 14 is a new socket
2011/04/04 09:55:26.236 kid1| fd_open() FD 14 mail.google.com:443
2011/04/04 09:55:26.236 kid1| commBind: bind socket FD 14 to 0.0.0.0
2011/04/04 09:55:26.236 kid1| comm_local_port: FD 14: port 44214(family=2)
2011/04/04 09:55:26.236 kid1| comm_add_close_handler: FD 14, handler=1,
data=0x23e3988
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=1
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=2
2011/04/04 09:55:26.236 kid1| The AsyncCall SomeCloseHandler constructed,
this=0x22947b0 [call21]
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=3
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e3988=2
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e3988=1
2011/04/04 09:55:26.236 kid1| comm_add_close_handler: FD 14,
AsyncCall=0x22947b0*1
2011/04/04 09:55:26.236 kid1| comm_add_close_handler: FD 11, handler=1,
data=0x23e3988
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=2
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=3
2011/04/04 09:55:26.236 kid1| The AsyncCall SomeCloseHandler constructed,
this=0x23e3a00 [call22]
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=4
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e3988=3
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e3988=2
2011/04/04 09:55:26.236 kid1| comm_add_close_handler: FD 11,
AsyncCall=0x23e3a00*1
2011/04/04 09:55:26.236 kid1| comm.cc(1116) commSetTimeout: FD 11 timeout 86400
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=3
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=4
2011/04/04 09:55:26.236 kid1| The AsyncCall SomeTimeoutHandler constructed,
this=0x23e3a70 [call23]
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=5
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e3988=4
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e3988=3
2011/04/04 09:55:26.236 kid1| comm.cc(1127) commSetTimeout: FD 11 timeout 86400
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e0a78=1
2011/04/04 09:55:26.236 kid1| comm.cc(1116) commSetTimeout: FD 14 timeout 60
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=4
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=5
2011/04/04 09:55:26.236 kid1| The AsyncCall SomeTimeoutHandler constructed,
this=0x21297a0 [call24]
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=6
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e3988=5
2011/04/04 09:55:26.236 kid1| cbdataUnlock: 0x23e3988=4
2011/04/04 09:55:26.236 kid1| comm.cc(1127) commSetTimeout: FD 14 timeout 60
2011/04/04 09:55:26.236 kid1| peerSelect: CONNECT
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x23e3988=5
2011/04/04 09:55:26.236 kid1| peerSelectFoo: 'CONNECT mail.google.com'
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x20c0fe8=1
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x2405188=1
2011/04/04 09:55:26.236 kid1| cbdataReferenceValid: 0x2405188
2011/04/04 09:55:26.236 kid1| cbdataReferenceValid: 0x20c0fe8
2011/04/04 09:55:26.236 kid1| ACLChecklist::preCheck: 0x2405488 checking
'always_direct allow drac speedy12 fmail fmail2'
2011/04/04 09:55:26.236 kid1| ACLList::matches: checking drac
2011/04/04 09:55:26.236 kid1| ACL::checklistMatches: checking 'drac'
2011/04/04 09:55:26.236 kid1| ipcache_gethostbyname: 'mail.google.com', flags=1
2011/04/04 09:55:26.236 kid1| Address.cc(409) LookupHostIP: Given Non-IP
'mail.google.com': Name or service not known
2011/04/04 09:55:26.236 kid1| ipcache_nbgethostbyname: Name 'mail.google.com'.
2011/04/04 09:55:26.236 kid1| Address.cc(409) LookupHostIP: Given Non-IP
'mail.google.com': Name or service not known
2011/04/04 09:55:26.236 kid1| ipcache_nbgethostbyname: MISS for
'mail.google.com'
2011/04/04 09:55:26.236 kid1| idnsALookup: buf is 33 bytes for mail.google.com,
id = 0x0
2011/04/04 09:55:26.236 kid1| cbdataLock: 0x24050c8=1
2011/04/04 09:55:26.236 kid1| comm_udp_sendto: Attempt to send UDP packet to
127.0.0.1:53 using FD 7 using Port 17957
2011/04/04 09:55:26.236 kid1| event.cc(344) schedule: schedule: Adding
'idnsCheckQueue', in 5.00 seconds
2011/04/04 09:55:26.236 kid1| aclMatchAcl: Can't yet compare 'drac' ACL for
'mail.google.com'
2011/04/04 09:55:26.236 kid1| ACL::ChecklistMatches: result for 'drac' is 0
2011/04/04 09:55:26.236 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.236 kid1| aclmatchAclList: 0x2405488 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.236 kid1| ACLChecklist::asyncInProgress: 0x2405488 async
set to 1
2011/04/04 09:55:26.236 kid1| ipcache_nbgethostbyname: Name 'mail.google.com'.
2011/04/04 09:55:26.236 kid1| Address.cc(409) LookupHostIP: Given Non-IP
'mail.google.com': Name or service not known
2011/04/04 09:55:26.237 kid1| ipcache_nbgethostbyname: MISS for
'mail.google.com'
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x2405488=1
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x23e3808=1
2011/04/04 09:55:26.237 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=1 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x23e0548=5
2011/04/04 09:55:26.237 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist:
ACLFilledChecklist destroyed 0x23e3b18
2011/04/04 09:55:26.237 kid1| ACLChecklist::~ACLChecklist: destroyed 0x23e3b18
2011/04/04 09:55:26.237 kid1| cbdataFree: 0x23e3b18
2011/04/04 09:55:26.237 kid1| cbdataFree: Freeing 0x23e3b18
2011/04/04 09:55:26.237 kid1| client_side.cc(2364) connNoteUseOfBuffer:
conn->in.notYetUsed = 0
2011/04/04 09:55:26.237 kid1| client_side.cc(2752) clientParseRequest: Not
reading, as this request may need the connection
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.237 kid1| clientReadSomeData: FD 11: reading request...
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x23e0548=6
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x23e0548=7
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x23e0548=8
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x23e0548=9
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x23e0548=8
2011/04/04 09:55:26.237 kid1| The AsyncCall ConnStateData::clientReadRequest
constructed, this=0x2409bb0 [call25]
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x23e0548=9
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x23e0548=10
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x23e0548=9
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x23e0548=8
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x23e0548=7
2011/04/04 09:55:26.237 kid1| comm_read, queueing read for FD 11; asynCall
0x2409bb0*1
2011/04/04 09:55:26.237 kid1| ModEpoll.cc(137) SetSelect: FD 11, type=1,
handler=1, client_data=0x20e0ba0, timeout=0
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x23e0548
2011/04/04 09:55:26.237 kid1| ConnStateData status out: [ job2]
2011/04/04 09:55:26.237 kid1| leaving ConnStateData::clientReadRequest(FD 11,
data=0x23e0548, size=183, buf=0x238b410)
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x23e0548=6
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x23e0548=5
2011/04/04 09:55:26.237 kid1| Engine 0x7fff6cadf890 is idle.
2011/04/04 09:55:26.237 kid1| Engine 0x7fff6cadf8c0 is idle.
2011/04/04 09:55:26.237 kid1| ModEpoll.cc(289) DoSelect: got FD 7 events=1
monitoring=19 F->read_handler=1 F->write_handler=0
2011/04/04 09:55:26.237 kid1| ModEpoll.cc(295) DoSelect: Calling read handler
on FD 7
2011/04/04 09:55:26.237 kid1| idnsRead: starting with FD 7
2011/04/04 09:55:26.237 kid1| ModEpoll.cc(137) SetSelect: FD 7, type=1,
handler=1, client_data=0, timeout=0
2011/04/04 09:55:26.237 kid1| comm_udp_recvfrom: FD 7 from [::]
2011/04/04 09:55:26.237 kid1| idnsRead: FD 7: received 335 bytes from
127.0.0.1:53
2011/04/04 09:55:26.237 kid1| idnsGrokReply: QID 0x62ef, 5 answers
2011/04/04 09:55:26.237 kid1| dns_internal.cc(1241) idnsGrokReply: Sending 5
DNS results to caller.
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x24050c8
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x24050c8=0
2011/04/04 09:55:26.237 kid1| cbdataFree: 0x24050c8
2011/04/04 09:55:26.237 kid1| cbdataFree: Freeing 0x24050c8
2011/04/04 09:55:26.237 kid1| ipcacheParse: mail.google.com #0 74.125.235.23
2011/04/04 09:55:26.237 kid1| ipcacheParse: mail.google.com #1 74.125.235.24
2011/04/04 09:55:26.237 kid1| ipcacheParse: mail.google.com #2 74.125.235.21
2011/04/04 09:55:26.237 kid1| ipcacheParse: mail.google.com #3 74.125.235.22
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x23e3808
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x23e3808=0
2011/04/04 09:55:26.237 kid1| cbdataFree: 0x23e3808
2011/04/04 09:55:26.237 kid1| cbdataFree: Freeing 0x23e3808
2011/04/04 09:55:26.237 kid1| ipcacheParse: mail.google.com #0 74.125.235.23
2011/04/04 09:55:26.237 kid1| ipcacheParse: mail.google.com #1 74.125.235.24
2011/04/04 09:55:26.237 kid1| ipcacheParse: mail.google.com #2 74.125.235.21
2011/04/04 09:55:26.237 kid1| ipcacheParse: mail.google.com #3 74.125.235.22
2011/04/04 09:55:26.237 kid1| ipcacheRelease: Releasing entry for
'mail.google.com'
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x2405488
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x2405488=0
2011/04/04 09:55:26.237 kid1| ACLChecklist::asyncInProgress: 0x2405488 async
set to 0
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x2405188
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x20c0fe8
2011/04/04 09:55:26.237 kid1| ACLChecklist::preCheck: 0x2405488 checking
'always_direct allow drac speedy12 fmail fmail2'
2011/04/04 09:55:26.237 kid1| ACLList::matches: checking drac
2011/04/04 09:55:26.237 kid1| ACL::checklistMatches: checking 'drac'
2011/04/04 09:55:26.237 kid1| ipcache_gethostbyname: 'mail.google.com', flags=1
2011/04/04 09:55:26.237 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.23/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
10.1.1.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.237 kid1| aclIpMatchIp: '74.125.235.23' NOT found
2011/04/04 09:55:26.237 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.24/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
10.1.1.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.237 kid1| aclIpMatchIp: '74.125.235.24' NOT found
2011/04/04 09:55:26.237 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.21/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
10.1.1.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.237 kid1| aclIpMatchIp: '74.125.235.21' NOT found
2011/04/04 09:55:26.237 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.22/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
10.1.1.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.237 kid1| aclIpMatchIp: '74.125.235.22' NOT found
2011/04/04 09:55:26.237 kid1| ACL::ChecklistMatches: result for 'drac' is 0
2011/04/04 09:55:26.237 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.237 kid1| aclmatchAclList: 0x2405488 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.237 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x20c10a8=1
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x20c0fe8=0
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x20c10a8
2011/04/04 09:55:26.237 kid1| ACLChecklist::preCheck: 0x2405488 checking
'always_direct allow changi'
2011/04/04 09:55:26.237 kid1| ACLList::matches: checking changi
2011/04/04 09:55:26.237 kid1| ACL::checklistMatches: checking 'changi'
2011/04/04 09:55:26.237 kid1| aclMatchDomainList: checking 'mail.google.com'
2011/04/04 09:55:26.237 kid1| aclMatchDomainList: 'mail.google.com' NOT found
2011/04/04 09:55:26.237 kid1| ACL::ChecklistMatches: result for 'changi' is 0
2011/04/04 09:55:26.237 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.237 kid1| aclmatchAclList: 0x2405488 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.237 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.237 kid1| cbdataLock: 0x20c2298=1
2011/04/04 09:55:26.237 kid1| cbdataUnlock: 0x20c10a8=0
2011/04/04 09:55:26.237 kid1| cbdataReferenceValid: 0x20c2298
2011/04/04 09:55:26.237 kid1| ACLChecklist::preCheck: 0x2405488 checking
'always_direct allow xp5800'
2011/04/04 09:55:26.237 kid1| ACLList::matches: checking xp5800
2011/04/04 09:55:26.237 kid1| ACL::checklistMatches: checking 'xp5800'
2011/04/04 09:55:26.237 kid1| aclMatchDomainList: checking 'mail.google.com'
2011/04/04 09:55:26.238 kid1| aclMatchDomainList: 'mail.google.com' NOT found
2011/04/04 09:55:26.238 kid1| ACL::ChecklistMatches: result for 'xp5800' is 0
2011/04/04 09:55:26.238 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.238 kid1| aclmatchAclList: 0x2405488 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.238 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x20c2328=1
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x20c2298=0
2011/04/04 09:55:26.238 kid1| cbdataReferenceValid: 0x20c2328
2011/04/04 09:55:26.238 kid1| ACLChecklist::preCheck: 0x2405488 checking
'always_direct allow direct1'
2011/04/04 09:55:26.238 kid1| ACLList::matches: checking direct1
2011/04/04 09:55:26.238 kid1| ACL::checklistMatches: checking 'direct1'
2011/04/04 09:55:26.238 kid1| aclMatchDomainList: checking 'mail.google.com'
2011/04/04 09:55:26.238 kid1| aclMatchDomainList: 'mail.google.com' NOT found
2011/04/04 09:55:26.238 kid1| ACL::ChecklistMatches: result for 'direct1' is 0
2011/04/04 09:55:26.238 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.238 kid1| aclmatchAclList: 0x2405488 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.238 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x20c2b28=1
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x20c2328=0
2011/04/04 09:55:26.238 kid1| cbdataReferenceValid: 0x20c2b28
2011/04/04 09:55:26.238 kid1| ACLChecklist::preCheck: 0x2405488 checking
'always_direct allow accs-IPs'
2011/04/04 09:55:26.238 kid1| ACLList::matches: checking accs-IPs
2011/04/04 09:55:26.238 kid1| ACL::checklistMatches: checking 'accs-IPs'
2011/04/04 09:55:26.238 kid1| ipcache_gethostbyname: 'mail.google.com', flags=1
2011/04/04 09:55:26.238 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.23/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
155.161.233.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.238 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.23/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
155.161.200.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.238 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.23/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
155.161.22.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.238 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.22/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
155.161.22.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.238 kid1| aclIpAddrNetworkCompare: compare:
74.125.235.22/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00] (74.125.235.0) vs
155.161.22.0-[::]/[ffff:ffff:ffff:ffff:ffff:ffff:ffff:ff00]
2011/04/04 09:55:26.238 kid1| aclIpMatchIp: '74.125.235.22' NOT found
2011/04/04 09:55:26.238 kid1| ACL::ChecklistMatches: result for 'accs-IPs' is 0
2011/04/04 09:55:26.238 kid1| ACLList::matches: result is false
2011/04/04 09:55:26.238 kid1| aclmatchAclList: 0x2405488 returning false (AND
list entry failed to match)
2011/04/04 09:55:26.238 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x20c32c8=1
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x20c2b28=0
2011/04/04 09:55:26.238 kid1| cbdataReferenceValid: 0x20c32c8
2011/04/04 09:55:26.238 kid1| ACLChecklist::preCheck: 0x2405488 checking
'always_direct allow all'
2011/04/04 09:55:26.238 kid1| ACLList::matches: checking all
2011/04/04 09:55:26.238 kid1| ACL::checklistMatches: checking 'all'
2011/04/04 09:55:26.238 kid1| aclIpAddrNetworkCompare: compare:
192.168.243.1:54622/[::] ([::]:54622) vs [::]-[::]/[::]
2011/04/04 09:55:26.238 kid1| aclIpMatchIp: '192.168.243.1:54622' found
2011/04/04 09:55:26.238 kid1| ACL::ChecklistMatches: result for 'all' is 1
2011/04/04 09:55:26.238 kid1| ACLList::matches: result is true
2011/04/04 09:55:26.238 kid1| aclmatchAclList: 0x2405488 returning true (AND
list satisfied)
2011/04/04 09:55:26.238 kid1| ACLChecklist::markFinished: 0x2405488 checklist
processing finished
2011/04/04 09:55:26.238 kid1| ACLChecklist::check: 0x2405488 match found,
calling back with 1
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x20c32c8=0
2011/04/04 09:55:26.238 kid1| FilledChecklist.cc(16) checkCallback: 0x2405488
answer=1
2011/04/04 09:55:26.238 kid1| ACLChecklist::checkCallback: 0x2405488 answer=1
2011/04/04 09:55:26.238 kid1| cbdataReferenceValid: 0x2405188
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x2405188=0
2011/04/04 09:55:26.238 kid1| peerCheckAlwaysDirectDone: 1
2011/04/04 09:55:26.238 kid1| peerSelectFoo: 'CONNECT mail.google.com'
2011/04/04 09:55:26.238 kid1| peerSelectFoo: direct = DIRECT_YES
2011/04/04 09:55:26.238 kid1| peerAddFwdServer: adding DIRECT HIER_DIRECT
2011/04/04 09:55:26.238 kid1| cbdataReferenceValid: 0x23e3988
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x23e3988=4
2011/04/04 09:55:26.238 kid1| commConnectStart: FD 14, data 0x23e3988,
mail.google.com:443
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x23e3988=5
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x23e3988=6
2011/04/04 09:55:26.238 kid1| The AsyncCall SomeCommConnectHandler constructed,
this=0x240a5f0 [call26]
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x23e3988=7
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x23e3988=6
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x23e3988=5
2011/04/04 09:55:26.238 kid1| commConnectStart: FD 14, cb 0x240a5f0*1,
mail.google.com:443
2011/04/04 09:55:26.238 kid1| comm_add_close_handler: FD 14, handler=1,
data=0x24055b8
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x24055b8=1
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x24055b8=2
2011/04/04 09:55:26.238 kid1| The AsyncCall SomeCloseHandler constructed,
this=0x240a580 [call27]
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x24055b8=3
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x24055b8=2
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x24055b8=1
2011/04/04 09:55:26.238 kid1| comm_add_close_handler: FD 14,
AsyncCall=0x240a580*1
2011/04/04 09:55:26.238 kid1| ipcache_nbgethostbyname: Name 'mail.google.com'.
2011/04/04 09:55:26.238 kid1| Address.cc(409) LookupHostIP: Given Non-IP
'mail.google.com': Name or service not known
2011/04/04 09:55:26.238 kid1| ipcache_nbgethostbyname: HIT for
'mail.google.com'
2011/04/04 09:55:26.238 kid1| cbdataLock: 0x24055b8=2
2011/04/04 09:55:26.238 kid1| cbdataReferenceValid: 0x24055b8
2011/04/04 09:55:26.238 kid1| cbdataUnlock: 0x24055b8=1
2011/04/04 09:55:26.238 kid1| comm.cc(1034) connect: to 74.125.235.23:443
2011/04/04 09:55:26.238 kid1| comm.cc(1164) comm_connect_addr: connecting
socket FD 14 to 74.125.235.23:443 (want family: 2)
2011/04/04 09:55:26.239 kid1| comm_connect_addr: sock=14, addrinfo( flags=4,
family=2, socktype=1, protocol=6, &addr=0x240a530, addrlen=16 )
2011/04/04 09:55:26.239 kid1| connect FD 14: (-1) (115) Operation now in
progress
2011/04/04 09:55:26.239 kid1| connecting to: 74.125.235.23:443
2011/04/04 09:55:26.239 kid1| comm.cc(1039) connect: FD 14: COMM_INPROGRESS
2011/04/04 09:55:26.239 kid1| ModEpoll.cc(137) SetSelect: FD 14, type=2,
handler=1, client_data=0x24055b8, timeout=0
2011/04/04 09:55:26.239 kid1| cbdataFree: 0x2405188
2011/04/04 09:55:26.239 kid1| cbdataFree: Freeing 0x2405188
2011/04/04 09:55:26.239 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist:
ACLFilledChecklist destroyed 0x2405488
2011/04/04 09:55:26.239 kid1| ACLChecklist::~ACLChecklist: destroyed 0x2405488
2011/04/04 09:55:26.239 kid1| cbdataFree: 0x2405488
2011/04/04 09:55:26.239 kid1| cbdataFree: Freeing 0x2405488
2011/04/04 09:55:26.239 kid1| cbdataFree: 0x24079e8
2011/04/04 09:55:26.239 kid1| cbdataFree: Freeing 0x24079e8
2011/04/04 09:55:26.239 kid1| cbdataFree: 0x2405778
2011/04/04 09:55:26.239 kid1| cbdataFree: Freeing 0x2405778
2011/04/04 09:55:26.239 kid1| comm_udp_recvfrom: FD 7 from 127.0.0.1:53
2011/04/04 09:55:26.239 kid1| Engine 0x7fff6cadf890 is idle.
2011/04/04 09:55:26.239 kid1| Engine 0x7fff6cadf8c0 is idle.
2011/04/04 09:55:26.248 kid1| ModEpoll.cc(289) DoSelect: got FD 14 events=4
monitoring=1c F->read_handler=0 F->write_handler=1
2011/04/04 09:55:26.248 kid1| ModEpoll.cc(311) DoSelect: Calling write handler
on FD 14
2011/04/04 09:55:26.248 kid1| comm.cc(1034) connect: to 74.125.235.23:443
2011/04/04 09:55:26.248 kid1| comm.cc(1164) comm_connect_addr: connecting
socket FD 14 to 74.125.235.23:443 (want family: 2)
2011/04/04 09:55:26.248 kid1| comm.cc(1044) connect: FD 14: COMM_OK - connected
2011/04/04 09:55:26.248 kid1| commConnectCallback: FD 14
2011/04/04 09:55:26.248 kid1| comm_remove_close_handler: FD 14, handler=1,
data=0x24055b8
2011/04/04 09:55:26.248 kid1| cbdataUnlock: 0x24055b8=0
2011/04/04 09:55:26.248 kid1| comm.cc(1116) commSetTimeout: FD 14 timeout -1
2011/04/04 09:55:26.248 kid1| comm.cc(1127) commSetTimeout: FD 14 timeout -1
2011/04/04 09:55:26.248 kid1| cbdataUnlock: 0x23e3988=4
2011/04/04 09:55:26.248 kid1| comm.cc(854) will call SomeCommConnectHandler(FD
14, data=0x23e3988, ) [call26]
2011/04/04 09:55:26.248 kid1| commConnectFree: FD 14
2011/04/04 09:55:26.248 kid1| cbdataFree: 0x24055b8
2011/04/04 09:55:26.248 kid1| cbdataFree: Freeing 0x24055b8
2011/04/04 09:55:26.248 kid1| entering SomeCommConnectHandler(FD 14,
data=0x23e3988, )
2011/04/04 09:55:26.248 kid1| AsyncCall.cc(32) make: make call
SomeCommConnectHandler [call26]
2011/04/04 09:55:26.248 kid1| cbdataReferenceValid: 0x23e3988
2011/04/04 09:55:26.248 kid1| tunnelConnected: FD 14 tunnelState=0x23e3988
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=5
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=6
2011/04/04 09:55:26.248 kid1| The AsyncCall tunnelConnectedWriteDone
constructed, this=0x23e4e30 [call28]
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=7
2011/04/04 09:55:26.248 kid1| cbdataUnlock: 0x23e3988=6
2011/04/04 09:55:26.248 kid1| cbdataUnlock: 0x23e3988=5
2011/04/04 09:55:26.248 kid1| Write.cc(20) Write: FD 11: sz 39: asynCall
0x23e4e30*1
2011/04/04 09:55:26.248 kid1| ModEpoll.cc(137) SetSelect: FD 11, type=2,
handler=1, client_data=0x20e0bd0, timeout=0
2011/04/04 09:55:26.248 kid1| comm.cc(1116) commSetTimeout: FD 14 timeout 900
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=6
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=7
2011/04/04 09:55:26.248 kid1| The AsyncCall SomeTimeoutHandler constructed,
this=0x21297a0 [call29]
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=8
2011/04/04 09:55:26.248 kid1| cbdataUnlock: 0x23e3988=7
2011/04/04 09:55:26.248 kid1| cbdataUnlock: 0x23e3988=6
2011/04/04 09:55:26.248 kid1| comm.cc(1127) commSetTimeout: FD 14 timeout 900
2011/04/04 09:55:26.248 kid1| leaving SomeCommConnectHandler(FD 14,
data=0x23e3988, )
2011/04/04 09:55:26.248 kid1| cbdataUnlock: 0x23e3988=5
2011/04/04 09:55:26.248 kid1| Engine 0x7fff6cadf890 is idle.
2011/04/04 09:55:26.248 kid1| Engine 0x7fff6cadf8c0 is idle.
2011/04/04 09:55:26.248 kid1| ModEpoll.cc(289) DoSelect: got FD 14 events=4
monitoring=1c F->read_handler=0 F->write_handler=0
2011/04/04 09:55:26.248 kid1| ModEpoll.cc(318) DoSelect: no write handler for
FD 14
2011/04/04 09:55:26.248 kid1| ModEpoll.cc(137) SetSelect: FD 14, type=2,
handler=0, client_data=0, timeout=0
2011/04/04 09:55:26.248 kid1| ModEpoll.cc(289) DoSelect: got FD 11 events=4
monitoring=1d F->read_handler=1 F->write_handler=1
2011/04/04 09:55:26.248 kid1| ModEpoll.cc(311) DoSelect: Calling write handler
on FD 11
2011/04/04 09:55:26.248 kid1| Write.cc(50) HandleWrite: FD 11: off 0, sz 39.
2011/04/04 09:55:26.248 kid1| Write.cc(90) HandleWrite: write() returns 39
2011/04/04 09:55:26.248 kid1| IoCallback.cc(102) finish: called for FD 11 (0,
0)
2011/04/04 09:55:26.248 kid1| IoCallback.cc(120) will call
tunnelConnectedWriteDone(FD 11, data=0x23e3988, size=39, buf=0x615708) [call28]
2011/04/04 09:55:26.248 kid1| entering tunnelConnectedWriteDone(FD 11,
data=0x23e3988, size=39, buf=0x615708)
2011/04/04 09:55:26.248 kid1| AsyncCall.cc(32) make: make call
tunnelConnectedWriteDone [call28]
2011/04/04 09:55:26.248 kid1| cbdataReferenceValid: 0x23e3988
2011/04/04 09:55:26.248 kid1| cbdataReferenceValid: 0x23e3988
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=6
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=7
2011/04/04 09:55:26.248 kid1| The AsyncCall SomeCommReadHandler constructed,
this=0x240a080 [call30]
2011/04/04 09:55:26.248 kid1| cbdataLock: 0x23e3988=8
2011/04/04 09:55:26.248 kid1| cbdataUnlock: 0x23e3988=7
2011/04/04 09:55:26.249 kid1| cbdataUnlock: 0x23e3988=6
2011/04/04 09:55:26.249 kid1| comm_read, queueing read for FD 14; asynCall
0x240a080*1
2011/04/04 09:55:26.249 kid1| ModEpoll.cc(137) SetSelect: FD 14, type=1,
handler=1, client_data=0x20e0cd8, timeout=0
2011/04/04 09:55:26.249 kid1| cbdataLock: 0x23e3988=7
2011/04/04 09:55:26.249 kid1| cbdataLock: 0x23e3988=8
2011/04/04 09:55:26.249 kid1| The AsyncCall SomeCommReadHandler constructed,
this=0x2409f10 [call31]
2011/04/04 09:55:26.249 kid1| cbdataLock: 0x23e3988=9
2011/04/04 09:55:26.249 kid1| cbdataUnlock: 0x23e3988=8
2011/04/04 09:55:26.249 kid1| cbdataUnlock: 0x23e3988=7
2011/04/04 09:55:26.249 kid1| comm_read, queueing read for FD 11; asynCall
0x2409f10*1
2011/04/04 09:55:26.249 kid1| assertion failed: comm.cc:216:
"fd_table[fd].halfClosedReader != NULL"
2011/04/04 09:55:29.262 kid1| enter_suid: PID 12854 taking root priveleges
2011/04/04 09:55:29.262 kid1| cache_manager.cc(102) registerProfile:
registering legacy config
2011/04/04 09:55:29.262 kid1| cache_manager.cc(87) registerProfile: registered
profile: config
2011/04/04 09:55:29.262 kid1| Memory pools are 'on'; limit: 5.000 MB
2011/04/04 09:55:29.262 kid1| cache_manager.cc(102) registerProfile:
registering legacy comm_epoll_incoming
2011/04/04 09:55:29.262 kid1| cache_manager.cc(87) registerProfile: registered
profile: comm_epoll_incoming
2011/04/04 09:55:29.262 kid1| leave_suid: PID 12854 called
2011/04/04 09:55:29.262 kid1| leave_suid: PID 12854 giving up root, becoming
'nobody'
2011/04/04 09:55:29.262 kid1| command-line -X overrides: ALL,1
2011/04/04 09:55:29.263 kid1| fd_open() FD 5 /var/local/squid/cache.log
2011/04/04 09:55:29.263 kid1| Starting Squid Cache version 3.HEAD-BZR for
x86_64-unknown-linux-gnu...
2011/04/04 09:55:29.263 kid1| Process ID 12854
2011/04/04 09:55:29.263 kid1| With 1024 file descriptors available
2011/04/04 09:55:29.263 kid1| Initializing IP Cache...
2011/04/04 09:55:29.263 kid1| cache_manager.cc(102) registerProfile:
registering legacy ipcache
2011/04/04 09:55:29.263 kid1| cache_manager.cc(87) registerProfile: registered
profile: ipcache
2011/04/04 09:55:29.263 kid1| cache_manager.cc(102) registerProfile:
registering legacy fqdncache
2011/04/04 09:55:29.263 kid1| cache_manager.cc(87) registerProfile: registered
profile: fqdncache
2011/04/04 09:55:29.263 kid1| Initializing FQDN Cache...
2011/04/04 09:55:29.263 kid1| etc_hosts: line is '127.0.0.1 localhost lo l
