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

[Amos Jeffries]

On 18/09/2012 4:36 p.m., Cameron Charles wrote:
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

<snip irrelevant lines>

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
No you configured:
   external_acl_type auth_bypass_ext_acl_type ... cache=0 ...

squid-3.2 now obeys the external ACL caching options exactly as 
configured. 3.1 had a few bugs where it would interpret the config cache 
size and TTLs a bit loosely.


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@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@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@base
[4493:169943724] INFO: has concurrency
2012-09-18 10:38:32,913
advance.policy.management.commands.ext_acl_payload_check@ext_acl_payload_check
[4493:169943724] INFO: KEY IS auth_bypass
2012-09-18 10:38:32,914 advance.utils.management.base@base
[4493:169943724] INFO: ext_acl_payload_check Response: '0 ERR'
2012-09-18 10:38:32,914 advance.utils.management.base@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@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@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@base
[4507:153346732] INFO: has concurrency
2012-09-18 10:38:32,917
advance.policy.management.commands.ext_acl_payload_check@ext_acl_payload_check
[4507:153346732] INFO: KEY IS user_auth
2012-09-18 10:38:32,917 advance.utils.management.base@base
[4507:153346732] INFO: ext_acl_payload_check Response: '0 OK'
2012-09-18 10:38:32,918 advance.utils.management.base@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

Thank you. Looks like you have uncovered a performance problem in ACL 
testing. Someone could make the checklist faster by caching the last ACL 
tested and walk the lines like this without repeating expensive tests. 
Could you report this to bugzilla please.

That is the only bug visible, it is hit due to expected behaviour when 
external ACL have cache=0 option set.

<snip>

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

You have configured cache=0 on both of these. Such that zero responses 
may be cached from previous tests.

The loop should disappear if you remove or set the cache= size on 
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.


Amos