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@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@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@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@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@base [4493:169943724] INFO: has concurrency 2012-09-18 10:38:32,898 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,899 advance.utils.management.base@base [4493:169943724] INFO: ext_acl_payload_check Response: '0 ERR' 2012-09-18 10:38:32,899 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.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@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 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@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@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@base [4493:169943724] INFO: has concurrency 2012-09-18 10:38:32,919 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,920 advance.utils.management.base@base [4493:169943724] INFO: ext_acl_payload_check Response: '0 ERR' 2012-09-18 10:38:32,920 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.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@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@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@base [4507:153346732] INFO: has concurrency 2012-09-18 10:38:32,922 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,922 advance.utils.management.base@base [4507:153346732] INFO: ext_acl_payload_check Response: '0 OK' 2012-09-18 10:38:32,922 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.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