Hi Amos,
I have found something that looks like a border case bug in the
external acl caching of squid.
I tested this with 3.2.0.19 and 3.2.3.
I have the following in my configuration:
===========
external_acl_type abc_noauth_type ttl=3600 children-startup=2
children-max=5 %SRC %DST /var/www/bin/acl.php
acl abc_noauth external abc_noauth_type
acl auth_username_valid proxy_auth_regex @
acl auth_username_empty proxy_auth_regex ^$
http_access allow abc_noauth
http_access deny !auth_username_valid !auth_username_empty
http_access deny all
============
/var/www/bin/acl.php is a script that always returns OK.
The user visits a website, the external acl returns OK, and squid
caches the acl result for 3600 seconds (because of the ttl parameter).
It seems that when there is another request in exactly 3600 seconds,
the external ACL fails.
Please see these log excerpts:
First request:
2012/12/07 10:52:46.385 kid1| ACLChecklist::preCheck: 0x10697d30
checking 'http_access allow abc_noauth'
2012/12/07 10:52:46.385 kid1| ACLList::matches: checking abc_noauth
2012/12/07 10:52:46.385 kid1| ACL::checklistMatches: checking 'abc_noauth'
2012/12/07 10:52:46.385 kid1| aclMatchExternal:
abc_noauth_type("10.1.1.2 somewebsite.com") = lookup needed
2012/12/07 10:52:46.385 kid1| aclMatchExternal: "10.1.1.2
somewebsite.com": entry=@0x11070d38, age=3602
2012/12/07 10:52:46.385 kid1| aclMatchExternal: "10.1.1.2
somewebsite.com": queueing a call.
2012/12/07 10:52:46.385 kid1| aclMatchExternal: "10.1.1.2
somewebsite.com": return -1.
2012/12/07 10:52:46.385 kid1| ACL::ChecklistMatches: result for
'abc_noauth' is -1
2012/12/07 10:52:46.385 kid1| ACLList::matches: result is false
2012/12/07 10:52:46.385 kid1| ACLChecklist::asyncInProgress:
0x10697d30 async set to 1
2012/12/07 10:52:46.385 kid1| externalAclLookup: lookup in
'abc_noauth_type' for '10.1.1.2 somewebsite.com'
2012/12/07 10:52:46.385 kid1| externalAclLookup: looking up for
'10.1.1.2 somewebsite.com' in 'abc_noauth_type'.
2012/12/07 10:52:46.385 kid1| externalAclLookup: will wait for the
result of '10.1.1.2 somewebsite.com' in 'abc_noauth_type'
(ch=0x10697d30).
2012/12/07 10:52:46.385 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=1 lastACLResult() = 0 finished() = 0
2012/12/07 10:52:46.385 kid1| aclmatchAclList: 0x10697d30 returning
(AND list entry awaiting an async lookup)
2012/12/07 10:52:46.387 kid1| externalAclHandleReply: reply="OK user=
log=3 message=Matched%20policy%3A%203"
2012/12/07 10:52:46.387 kid1| external_acl_cache_add: Adding '10.1.1.2
somewebsite.com' = 1
2012/12/07 10:52:46.387 kid1| ExternalACLEntry::update: updating existing entry
2012/12/07 10:52:46.388 kid1| ACLChecklist::asyncInProgress:
0x10697d30 async set to 0
2012/12/07 10:52:46.388 kid1| ACLChecklist::preCheck: 0x10697d30
checking 'http_access allow abc_noauth'
2012/12/07 10:52:46.388 kid1| ACLList::matches: checking abc_noauth
2012/12/07 10:52:46.388 kid1| ACL::checklistMatches: checking 'abc_noauth'
2012/12/07 10:52:46.388 kid1| aclMatchExternal: abc_noauth_type = 1
2012/12/07 10:52:46.388 kid1| ACL::ChecklistMatches: result for
'abc_noauth' is 1
2012/12/07 10:52:46.388 kid1| ACLList::matches: result is true
2012/12/07 10:52:46.388 kid1| aclmatchAclList: 0x10697d30 returning
true (AND list satisfied)
2012/12/07 10:52:46.388 kid1| ACLChecklist::markFinished: 0x10697d30
checklist processing finished
2012/12/07 10:52:46.388 kid1| ACLChecklist::check: 0x10697d30 match
found, calling back with 1
2012/12/07 10:52:46.388 kid1| ACLChecklist::checkCallback: 0x10697d30 answer=1
2012/12/07 10:52:46.388 kid1| The request POST
http://somewebsite.com/ajax.php is 1, because it matched 'abc_noauth'
2012/12/07 10:52:46.388 kid1| client_side_request.cc(734)
clientAccessCheck2: No adapted_http_access configuration. default:
ALLOW
2012/12/07 10:52:46.388 kid1| The request POST
http://somewebsite.com/ajax.php is 1, because it matched 'abc_noauth'
------
Second request, one hour later:
2012/12/07 11:52:46.568 kid1| ACLChecklist::preCheck: 0xf512178
checking 'http_access allow abc_noauth'
2012/12/07 11:52:46.568 kid1| ACLList::matches: checking abc_noauth
2012/12/07 11:52:46.568 kid1| ACL::checklistMatches: checking 'abc_noauth'
2012/12/07 11:52:46.568 kid1| aclMatchExternal:
abc_noauth_type("10.1.1.2 somewebsite.com") = lookup needed
2012/12/07 11:52:46.568 kid1| aclMatchExternal: "10.1.1.2
somewebsite.com": entry=@0x11070d38, age=3600
2012/12/07 11:52:46.568 kid1| aclMatchExternal: "10.1.1.2
somewebsite.com": queueing a call.
2012/12/07 11:52:46.568 kid1| aclMatchExternal: "10.1.1.2
somewebsite.com": return -1.
2012/12/07 11:52:46.568 kid1| ACL::ChecklistMatches: result for
'abc_noauth' is -1
2012/12/07 11:52:46.568 kid1| ACLList::matches: result is false
2012/12/07 11:52:46.568 kid1| ACLChecklist::asyncInProgress: 0xf512178
async set to 1
2012/12/07 11:52:46.568 kid1| externalAclLookup: lookup in
'abc_noauth_type' for '10.1.1.2 somewebsite.com'
2012/12/07 11:52:46.568 kid1| externalAclLookup: looking up for
'10.1.1.2 somewebsite.com' in 'abc_noauth_type'.
2012/12/07 11:52:46.568 kid1| externalAclLookup: no need to wait for
the result of '10.1.1.2 somewebsite.com' in 'abc_noauth_type'
(ch=0xf512178).
2012/12/07 11:52:46.568 kid1| externalAclLookup: using cached entry 0x11070d38
2012/12/07 11:52:46.568 kid1| externalAclLookup: entry = {
date=1354845166, result=1 tag= log=3 }
2012/12/07 11:52:46.568 kid1| externalAclLookup: user=
2012/12/07 11:52:46.568 kid1| ACLChecklist::asyncInProgress: 0xf512178
async set to 0
2012/12/07 11:52:46.568 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2012/12/07 11:52:46.568 kid1| aclmatchAclList: 0xf512178 returning
(AND list entry awaiting an async lookup)
2012/12/07 11:52:46.568 kid1| ACLChecklist::preCheck: 0xf512178
checking 'http_access deny !auth_username_valid !auth_username_empty'
2012/12/07 11:52:46.568 kid1| ACLList::matches: checking !auth_username_valid
2012/12/07 11:52:46.568 kid1| ACL::checklistMatches: checking
'auth_username_valid'
2012/12/07 11:52:46.568 kid1| Acl.cc(61) AuthenticateAcl: returning 0
sending authentication challenge.
2012/12/07 11:52:46.568 kid1| ACL::ChecklistMatches: result for
'auth_username_valid' is 0
2012/12/07 11:52:46.568 kid1| ACLList::matches: result is true
2012/12/07 11:52:46.568 kid1| ACLChecklist::markFinished: 0xf512178
checklist processing finished
2012/12/07 11:52:46.568 kid1| aclmatchAclList: async=1 nodeMatched=1
async_in_progress=0 lastACLResult() = 1 finished() = 1
2012/12/07 11:52:46.568 kid1| aclmatchAclList: 0xf512178 returning
(AND list entry failed to match)
2012/12/07 11:52:46.568 kid1| ACLChecklist::check: 0xf512178 match
found, calling back with 3
2012/12/07 11:52:46.568 kid1| ACLChecklist::checkCallback: 0xf512178 answer=3
2012/12/07 11:52:46.568 kid1| The request POST
http://somewebsite.com/ajax.php is 3, because it matched
'auth_username_valid'
2012/12/07 11:52:46.569 kid1| errorpage.cc(1268) BuildContent: No
existing error page language negotiated for ERR_CACHE_ACCESS_DENIED.
Using default error file.
Please let me know if you need any further information.
Best regards,
Alan
