[squid-users] Infinitely looping basic auth/external acl issue since updating to 3.2

Hi all,

we have recently set about updating our squid based setup to 3.2, from
3.1.19, everything seemed fine until we turned on the basic
authentication method as the main auth method for the setup and
therefore activating relevant acls, with the squid.conf setup for
basic auth we are having an issue of squid going into an infinite
loop, where it is evaluating 2 acls over and over again.

Some more info:
-one of the acls in question should be getting its result checked and
cached earlier in the conf, which the logs say is happening however
further down at the beginning of the loop the cache check fails and it
evaluates the acl again
-the exact same conf setup, with only minor changes made to comply
with the now defunct directives in 3.2 (concurrency), works 100% as
desired with 3.1.19
-the two acls that are looping are on the same line as the
acl/deirective that is supposed to kick of the basic auth prompt using
the specified settings - this acl/directive appears to never run and
the user is never prompted for auth

heres some fine grained log output of a request from initiation to the
loop beginning, the loop continues with no difference in output
indefinitely until the system crashes from load or squid is stopped

============================= LOG OUTPUT =============================
Beginning of a request as far as acls are concerned

2012/09/18 10:38:31.828 kid1| ACLChecklist::preCheck: 0xa24df20
checking 'http_access allow request_init_acl !all'
2012/09/18 10:38:31.828 kid1| ACLList::matches: checking request_init_acl
2012/09/18 10:38:31.828 kid1| ACL::checklistMatches: checking 'request_init_acl'
2012/09/18 10:38:31.828 kid1| external_acl.cc(774) aclMatchExternal:
acl="request_init_ext_acl_type"
2012/09/18 10:38:31.828 kid1| external_acl.cc(803) aclMatchExternal:
No helper entry available
2012/09/18 10:38:31.828 kid1| aclMatchExternal:
request_init_ext_acl_type("http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128") = lookup needed
2012/09/18 10:38:31.828 kid1| aclMatchExternal:
"http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128": entry=@0, age=0
2012/09/18 10:38:31.828 kid1| aclMatchExternal:
"http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128": queueing a call.
2012/09/18 10:38:31.828 kid1| aclMatchExternal:
"http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128": return -1.
2012/09/18 10:38:31.828 kid1| ACL::ChecklistMatches: result for
'request_init_acl' is -1
2012/09/18 10:38:31.828 kid1| ACLList::matches: result is false
2012/09/18 10:38:31.828 kid1| ACL::FindByName 'request_init_acl'
2012/09/18 10:38:31.828 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 1
2012/09/18 10:38:31.828 kid1| externalAclLookup: lookup in
'request_init_ext_acl_type' for
'http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128'
2012/09/18 10:38:31.828 kid1| externalAclLookup: looking up for
'http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128' in 'request_init_ext_acl_type'.
2012/09/18 10:38:31.828 kid1| externalAclLookup: will wait for the
result of 'http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128' in 'request_init_ext_acl_type'
(ch=0xa24df20).
2012/09/18 10:38:31.828 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=1 lastACLResult() = 0 finished() = 0
2012/09/18 10:38:31.828 kid1| aclmatchAclList: 0xa24df20 returning
(AND list entry awaiting an async lookup)
2012-09-18 10:38:32,895 advance.utils.management.base_at_base
[4426:162763372] INFO: ext_acl_request_init Response: '0 OK
tag=d9051ee5-2307-4a4e-85e9-923fb366a8aa
log={"user_auth":"full","url_rewrite":false,"auth_bypass":false,"policy_order":"wu"}'
2012-09-18 10:38:32,895 advance.utils.management.base_at_base
[4426:162763372] DEBUG: '0
http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128' ==> '0 OK
tag=d9051ee5-2307-4a4e-85e9-923fb366a8aa
log=%7B%22user_auth%22%3A%22full%22%2C%22url_rewrite%22%3Afalse%2C%22auth_bypass%22%3Afalse%2C%22policy_order%22%3A%22wu%22%7D'
2012/09/18 10:38:32.896 kid1| externalAclHandleReply: reply="OK
tag=d9051ee5-2307-4a4e-85e9-923fb366a8aa
log=%7B%22user_auth%22%3A%22full%22%2C%22url_rewrite%22%3Afalse%2C%22auth_bypass%22%3Afalse%2C%22policy_order%22%3A%22wu%22%7D"
2012/09/18 10:38:32.896 kid1| external_acl_cache_add: Adding
'http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128' = 1
2012/09/18 10:38:32.896 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 0
2012/09/18 10:38:32.896 kid1| ACLChecklist::preCheck: 0xa24df20
checking 'http_access allow request_init_acl !all'
2012/09/18 10:38:32.896 kid1| ACLList::matches: checking request_init_acl
2012/09/18 10:38:32.896 kid1| ACL::checklistMatches: checking 'request_init_acl'
2012/09/18 10:38:32.896 kid1| external_acl.cc(774) aclMatchExternal:
acl="request_init_ext_acl_type"
2012/09/18 10:38:32.896 kid1| aclMatchExternal: request_init_ext_acl_type = 1
2012/09/18 10:38:32.896 kid1| ACL::ChecklistMatches: result for
'request_init_acl' is 1
2012/09/18 10:38:32.896 kid1| ACLList::matches: result is true
2012/09/18 10:38:32.896 kid1| ACLList::matches: checking !all
2012/09/18 10:38:32.896 kid1| ACL::checklistMatches: checking 'all'
2012/09/18 10:38:32.896 kid1| aclIpAddrNetworkCompare: compare:
10.0.1.79:53091/[::] ([::]:53091) vs [::]-[::]/[::]
2012/09/18 10:38:32.896 kid1| aclIpMatchIp: '10.0.1.79:53091' found
2012/09/18 10:38:32.896 kid1| ACL::ChecklistMatches: result for 'all' is 1
2012/09/18 10:38:32.896 kid1| ACLList::matches: result is false
2012/09/18 10:38:32.896 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2012/09/18 10:38:32.896 kid1| aclmatchAclList: 0xa24df20 returning
(AND list entry awaiting an async lookup)

