Re: [squid-users] Negotiate/kerberos problem with squid 3.4.2

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_at_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_at_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_at_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