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