The caching pre-check for this acls result

2012/09/18 10:38:32.896 kid1| ACLChecklist::preCheck: 0xa24df20
checking 'http_access allow auth_bypass_acl'
2012/09/18 10:38:32.896 kid1| ACLList::matches: checking auth_bypass_acl
2012/09/18 10:38:32.896 kid1| ACL::checklistMatches: checking 'auth_bypass_acl'
2012/09/18 10:38:32.896 kid1| external_acl.cc(774) aclMatchExternal:
acl="auth_bypass_ext_acl_type"
2012/09/18 10:38:32.896 kid1| external_acl.cc(789) aclMatchExternal:
entry 0xa24dea8 not valid or not ours. Discarded.
2012/09/18 10:38:32.896 kid1| external_acl.cc(791) aclMatchExternal:
entry def=0x9d6aeb0, our def=0x9d6e420
2012/09/18 10:38:32.896 kid1| external_acl.cc(793) aclMatchExternal:
entry key='http://www.homerosimpson.net/portal/modules/My_eGallery/gallery/Wallpapers/ACD%2520Wallpaper.bmp
10.0.1.79 GET Mozilla/5.0%20(Macintosh;%20Intel%20Mac%20OS%20X%2010.7;%20rv:14.0)%20Gecko/20100101%20Firefox/14.0.1
www.homerosimpson.net 10.0.1.26 3128', our
key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.896 kid1| external_acl.cc(803) aclMatchExternal:
No helper entry available
2012/09/18 10:38:32.896 kid1| aclMatchExternal:
auth_bypass_ext_acl_type("d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D")
= lookup needed
2012/09/18 10:38:32.896 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
entry=@0, age=0
2012/09/18 10:38:32.896 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
queueing a call.
2012/09/18 10:38:32.896 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
return -1.
2012/09/18 10:38:32.896 kid1| ACL::ChecklistMatches: result for
'auth_bypass_acl' is -1
2012/09/18 10:38:32.896 kid1| ACLList::matches: result is false
2012/09/18 10:38:32.896 kid1| ACL::FindByName 'auth_bypass_acl'
2012/09/18 10:38:32.896 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 1
2012/09/18 10:38:32.896 kid1| externalAclLookup: lookup in
'auth_bypass_ext_acl_type' for 'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.896 kid1| externalAclLookup: looking up for
'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'auth_bypass_ext_acl_type'.
2012/09/18 10:38:32.896 kid1| externalAclLookup: will wait for the
result of 'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'auth_bypass_ext_acl_type' (ch=0xa24df20).
2012/09/18 10:38:32.896 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=1 lastACLResult() = 0 finished() = 0
2012/09/18 10:38:32.896 kid1| aclmatchAclList: 0xa24df20 returning
(AND list entry awaiting an async lookup)
2012-09-18 10:38:32,897 advance.utils.management.base_at_base
[4493:3086278736] DEBUG: received input '0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012-09-18 10:38:32,898 advance.utils.management.base_at_base
[4493:169943724] INFO: ext_acl_payload_check LINE: ' 0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
{"user_auth":"full","url_rewrite":false,"auth_bypass":false,"policy_order":"wu"}'
2012-09-18 10:38:32,898 advance.utils.management.base_at_base
[4493:169943724] INFO: has concurrency
2012-09-18 10:38:32,898
advance.policy.management.commands.ext_acl_payload_check_at_ext_acl_payload_check
[4493:169943724] INFO: KEY IS auth_bypass
2012-09-18 10:38:32,899 advance.utils.management.base_at_base
[4493:169943724] INFO: ext_acl_payload_check Response: '0 ERR'
2012-09-18 10:38:32,899 advance.utils.management.base_at_base
[4493:169943724] DEBUG: '0 d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
==> '0 ERR'
2012/09/18 10:38:32.899 kid1| externalAclHandleReply: reply="ERR"
2012/09/18 10:38:32.899 kid1| external_acl.cc(1184) external_acl_cache_add:
2012/09/18 10:38:32.899 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 0
2012/09/18 10:38:32.899 kid1| ACLChecklist::preCheck: 0xa24df20
checking 'http_access allow auth_bypass_acl'
2012/09/18 10:38:32.899 kid1| ACLList::matches: checking auth_bypass_acl
2012/09/18 10:38:32.899 kid1| ACL::checklistMatches: checking 'auth_bypass_acl'
2012/09/18 10:38:32.899 kid1| external_acl.cc(774) aclMatchExternal:
acl="auth_bypass_ext_acl_type"
2012/09/18 10:38:32.899 kid1| aclMatchExternal: auth_bypass_ext_acl_type = 0
2012/09/18 10:38:32.899 kid1| ACL::ChecklistMatches: result for
'auth_bypass_acl' is 0
2012/09/18 10:38:32.899 kid1| ACLList::matches: result is false
2012/09/18 10:38:32.899 kid1| aclmatchAclList: async=0 nodeMatched=0
async_in_progress=0 lastACLResult() = 0 finished() = 0
2012/09/18 10:38:32.899 kid1| aclmatchAclList: 0xa24df20 returning
(AND list entry awaiting an async lookup)

