[squid-users] Authenticacion with Active Directory fails

Sergio Belkin sebelk at gmail.com
Tue Jul 19 18:38:42 UTC 2016 

2016-07-15 12:11 GMT-03:00 Sergio Belkin <sebelk at gmail.com>:

>
> 2016-07-15 6:31 GMT-03:00 Amos Jeffries <squid3 at treenet.co.nz>:
>
>> On 15/07/2016 4:07 a.m., Sergio Belkin wrote:
>> > Hi,
>> >
>> > Using squid squid-3.5.19-1.el7.centos.x86_64,
>> >
>> > I obtain a kerberos ticket but I get the following when trying to use
>> the
>> > proxy:
>> >
>> > 2016/07/14 12:57:03.711 kid1| 29,4| UserRequest.cc(290) authenticate: No
>> > Proxy-Auth header and no working alternative. Requesting auth header.
>> > 2016/07/14 12:57:03.712 kid1| 29,9| UserRequest.cc(487)
>> addReplyAuthHeader:
>> > headertype:46 authuser:NULL
>> > 2016/07/14 12:57:03.712 kid1| 29,9| Config.cc(188) fixHeader: Sending
>> > type:46 header: 'Negotiate'
>> > 2016/07/14 12:57:04.159 kid1| 29,4| UserRequest.cc(290) authenticate: No
>> > Proxy-Auth header and no working alternative. Requesting auth header.
>> > 2016/07/14 12:57:04.159 kid1| 29,9| UserRequest.cc(487)
>> addReplyAuthHeader:
>> > headertype:46 authuser:NULL
>> > 2016/07/14 12:57:04.159 kid1| 29,9| Config.cc(188) fixHeader: Sending
>> > type:46 header: 'Negotiate'
>> >
>>
>> That looks like a debug log of Negotiate/Kerberos authentication
>> beginning on two connections.
>>
>> A good secure client does not send credentials until it needs to. Squdi
>> has received a request that it needs to authenticate, but does not yet
>> have credentiasl. So it responds with a 407 or 401 message requesting
>> the client send them using "Negotiate" auth protocol.
>>  No problem visible.
>>
>>
>> <snip>
>>
>> > Please could you help me? Am I doing something wrong?
>>
>> Perhapse if you described what your problem was ?
>>
>
>
> Amos, thanks, for your clarification, I get as follows:
>
> "Sorry, you are not currently allowed to request http://www.lxer.com/
> from this cache until you have authenticated yourself"
>
> ( trying to use from a Linux client:)
>
> (And in fact I've RTFM :-) )
>
> tail /var/log/squid/access.log
>
> 192.168.50.37 - - [15/Jul/2016:12:01:05 -0300] "GET http://www.lxer.com/
> HTTP/1.1" 407 4064 "-" "curl/7.43.0" TCP_DENIED:HIER_NONE
>
> I have a kerberos ticket:
>
> klist
> Ticket cache: KEYRING:persistent:16777216:16777216
> Default principal: john.doe at EXAMPLE.LOCAL
>
> Valid starting     Expires            Service principal
> 15/07/16 12:00:31  15/07/16 22:00:31  krbtgt/EXAMPLE.LOCAL at EXAMPLE.LOCAL
>         renew until 22/07/16 12:00:31
>
>
> End of output
>
> I don't know what I'm doing wrong.
>
> Thanks in advance!
>
>
>>
>> Amos
>>
>> _______________________________________________
>> squid-users mailing list
>> squid-users at lists.squid-cache.org
>> http://lists.squid-cache.org/listinfo/squid-users
>>
>
>
>
> --
> -
>

Please any ideas?

squid is on Centos 7.2
AD is Windows 2008 R2 Standard

Below more details from cache.log when trying to access from a Windows
machine:

 2016/07/15 19:53:47.334 kid1| 29,4| UserRequest.cc(290) authenticate: No
Proxy-Auth header and no working alternative. Requesting auth header.
2016/07/15 19:53:47.347 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader:
headertype:46 authuser:NULL
2016/07/15 19:53:47.347 kid1| 29,9| Config.cc(188) fixHeader: Sending
type:46 header: 'Negotiate'
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(328) authenticate:
header Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(332) authenticate: This
is a new checklist test on:local=192.168.50.22:3128 remote=
192.168.50.47:61011 FD 12 flags=1
2016/07/15 19:53:47.447 kid1| 29,4| UserRequest.cc(350) authenticate: No
connection authentication type
2016/07/15 19:53:47.447 kid1| 29,9| Config.cc(36) CreateAuthUser: header =
'Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw=='
2016/07/15 19:53:47.447 kid1| 29,5| User.cc(39) User: Initialised auth_user
'0x2cf1e00'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(95) UserRequest:
initialised request 0x30c4be0
2016/07/15 19:53:47.447 kid1| 29,9| Config.cc(267) decode: decode Negotiate
authentication
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(225) authenticate: auth
state negotiate none. Received blob: 'Negotiate
TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw=='
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(46) start: 0x30c4be0
2016/07/15 19:53:47.447 kid1| 29,8| UserRequest.cc(134) startHelperLookup:
credentials state is '2'
negotiate_kerberos_auth.cc(610): pid=5236 :2016/07/15 19:53:47|
negotiate_kerberos_auth: DEBUG: Got 'YR
TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==' from squid
(length: 59).
negotiate_kerberos_auth.cc(663): pid=5236 :2016/07/15 19:53:47|
negotiate_kerberos_auth: DEBUG: Decode
'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==' (decoded length:
40).
negotiate_kerberos_auth.cc(673): pid=5236 :2016/07/15 19:53:47|
negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2016/07/15 19:53:47.447 kid1| 29,8| UserRequest.cc(266) HandleReply:
helper: '0x30c5698/0x30c5698' sent us reply={result=BH, notes={message:
received type 1 NTLM token; }}
2016/07/15 19:53:47.447 kid1| 29,6| UserRequest.cc(175) releaseAuthServer:
releasing Negotiate auth server '0x30c5698'
2016/07/15 19:53:47.447 kid1| ERROR: Negotiate Authentication validating
user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(328) authenticate:
header Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(256) authenticate: auth
state negotiate failed. Negotiate
TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.447 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.448 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader:
headertype:46 authuser:NULL
2016/07/15 19:53:47.448 kid1| 29,9| Config.cc(188) fixHeader: Sending
type:46 header: 'Negotiate'
2016/07/15 19:53:47.532 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader:
headertype:46 authuser:NULL
2016/07/15 19:53:47.532 kid1| 29,9| Config.cc(188) fixHeader: Sending
type:46 header: 'Negotiate'
2016/07/15 19:53:47.655 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader:
headertype:46 authuser:NULL
2016/07/15 19:53:47.655 kid1| 29,9| Config.cc(188) fixHeader: Sending
type:46 header: 'Negotiate'
2016/07/15 19:53:47.688 kid1| 29,4| UserRequest.cc(290) authenticate: No
Proxy-Auth header and no working alternative. Requesting auth header.
2016/07/15 19:53:47.688 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader:
headertype:46 authuser:NULL
2016/07/15 19:53:47.688 kid1| 29,9| Config.cc(188) fixHeader: Sending
type:46 header: 'Negotiate'
2016/07/15 19:53:47.698 kid1| 29,6| UserRequest.cc(179) releaseAuthServer:
No Negotiate auth server to release.
2016/07/15 19:53:47.698 kid1| 29,6| UserRequest.cc(179) releaseAuthServer:
No Negotiate auth server to release.
2016/07/15 19:53:47.698 kid1| 29,5| UserRequest.cc(101) ~UserRequest:
freeing request 0x30c4be0
2016/07/15 19:53:47.698 kid1| 29,5| User.cc(21) ~User: doing nothing to
clear Negotiate scheme data for '0x2cf1e00'
2016/07/15 19:53:47.698 kid1| 29,5| User.cc(127) ~User: Freeing auth_user
'0x2cf1e00'.
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(328) authenticate:
header Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==.
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(332) authenticate: This
is a new checklist test on:local=192.168.50.22:3128 remote=
192.168.50.47:61012 FD 16 flags=1
2016/07/15 19:53:47.717 kid1| 29,4| UserRequest.cc(350) authenticate: No
connection authentication type
2016/07/15 19:53:47.717 kid1| 29,9| Config.cc(36) CreateAuthUser: header =
'Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw=='
2016/07/15 19:53:47.717 kid1| 29,5| User.cc(39) User: Initialised auth_user
'0x2cf1e00'.
2016/07/15 19:53:47.717 kid1| 29,5| UserRequest.cc(95) UserRequest:
initialised request 0x30c4be0
2016/07/15 19:53:47.717 kid1| 29,9| Config.cc(267) decode: decode Negotiate
authentication
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.717 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.717 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(225) authenticate: auth
state negotiate none. Received blob: 'Negotiate
TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw=='
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.717 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.717 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.717 kid1| 29,9| UserRequest.cc(46) start: 0x30c4be0
2016/07/15 19:53:47.717 kid1| 29,8| UserRequest.cc(134) startHelperLookup:
credentials state is '2'
negotiate_kerberos_auth.cc(610): pid=5236 :2016/07/15 19:53:47|
negotiate_kerberos_auth: DEBUG: Got 'YR
TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==' from squid
(length: 59).
negotiate_kerberos_auth.cc(663): pid=5236 :2016/07/15 19:53:47|
negotiate_kerberos_auth: DEBUG: Decode
'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==' (decoded length:
40).
negotiate_kerberos_auth.cc(673): pid=5236 :2016/07/15 19:53:47|
negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2016/07/15 19:53:47.717 kid1| 29,8| UserRequest.cc(266) HandleReply:
helper: '0x30c5698/0x30c5698' sent us reply={result=BH, notes={message:
received type 1 NTLM token; }}
2016/07/15 19:53:47.717 kid1| 29,6| UserRequest.cc(175) releaseAuthServer:
releasing Negotiate auth server '0x30c5698'
2016/07/15 19:53:47.717 kid1| ERROR: Negotiate Authentication validating
user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.718 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.718 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(328) authenticate:
header Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==.
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.718 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(256) authenticate: auth
state negotiate failed. Negotiate
TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(53) valid: Validating
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.718 kid1| 29,5| UserRequest.cc(73) valid: Validated.
Auth::UserRequest '0x30c4be0'.
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(63) authenticated: user
not fully authenticated.
2016/07/15 19:53:47.718 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader:
headertype:46 authuser:NULL
2016/07/15 19:53:47.718 kid1| 29,9| Config.cc(188) fixHeader: Sending
type:46 header: 'Negotiate'
2016/07/15 19:53:47.743 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader:
headertype:46 authuser:NULL
2016/07/15 19:53:47.743 kid1| 29,9| Config.cc(188) fixHeader: Sending
type:46 header: 'Negotiate'
2016/07/15 19:53:47.754 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader:
headertype:46 authuser:NULL
2016/07/15 19:53:47.754 kid1| 29,9| Config.cc(188) fixHeader: Sending
type:46 header: 'Negotiate'


Thanks in advance!
-- 
--
Sergio Belkin
LPIC-2 Certified - http://www.lpi.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20160719/4c5a8f55/attachment-0001.html>

More information about the squid-users mailing list