Hi Amos, thanks for quick response. On Fri, Jan 10, 2014 at 10:38:30AM +1300, Amos Jeffries wrote: > On 2014-01-10 01:17, Peter Benko wrote: > >Hi squid users, > > > >I'm trying to upgrade squid from 3.3.11 to 3.4.2 on Debian 6. Both > >squids are > >compiled from source with the same compilation flags and their > >config files are > >equal. > > > >I have problem with Negotiate/kerberos authentication against > >Active Directory > >in squid 3.4.2 (squid 3.3.11 works without problems). > > > >First 2 lines of access.log are produced by command: > >$ curl -q --proxy-negotiate -x proxy2.example.com:8080 -U : -L > >--max-redirs 1 http://www.six.sk/ > >curl: (47) Maximum (1) redirects followed > >...curl doesn't obtain the required html page (it works against > >squid 3.3.11). > > > >Last 3 lines of access.log are produced by command: > >$ curl -q --proxy-negotiate -x proxy2.example.com:8080 -U : -L > >--max-redirs 2 http://www.six.sk/ > >...curl obtains the required html page. > > > >What's wrong with my squid configuration? > > > >squid@proxy2:~ $ diff -s squid33/etc/squid.conf squid34/etc/squid.conf > >Files squid33/etc/squid.conf and squid34/etc/squid.conf are identical > > > > So the only difference there is a curl parameter about how many > "redirects" it will follow? > That sounds to me like they are counting 407 challenges as a redirect. The reason why I used the '--max-redirs 1' parameter is that it simulates my Firefox behaviour. Firefox doesn't accept more than one 407 response from squid. > Is this exactly the same version of curl being used to test each of > the proxies? Yes, the same version. > Does the results change if you reverse the order of the tests? From > what I have seen below it just might (caching group lookup results > from first test may let second attempt pass). Yes. I observe the following behaviour: step1: curl ...--max-redirs 2... ...curl obtains the required html page step2: wait max few seconds step3: curl ...--max-redirs 1... ...curl obtains the required html page If I wait more than cca 15 seconds in step 2, curl in step 3 will fail. > > > <snip> > > > >squid@proxy2:~ $ cat /var/log/squid/access.log > > TCP connection #1 from client port 42736: > > >1389267633.593 0 10.106.68.14 TCP_DENIED/407 3519 GET > >http://www.six.sk/ - HIER_NONE/- text/html > >1389267633.603 4 10.106.68.14 TCP_DENIED/407 6116 GET > >http://www.six.sk/ benko_peter HIER_NONE/- text/html > > ... which could be interpreted as request #1 redirected, request #2 > redirected, then stop. > > TCP connection #2 from client port 42737: > > >1389267662.100 0 10.106.68.14 TCP_DENIED/407 3519 GET > >http://www.six.sk/ - HIER_NONE/- text/html > >1389267662.110 4 10.106.68.14 TCP_DENIED/407 6116 GET > >http://www.six.sk/ benko_peter HIER_NONE/- text/html > >1389267662.150 34 10.106.68.14 TCP_MISS/200 4387 GET > >http://www.six.sk/ benko_peter HIER_DIRECT/194.160.23.5 text/html > > > > ... which could be interpreted as request #1 redirected, request #2 > redirected, then request #3 with result. > > As you can see Squid is emitting the same 407 results each time. Not > that Negotiate should be needing that many 407 to begin with, but > the outright failure seems to be coming from curl. > > > >squid@proxy2:~ $ cat /var/log/squid/cache.log > > >2014/01/09 12:39:12 kid1| Set Current Directory to /var/spool/squid > >2014/01/09 12:39:12 kid1| Starting Squid Cache version 3.4.2 for > >x86_64-unknown-linux-gnu... > >2014/01/09 12:39:12 kid1| Process ID 25457 > >2014/01/09 12:39:12 kid1| Process Roles: worker > > >2014/01/09 12:40:33.592 kid1| Checklist.cc(62) preCheck: 0x13ec528 > >checking slow rules > >2014/01/09 12:40:33.592 kid1| Ip.cc(560) match: aclIpMatchIp: > >'10.106.68.14:42736' found > >2014/01/09 12:40:33.592 kid1| Acl.cc(176) matches: checked: > >FromLocalNet = 1 > >2014/01/09 12:40:33.592 kid1| Acl.cc(176) matches: checked: > >!FromLocalNet = 0 > >2014/01/09 12:40:33.592 kid1| Acl.cc(176) matches: checked: > >http_access#1 = 0 > >2014/01/09 12:40:33.592 kid1| Checklist.cc(55) markFinished: 0x13ec528 > >answer AUTH_REQUIRED for aclMatchExternal exception > >2014/01/09 12:40:33.592 kid1| Acl.cc(176) matches: checked: group1 = -1 > >2014/01/09 12:40:33.592 kid1| Acl.cc(176) matches: checked: > >!group1 = -1 > >2014/01/09 12:40:33.592 kid1| Acl.cc(176) matches: checked: > >http_access#2 = -1 > >2014/01/09 12:40:33.592 kid1| Acl.cc(176) matches: checked: > >http_access = -1 > >2014/01/09 12:40:33.592 kid1| Checklist.cc(148) checkCallback: > >ACLChecklist::checkCallback: 0x13ec528 answer=AUTH_REQUIRED > > No credentials. So exit with a 407 challenge to get them. > > LOG for port 42736: > ## 1389267633.593 0 10.106.68.14 TCP_DENIED/407 3519 GET > ## http://www.six.sk/ - HIER_NONE/- text/html > > > >2014/01/09 12:40:33.598 kid1| Checklist.cc(62) preCheck: 0x13ec528 > >checking slow rules > >2014/01/09 12:40:33.598 kid1| Ip.cc(560) match: aclIpMatchIp: > >'10.106.68.14:42736' found > >2014/01/09 12:40:33.598 kid1| Acl.cc(176) matches: checked: > >FromLocalNet = 1 > >2014/01/09 12:40:33.598 kid1| Acl.cc(176) matches: checked: > >!FromLocalNet = 0 > >2014/01/09 12:40:33.598 kid1| Acl.cc(176) matches: checked: > >http_access#1 = 0 > >2014/01/09 12:40:33.598 kid1| AclProxyAuth.cc(143) checkForAsync: > >checking password via authenticator > >2014/01/09 12:40:33.598 kid1| Acl.cc(176) matches: checked: group1 > >= -1 async > >2014/01/09 12:40:33.598 kid1| Acl.cc(176) matches: checked: > >!group1 = -1 async > >2014/01/09 12:40:33.598 kid1| Acl.cc(176) matches: checked: > >http_access#2 = -1 async > >2014/01/09 12:40:33.598 kid1| Acl.cc(176) matches: checked: > >http_access = -1 async > >2014/01/09 12:40:33.602 kid1| Checklist.cc(119) goAsync: 0x13ec528 a > >slow ACL resumes by going async again! > >2014/01/09 12:40:33.602 kid1| Checklist.cc(55) markFinished: 0x13ec528 > >answer DUNNO for aclMatchExternal exception > > Hmm. Maybe its confused between loop and external_acl triggering > both auth helper and external helper lookups in the same test > sequence. What happens if you change your ACLs to these? > > acl auth proxy_auth REQUIRED > http_access deny !FromLocalNet > http_access deny !auth > http_access deny !group1 all If I change the squid.conf as you proposed, both 'curl ...--max-redirs 1' and 'Firefox' work. > If that makes it "work", would you mind testing a patch with the old > config? I will be glad to check the new patch. > > >2014/01/09 12:40:33.602 kid1| Acl.cc(176) matches: checked: group1 = -1 > >2014/01/09 12:40:33.602 kid1| InnerNode.cc(104) resumeMatchingAt: > >checked: !group1 = -1 > >2014/01/09 12:40:33.602 kid1| InnerNode.cc(104) resumeMatchingAt: > >checked: http_access#2 = -1 > >2014/01/09 12:40:33.602 kid1| InnerNode.cc(104) resumeMatchingAt: > >checked: http_access = -1 > >2014/01/09 12:40:33.602 kid1| Checklist.cc(148) checkCallback: > >ACLChecklist::checkCallback: 0x13ec528 answer=DUNNO > > LOG for port 42736: > ## 1389267633.603 4 10.106.68.14 TCP_DENIED/407 6116 GET > ## http://www.six.sk/ benko_peter HIER_NONE/- text/html > > Hmm, another strangeness. DUNNO result logging as 407, even with the > "all" hack in place. > > > PS. Thank you for a most excellent debug trace of the problem. > > Amos -- Peter Benko