The line that casuses the loop

2012/09/18 10:38:32.912 kid1| ACLChecklist::preCheck: 0xa24df20
checking 'http_access allow !auth_bypass_acl inband_auth_available_acl
perform_inband_auth_acl !all'

checking the acl from before, the result should be cached

2012/09/18 10:38:32.912 kid1| ACLList::matches: checking !auth_bypass_acl
2012/09/18 10:38:32.912 kid1| ACL::checklistMatches: checking 'auth_bypass_acl'
2012/09/18 10:38:32.912 kid1| external_acl.cc(774) aclMatchExternal:
acl="auth_bypass_ext_acl_type"
2012/09/18 10:38:32.912 kid1| external_acl.cc(789) aclMatchExternal:
entry 0xa254b88 not valid or not ours. Discarded.
2012/09/18 10:38:32.912 kid1| external_acl.cc(791) aclMatchExternal:
entry def=0x9d6f728, our def=0x9d6e420
2012/09/18 10:38:32.912 kid1| external_acl.cc(793) aclMatchExternal:
entry key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D',
our key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.912 kid1| external_acl.cc(803) aclMatchExternal:
No helper entry available
2012/09/18 10:38:32.912 kid1| aclMatchExternal:
auth_bypass_ext_acl_type("d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D")
= lookup needed
2012/09/18 10:38:32.912 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
entry=@0, age=0
2012/09/18 10:38:32.912 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
queueing a call.
2012/09/18 10:38:32.912 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
return -1.
2012/09/18 10:38:32.912 kid1| ACL::ChecklistMatches: result for
'auth_bypass_acl' is -1
2012/09/18 10:38:32.912 kid1| ACLList::matches: result is false
2012/09/18 10:38:32.912 kid1| ACL::FindByName 'auth_bypass_acl'
2012/09/18 10:38:32.912 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 1
2012/09/18 10:38:32.912 kid1| externalAclLookup: lookup in
'auth_bypass_ext_acl_type' for 'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.912 kid1| externalAclLookup: looking up for
'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'auth_bypass_ext_acl_type'.
2012/09/18 10:38:32.912 kid1| externalAclLookup: will wait for the
result of 'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'auth_bypass_ext_acl_type' (ch=0xa24df20).
2012/09/18 10:38:32.912 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=1 lastACLResult() = 0 finished() = 0
2012/09/18 10:38:32.912 kid1| aclmatchAclList: 0xa24df20 returning
(AND list entry awaiting an async lookup)
2012-09-18 10:38:32,912 advance.utils.management.base_at_base
[4493:3086278736] DEBUG: received input '0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012-09-18 10:38:32,913 advance.utils.management.base_at_base
[4493:169943724] INFO: ext_acl_payload_check LINE: ' 0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
{"user_auth":"full","url_rewrite":false,"auth_bypass":false,"policy_order":"wu"}'
2012-09-18 10:38:32,913 advance.utils.management.base_at_base
[4493:169943724] INFO: has concurrency
2012-09-18 10:38:32,913
advance.policy.management.commands.ext_acl_payload_check_at_ext_acl_payload_check
[4493:169943724] INFO: KEY IS auth_bypass
2012-09-18 10:38:32,914 advance.utils.management.base_at_base
[4493:169943724] INFO: ext_acl_payload_check Response: '0 ERR'
2012-09-18 10:38:32,914 advance.utils.management.base_at_base
[4493:169943724] DEBUG: '0 d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
==> '0 ERR'
2012/09/18 10:38:32.914 kid1| externalAclHandleReply: reply="ERR"
2012/09/18 10:38:32.914 kid1| external_acl.cc(1184) external_acl_cache_add:
2012/09/18 10:38:32.914 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 0
2012/09/18 10:38:32.914 kid1| ACLChecklist::preCheck: 0xa24df20
checking 'http_access allow !auth_bypass_acl inband_auth_available_acl
perform_inband_auth_acl !all'
2012/09/18 10:38:32.914 kid1| ACLList::matches: checking !auth_bypass_acl
2012/09/18 10:38:32.914 kid1| ACL::checklistMatches: checking 'auth_bypass_acl'
2012/09/18 10:38:32.914 kid1| external_acl.cc(774) aclMatchExternal:
acl="auth_bypass_ext_acl_type"
2012/09/18 10:38:32.914 kid1| aclMatchExternal: auth_bypass_ext_acl_type = 0
2012/09/18 10:38:32.914 kid1| ACL::ChecklistMatches: result for
'auth_bypass_acl' is 0
2012/09/18 10:38:32.914 kid1| ACLList::matches: result is true

