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_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
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
Received on Tue Sep 18 2012 - 08:23:03 MDT
This archive was generated by hypermail 2.2.0 : Tue Sep 18 2012 - 12:00:03 MDT