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

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.

Is this exactly the same version of curl being used to test each of the
proxies?

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).

<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 that makes it "work", would you mind testing a patch with the old
config?

> 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
Received on Thu Jan 09 2014 - 21:38:36 MST