The second acl in the line

2012/09/18 10:38:32.914 kid1| ACLList::matches: checking
inband_auth_available_acl
2012/09/18 10:38:32.914 kid1| ACL::checklistMatches: checking
'inband_auth_available_acl'
2012/09/18 10:38:32.914 kid1| external_acl.cc(774) aclMatchExternal:
acl="inband_auth_available_ext_acl_type"
2012/09/18 10:38:32.914 kid1| external_acl.cc(789) aclMatchExternal:
entry 0xa255a58 not valid or not ours. Discarded.
2012/09/18 10:38:32.914 kid1| external_acl.cc(791) aclMatchExternal:
entry def=0x9d6e420, our def=0x9d6f0f8
2012/09/18 10:38:32.914 kid1| external_acl.cc(793) aclMatchExternal:
entry key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D',
our key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.914 kid1| external_acl.cc(803) aclMatchExternal:
No helper entry available
2012/09/18 10:38:32.914 kid1| aclMatchExternal:
inband_auth_available_ext_acl_type("d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D")
= lookup needed
2012/09/18 10:38:32.914 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
entry=@0, age=0
2012/09/18 10:38:32.914 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
queueing a call.
2012/09/18 10:38:32.914 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
return -1.
2012/09/18 10:38:32.914 kid1| ACL::ChecklistMatches: result for
'inband_auth_available_acl' is -1
2012/09/18 10:38:32.914 kid1| ACLList::matches: result is false
2012/09/18 10:38:32.914 kid1| ACL::FindByName 'inband_auth_available_acl'
2012/09/18 10:38:32.914 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 1
2012/09/18 10:38:32.914 kid1| externalAclLookup: lookup in
'inband_auth_available_ext_acl_type' for
'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.915 kid1| externalAclLookup: looking up for
'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'inband_auth_available_ext_acl_type'.
2012/09/18 10:38:32.915 kid1| externalAclLookup: will wait for the
result of 'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'inband_auth_available_ext_acl_type' (ch=0xa24df20).
2012/09/18 10:38:32.915 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=1 lastACLResult() = 0 finished() = 0
2012/09/18 10:38:32.915 kid1| aclmatchAclList: 0xa24df20 returning
(AND list entry awaiting an async lookup)
2012-09-18 10:38:32,915 advance.utils.management.base_at_base
[4507:3085946912] DEBUG: received input '0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012-09-18 10:38:32,916 advance.utils.management.base_at_base
[4507:153346732] INFO: ext_acl_payload_check LINE: ' 0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
{"user_auth":"full","url_rewrite":false,"auth_bypass":false,"policy_order":"wu"}'
2012-09-18 10:38:32,916 advance.utils.management.base_at_base
[4507:153346732] INFO: has concurrency
2012-09-18 10:38:32,917
advance.policy.management.commands.ext_acl_payload_check_at_ext_acl_payload_check
[4507:153346732] INFO: KEY IS user_auth
2012-09-18 10:38:32,917 advance.utils.management.base_at_base
[4507:153346732] INFO: ext_acl_payload_check Response: '0 OK'
2012-09-18 10:38:32,918 advance.utils.management.base_at_base
[4507:153346732] DEBUG: '0 d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
==> '0 OK'
2012/09/18 10:38:32.918 kid1| externalAclHandleReply: reply="OK"
2012/09/18 10:38:32.918 kid1| external_acl.cc(1184) external_acl_cache_add:
2012/09/18 10:38:32.918 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 0

