I'm trying to integrate squid 3.5.19 with AD/Kerberos (Windows 2008 R2), but I get always TCP_DENIED:HIER_NONE
These are the errors in /var/log/squid/cache.log
2016/07/28 10:26:01.583 kid1| 29,4| UserRequest.cc(290) authenticate: No Proxy-Auth header and no working alternative. Requesting auth header.
2016/07/28 10:26:01.584 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader: headertype:46 authuser:NULL
2016/07/28 10:26:01.584 kid1| 29,9| Config.cc(188) fixHeader: Sending type:46 header: 'Negotiate'
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(328) authenticate: header Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==.
2016/07/28 10:26:01.625 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:56015 FD 16 flags=1
2016/07/28 10:26:01.625 kid1| 29,4| UserRequest.cc(350) authenticate: No connection authentication type
2016/07/28 10:26:01.625 kid1| 29,9| Config.cc(36) CreateAuthUser: header = 'Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw=='
2016/07/28 10:26:01.625 kid1| 29,5| User.cc(39) User: Initialised auth_user '0x2857400'.
2016/07/28 10:26:01.625 kid1| 29,5| UserRequest.cc(95) UserRequest: initialised request 0x28576b0
2016/07/28 10:26:01.625 kid1| 29,9| Config.cc(267) decode: decode Negotiate authentication
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(53) valid: Validating Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.625 kid1| 29,5| UserRequest.cc(73) valid: Validated. Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(53) valid: Validating Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.625 kid1| 29,5| UserRequest.cc(73) valid: Validated. Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(63) authenticated: user not fully authenticated.
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(225) authenticate: auth state negotiate none. Received blob: 'Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw=='
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(53) valid: Validating Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.625 kid1| 29,5| UserRequest.cc(73) valid: Validated. Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(63) authenticated: user not fully authenticated.
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(53) valid: Validating Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.625 kid1| 29,5| UserRequest.cc(73) valid: Validated. Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.625 kid1| 29,9| UserRequest.cc(46) start: 0x28576b0
2016/07/28 10:26:01.625 kid1| 29,8| UserRequest.cc(134) startHelperLookup: credentials state is '2'
negotiate_kerberos_auth.cc(610): pid=11509 :2016/07/28 10:26:01| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(663): pid=11509 :2016/07/28 10:26:01| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(673): pid=11509 :2016/07/28 10:26:01| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2016/07/28 10:26:01.626 kid1| 29,8| UserRequest.cc(266) HandleReply: helper: '0x2860438/0x2860438' sent us reply={result=BH, notes={message: received type 1 NTLM token; }}
2016/07/28 10:26:01.626 kid1| 29,6| UserRequest.cc(175) releaseAuthServer: releasing Negotiate auth server '0x2860438'
2016/07/28 10:26:01.626 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(53) valid: Validating Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.626 kid1| 29,5| UserRequest.cc(73) valid: Validated. Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(53) valid: Validating Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.626 kid1| 29,5| UserRequest.cc(73) valid: Validated. Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(63) authenticated: user not fully authenticated.
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(328) authenticate: header Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==.
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(53) valid: Validating Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.626 kid1| 29,5| UserRequest.cc(73) valid: Validated. Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(63) authenticated: user not fully authenticated.
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(256) authenticate: auth state negotiate failed. Negotiate TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAKAFopAAAADw==
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(53) valid: Validating Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.626 kid1| 29,5| UserRequest.cc(73) valid: Validated. Auth::UserRequest '0x28576b0'.
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(63) authenticated: user not fully authenticated.
2016/07/28 10:26:01.626 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader: headertype:46 authuser:NULL
2016/07/28 10:26:01.626 kid1| 29,9| Config.cc(188) fixHeader: Sending type:46 header: 'Negotiate'
2016/07/28 10:26:01.732 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader: headertype:46 authuser:NULL
2016/07/28 10:26:01.732 kid1| 29,9| Config.cc(188) fixHeader: Sending type:46 header: 'Negotiate'
2016/07/28 10:26:01.913 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader: headertype:46 authuser:NULL
2016/07/28 10:26:01.913 kid1| 29,9| Config.cc(188) fixHeader: Sending type:46 header: 'Negotiate'
2016/07/28 10:26:01.956 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader: headertype:46 authuser:NULL
2016/07/28 10:26:01.956 kid1| 29,9| Config.cc(188) fixHeader: Sending type:46 header: 'Negotiate'
2016/07/28 10:26:01.980 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader: headertype:46 authuser:NULL
2016/07/28 10:26:01.980 kid1| 29,9| Config.cc(188) fixHeader: Sending type:46 header: 'Negotiate'
2016/07/28 10:26:01.993 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader: headertype:46 authuser:NULL
2016/07/28 10:26:01.993 kid1| 29,9| Config.cc(188) fixHeader: Sending type:46 header: 'Negotiate'
2016/07/28 10:26:02.004 kid1| 29,9| UserRequest.cc(487) addReplyAuthHeader: headertype:46 authuser:NULL
2016/07/28 10:26:02.004 kid1| 29,9| Config.cc(188) fixHeader: Sending type:46 header: 'Negotiate'
2016/07/28 10:26:09.555 kid1| 29,6| UserRequest.cc(179) releaseAuthServer: No Negotiate auth server to release.
2016/07/28 10:26:09.556 kid1| 29,6| UserRequest.cc(179) releaseAuthServer: No Negotiate auth server to release.
2016/07/28 10:26:09.556 kid1| 29,5| UserRequest.cc(101) ~UserRequest: freeing request 0x28576b0
2016/07/28 10:26:09.556 kid1| 29,5| User.cc(21) ~User: doing nothing to clear Negotiate scheme data for '0x2857400'
2016/07/28 10:26:09.556 kid1| 29,5| User.cc(127) ~User: Freeing auth_user '0x2857400'.
2016/07/28 10:26:09.559 kid1| 29,6| UserRequest.cc(179) releaseAuthServer: No Negotiate auth server to release.
2016/07/28 10:26:09.559 kid1| 29,6| UserRequest.cc(179) releaseAuthServer: No Negotiate auth server to release.
2016/07/28 10:26:09.559 kid1| 29,5| UserRequest.cc(101) ~UserRequest: freeing request 0x286f4d0
2016/07/28 10:26:09.559 kid1| 29,5| User.cc(21) ~User: doing nothing to clear Negotiate scheme data for '0x286f2a0'
2016/07/28 10:26:09.559 kid1| 29,5| User.cc(127) ~User: Freeing auth_user '0x286f2a0'.
2016/07/28 10:26:09.563 kid1| 29,6| UserRequest.cc(179) releaseAuthServer: No Negotiate auth server to release.
2016/07/28 10:26:09.563 kid1| 29,6| UserRequest.cc(179) releaseAuthServer: No Negotiate auth server to release.
2016/07/28 10:26:09.563 kid1| 29,5| UserRequest.cc(101) ~UserRequest: freeing request 0x2857ab0
2016/07/28 10:26:09.563 kid1| 29,5| User.cc(21) ~User: doing nothing to clear Negotiate scheme data for '0x241e990'
2016/07/28 10:26:09.563 kid1| 29,5| User.cc(127) ~User: Freeing auth_user '0x241e990'.
I've created the keytab on Windows using ktpass:
ktpass /princ host/kanban.infoestructura.local@EXAMPLE.LOCAL /mapuser squid@EXAMPLE.LOCAL /crypto rc4-hmac-nt /pass * /ptype KRB5_NT_PRINCIPAL /out C:\Soporte\winkrb5.keytab
and then copied to squid, and I see the following thing:
klist -kt /etc/squid/HTTP.keytab
Keytab name: FILE:/etc/squid/HTTP.keytab
KVNO Timestamp Principal
---- ------------------- ------------------------------------------------------
3 12/31/1969 21:00:00 HTTP/kanban.example.local@EXAMPLE.LOCAL
I wonder if the wrong timestamp has to do with the problem
Kerberos and relevant squid config files are as follows:
[logging] default = FILE:/var/log/krb5libs.log kdc = FILE:/var/log/krb5kdc.log admin_server = FILE:/var/log/kadmind.log
[libdefaults]
dns_lookup_realm = false
ticket_lifetime = 24h
renew_lifetime = 7d
forwardable = true
rdns = false
default_realm = EXAMPLE.LOCAL
default_ccache_name = KEYRING:persistent:%{uid}
; for Windows 2008 with AES
default_tgs_enctypes = aes256-cts-hmac-sha1-96 rc4-hmac des-cbc-crc des-cbc-md5
default_tkt_enctypes = aes256-cts-hmac-sha1-96 rc4-hmac des-cbc-crc des-cbc-md5
permitted_enctypes = aes256-cts-hmac-sha1-96 rc4-hmac des-cbc-crc des-cbc-md5
squid.conf:
auth_param negotiate program /usr/lib64/squid/negotiate_kerberos_auth -d -s HTTP/kanban.example.local@example.LOCAL
auth_param negotiate children 10
auth_param negotiate keep_alive on
acl kerb_auth proxy_auth REQUIRED
Is the keytab timestamp the cause of errors? Am I doing something wrong?