and now the problem begins, having just finished processing the last
acl it should move onto the third acl in the line and onward down the
conf but as you see it appears to start the line over once again
evaluating the first 2 acls infinitely

2012/09/18 10:38:32.918 kid1| ACLChecklist::preCheck: 0xa24df20
checking 'http_access allow !auth_bypass_acl inband_auth_available_acl
perform_inband_auth_acl !all'
2012/09/18 10:38:32.918 kid1| ACLList::matches: checking !auth_bypass_acl
2012/09/18 10:38:32.918 kid1| ACL::checklistMatches: checking 'auth_bypass_acl'
2012/09/18 10:38:32.918 kid1| external_acl.cc(774) aclMatchExternal:
acl="auth_bypass_ext_acl_type"
2012/09/18 10:38:32.918 kid1| external_acl.cc(789) aclMatchExternal:
entry 0xa255928 not valid or not ours. Discarded.
2012/09/18 10:38:32.918 kid1| external_acl.cc(791) aclMatchExternal:
entry def=0x9d6f0f8, our def=0x9d6e420
2012/09/18 10:38:32.918 kid1| external_acl.cc(793) aclMatchExternal:
entry key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D',
our key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.918 kid1| external_acl.cc(803) aclMatchExternal:
No helper entry available
2012/09/18 10:38:32.918 kid1| aclMatchExternal:
auth_bypass_ext_acl_type("d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D")
= lookup needed
2012/09/18 10:38:32.918 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
entry=@0, age=0
2012/09/18 10:38:32.918 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
queueing a call.
2012/09/18 10:38:32.918 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
return -1.
2012/09/18 10:38:32.918 kid1| ACL::ChecklistMatches: result for
'auth_bypass_acl' is -1
2012/09/18 10:38:32.918 kid1| ACLList::matches: result is false
2012/09/18 10:38:32.918 kid1| ACL::FindByName 'auth_bypass_acl'
2012/09/18 10:38:32.918 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 1
2012/09/18 10:38:32.918 kid1| externalAclLookup: lookup in
'auth_bypass_ext_acl_type' for 'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.918 kid1| externalAclLookup: looking up for
'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'auth_bypass_ext_acl_type'.
2012/09/18 10:38:32.918 kid1| externalAclLookup: will wait for the
result of 'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'auth_bypass_ext_acl_type' (ch=0xa24df20).
2012/09/18 10:38:32.918 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=1 lastACLResult() = 0 finished() = 0
2012/09/18 10:38:32.918 kid1| aclmatchAclList: 0xa24df20 returning
(AND list entry awaiting an async lookup)
2012-09-18 10:38:32,919 advance.utils.management.base_at_base
[4493:3086278736] DEBUG: received input '0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012-09-18 10:38:32,919 advance.utils.management.base_at_base
[4493:169943724] INFO: ext_acl_payload_check LINE: ' 0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
{"user_auth":"full","url_rewrite":false,"auth_bypass":false,"policy_order":"wu"}'
2012-09-18 10:38:32,919 advance.utils.management.base_at_base
[4493:169943724] INFO: has concurrency
2012-09-18 10:38:32,919
advance.policy.management.commands.ext_acl_payload_check_at_ext_acl_payload_check
[4493:169943724] INFO: KEY IS auth_bypass
2012-09-18 10:38:32,920 advance.utils.management.base_at_base
[4493:169943724] INFO: ext_acl_payload_check Response: '0 ERR'
2012-09-18 10:38:32,920 advance.utils.management.base_at_base
[4493:169943724] DEBUG: '0 d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
==> '0 ERR'
2012/09/18 10:38:32.920 kid1| externalAclHandleReply: reply="ERR"
2012/09/18 10:38:32.920 kid1| external_acl.cc(1184) external_acl_cache_add:
2012/09/18 10:38:32.920 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 0
2012/09/18 10:38:32.920 kid1| ACLChecklist::preCheck: 0xa24df20
checking 'http_access allow !auth_bypass_acl inband_auth_available_acl
perform_inband_auth_acl !all'
2012/09/18 10:38:32.920 kid1| ACLList::matches: checking !auth_bypass_acl
2012/09/18 10:38:32.920 kid1| ACL::checklistMatches: checking 'auth_bypass_acl'
2012/09/18 10:38:32.920 kid1| external_acl.cc(774) aclMatchExternal:
acl="auth_bypass_ext_acl_type"
2012/09/18 10:38:32.920 kid1| aclMatchExternal: auth_bypass_ext_acl_type = 0
2012/09/18 10:38:32.920 kid1| ACL::ChecklistMatches: result for
'auth_bypass_acl' is 0
2012/09/18 10:38:32.920 kid1| ACLList::matches: result is true
2012/09/18 10:38:32.920 kid1| ACLList::matches: checking
inband_auth_available_acl
2012/09/18 10:38:32.920 kid1| ACL::checklistMatches: checking
'inband_auth_available_acl'
2012/09/18 10:38:32.920 kid1| external_acl.cc(774) aclMatchExternal:
acl="inband_auth_available_ext_acl_type"
2012/09/18 10:38:32.920 kid1| external_acl.cc(789) aclMatchExternal:
entry 0xa255bf8 not valid or not ours. Discarded.
2012/09/18 10:38:32.920 kid1| external_acl.cc(791) aclMatchExternal:
entry def=0x9d6e420, our def=0x9d6f0f8
2012/09/18 10:38:32.920 kid1| external_acl.cc(793) aclMatchExternal:
entry key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D',
our key='d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.920 kid1| external_acl.cc(803) aclMatchExternal:
No helper entry available
2012/09/18 10:38:32.920 kid1| aclMatchExternal:
inband_auth_available_ext_acl_type("d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D")
= lookup needed
2012/09/18 10:38:32.920 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
entry=@0, age=0
2012/09/18 10:38:32.920 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
queueing a call.
2012/09/18 10:38:32.920 kid1| aclMatchExternal:
"d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D":
return -1.
2012/09/18 10:38:32.920 kid1| ACL::ChecklistMatches: result for
'inband_auth_available_acl' is -1
2012/09/18 10:38:32.920 kid1| ACLList::matches: result is false
2012/09/18 10:38:32.920 kid1| ACL::FindByName 'inband_auth_available_acl'
2012/09/18 10:38:32.920 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 1
2012/09/18 10:38:32.920 kid1| externalAclLookup: lookup in
'inband_auth_available_ext_acl_type' for
'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012/09/18 10:38:32.920 kid1| externalAclLookup: looking up for
'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'inband_auth_available_ext_acl_type'.
2012/09/18 10:38:32.920 kid1| externalAclLookup: will wait for the
result of 'd9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
in 'inband_auth_available_ext_acl_type' (ch=0xa24df20).
2012/09/18 10:38:32.920 kid1| aclmatchAclList: async=1 nodeMatched=0
async_in_progress=1 lastACLResult() = 0 finished() = 0
2012/09/18 10:38:32.920 kid1| aclmatchAclList: 0xa24df20 returning
(AND list entry awaiting an async lookup)
2012-09-18 10:38:32,921 advance.utils.management.base_at_base
[4507:3085946912] DEBUG: received input '0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
2012-09-18 10:38:32,921 advance.utils.management.base_at_base
[4507:153346732] INFO: ext_acl_payload_check LINE: ' 0
d9051ee5-2307-4a4e-85e9-923fb366a8aa
{"user_auth":"full","url_rewrite":false,"auth_bypass":false,"policy_order":"wu"}'
2012-09-18 10:38:32,921 advance.utils.management.base_at_base
[4507:153346732] INFO: has concurrency
2012-09-18 10:38:32,922
advance.policy.management.commands.ext_acl_payload_check_at_ext_acl_payload_check
[4507:153346732] INFO: KEY IS user_auth
2012-09-18 10:38:32,922 advance.utils.management.base_at_base
[4507:153346732] INFO: ext_acl_payload_check Response: '0 OK'
2012-09-18 10:38:32,922 advance.utils.management.base_at_base
[4507:153346732] DEBUG: '0 d9051ee5-2307-4a4e-85e9-923fb366a8aa
%7B%22user_auth%22:%22full%22,%22url_rewrite%22:false,%22auth_bypass%22:false,%22policy_order%22:%22wu%22%7D'
==> '0 OK'
2012/09/18 10:38:32.922 kid1| externalAclHandleReply: reply="OK"
2012/09/18 10:38:32.922 kid1| external_acl.cc(1184) external_acl_cache_add:
2012/09/18 10:38:32.922 kid1| ACLChecklist::asyncInProgress: 0xa24df20
async set to 0

Loop repeats indefinitely below
============================= END LOG OUTPUT =============================

and finally heres the relevant squid.conf lines

============================= Squid Conf =============================
The following are the lines as they occur in the conf

#Initiation ACL
http_access allow request_init_acl !all

# auth bypass cahcing pre check
http_access allow auth_bypass_acl

#Line that kicks off the loop
http_access allow !auth_bypass_acl inband_auth_available_acl
perform_inband_auth_acl !all

The following are the lines that pertain to each of the above metioned acls
# request_init_acl definition
external_acl_type request_init_ext_acl_type ttl=10 negative_ttl=10
grace=0 children-max=3 concurrency=5 %URI %SRC %METHOD %>{User-Agent}
%DST %MYADDR %MYPORT
/usr/share/getbusi/livestream/bin/ext_acl_request_init -c 5
acl request_init_acl external request_init_ext_acl_type

#auth_bypass_acl definition
external_acl_type auth_bypass_ext_acl_type ttl=10 negative_ttl=10
cache=0 children-startup=1 children-max=2 children-idle=2
concurrency=20 %TAG %EXT_LOG
/usr/share/getbusi/livestream/bin/ext_acl_payload_check -c 20
--key=auth_bypass
acl auth_bypass_acl external auth_bypass_ext_acl_type

#inband_auth_available_acl defnition
external_acl_type inband_auth_available_ext_acl_type ttl=10
negative_ttl=10 cache=0 children-max=2 concurrency=20 %TAG %EXT_LOG
/usr/share/getbusi/livestream/bin/ext_acl_payload_check -c 20
--key=user_auth --value=any --value=full --value=inband
acl inband_auth_available_acl external inband_auth_available_ext_acl_type

#the perform_inband_auth_acl definiton that seemingly never gets run
and its relevant basic auth settings
acl perform_inband_auth_acl proxy_auth REQUIRED
auth_param basic program
/usr/share/getbusi/livestream/bin/livestream_auth_check -c 3
auth_param basic credentialsttl 5 minutes
auth_param basic realm "Getbusi LiveStream Web Access"
auth_param basic casesensitive on
auth_param basic children 3 startup=1 idle=3 concurrency=3

============================= END Squid conf =============================

any info on why this is happening would be great and if anymore info
is required to help diagnose the issue just ask.

--
Cameron Charles
1 College Road, Sandy Bay, TAS 7005
Phone: (03) 6226 6241
Fax: (03) 6226  6140
www.getbusi.com