[Freeipa-users] ipa-dnskeysyncd ipa : ERROR Login to LDAP server failed: {'desc': 'Invalid credentials'}

Wed Dec 21 14:04:01 UTC 2016

On 21.12.2016 13:05, Brian J. Murrell wrote:
> On Wed, 2016-12-21 at 08:24 +0100, Petr Spacek wrote:
>>
>> You can try to add line
>> KRB5_TRACE=/dev/stdout
>> to
>> /etc/sysconfig/ipa-dnskeysyncd
> 
> [27472] 1482320667.240500: Retrieving ipa-dnskeysyncd/server.example.com at EXAMPLE.COM from FILE:/etc/ipa/dnssec/ipa-dnskeysyncd.keytab (vno 0, enctype 0) with result: 0/Success
> [27472] 1482320667.240567: Getting initial credentials for ipa-dnskeysyncd/server.example.com at EXAMPLE.COM
> [27472] 1482320667.241542: Looked up etypes in keytab: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
> [27472] 1482320667.241619: Sending request (207 bytes) to EXAMPLE.COM
> [27472] 1482320667.241952: Resolving hostname server.example.com
> [27472] 1482320667.242781: Initiating TCP connection to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.243067: Sending TCP request to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.248018: Received answer (336 bytes) from stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.248054: Terminating TCP connection to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.248215: Response was from master KDC
> [27472] 1482320667.248250: Received error from KDC: -1765328359/Additional pre-authentication required
> [27472] 1482320667.248304: Processing preauth types: 136, 19, 2, 133
> [27472] 1482320667.248317: Selected etype info: etype aes256-cts, salt "EXAMPLE.COMipa-dnskeysyncdserver.example.com", params ""
> [27472] 1482320667.248327: Received cookie: MIT
> [27472] 1482320667.248400: Retrieving ipa-dnskeysyncd/server.example.com at EXAMPLE.COM from FILE:/etc/ipa/dnssec/ipa-dnskeysyncd.keytab (vno 0, enctype aes256-cts) with result: 0/Success
> [27472] 1482320667.248424: AS key obtained for encrypted timestamp: aes256-cts/BCCF
> [27472] 1482320667.248498: Encrypted timestamp (for 1482320667.247961): plain [redacted], encrypted [redacted]
> [27472] 1482320667.248512: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
> [27472] 1482320667.248520: Produced preauth for next request: 133, 2
> [27472] 1482320667.248540: Sending request (302 bytes) to EXAMPLE.COM
> [27472] 1482320667.248561: Resolving hostname server.example.com
> [27472] 1482320667.248841: Initiating TCP connection to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.249050: Sending TCP request to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.512953: Received answer (837 bytes) from stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.512974: Terminating TCP connection to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.513076: Response was from master KDC
> [27472] 1482320667.513117: Processing preauth types: 19
> [27472] 1482320667.513131: Selected etype info: etype aes256-cts, salt "EXAMPLE.COMipa-dnskeysyncdserver.example.com", params ""
> [27472] 1482320667.513143: Produced preauth for next request: (empty)
> [27472] 1482320667.513159: AS key determined by preauth: aes256-cts/BCCF
> [27472] 1482320667.513244: Decrypted AS reply; session key is: aes256-cts/BD92
> [27472] 1482320667.513271: FAST negotiation: available
> [27472] 1482320667.513297: Initializing FILE:/tmp/ipa-dnskeysyncd.ccache with default princ ipa-dnskeysyncd/server.example.com at EXAMPLE.COM
> [27472] 1482320667.513881: Storing ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> krbtgt/EXAMPLE.COM at EXAMPLE.COM in FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.513974: Storing config in FILE:/tmp/ipa-dnskeysyncd.ccache for krbtgt/EXAMPLE.COM at EXAMPLE.COM: fast_avail: yes
> [27472] 1482320667.514022: Storing ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM at X-CACHECONF: in FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.514065: Storing config in FILE:/tmp/ipa-dnskeysyncd.ccache for krbtgt/EXAMPLE.COM at EXAMPLE.COM: pa_type: 2
> [27472] 1482320667.514102: Storing ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM at X-CACHECONF: in FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.514181: Storing config in FILE:/tmp/ipa-dnskeysyncd.ccache for : refresh_time: 1482363867
> [27472] 1482320667.514220: Storing ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> krb5_ccache_conf_data/refresh_time at X-CACHECONF: in FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.619828: ccselect module realm chose cache FILE:/tmp/ipa-dnskeysyncd.ccache with client principal ipa-dnskeysyncd/server.example.com at EXAMPLE.COM for server principal ldap/server.example.com at EXAMPLE.COM
> [27472] 1482320667.692119: Getting credentials ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> ldap/server.example.com at EXAMPLE.COM using ccache FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.692241: Retrieving ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> ldap/server.example.com at EXAMPLE.COM from FILE:/tmp/ipa-dnskeysyncd.ccache with result: -1765328243/Matching credential not found (filename: /tmp/ipa-dnskeysyncd.ccache)
> [27472] 1482320667.692330: Retrieving ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> krbtgt/EXAMPLE.COM at EXAMPLE.COM from FILE:/tmp/ipa-dnskeysyncd.ccache with result: 0/Success
> [27472] 1482320667.692342: Starting with TGT for client realm: ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> krbtgt/EXAMPLE.COM at EXAMPLE.COM
> [27472] 1482320667.692350: Requesting tickets for ldap/server.example.com at EXAMPLE.COM, referrals on
> [27472] 1482320667.692383: Generated subkey for TGS request: aes256-cts/60D5
> [27472] 1482320667.692436: etypes requested in TGS request: aes256-cts, aes128-cts, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
> [27472] 1482320667.692530: Encoding request body and padata into FAST request
> [27472] 1482320667.692611: Sending request (1023 bytes) to EXAMPLE.COM
> [27472] 1482320667.692799: Resolving hostname server.example.com
> [27472] 1482320667.693065: Initiating TCP connection to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.693299: Sending TCP request to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.697728: Received answer (973 bytes) from stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.697748: Terminating TCP connection to stream fd31:aeb1:48df:0:214:d1ff:fe13:45ac:88
> [27472] 1482320667.697849: Response was from master KDC
> [27472] 1482320667.697879: Decoding FAST response
> [27472] 1482320667.698004: FAST reply key: aes256-cts/03A5
> [27472] 1482320667.698103: TGS reply is for ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> ldap/server.example.com at EXAMPLE.COM with session key aes256-cts/F2D7
> [27472] 1482320667.698130: TGS request result: 0/Success
> [27472] 1482320667.698138: Received creds for desired service ldap/server.example.com at EXAMPLE.COM
> [27472] 1482320667.698150: Storing ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> ldap/server.example.com at EXAMPLE.COM in FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.698320: Creating authenticator for ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> ldap/server.example.com at EXAMPLE.COM, seqnum 370535193, subkey aes256-cts/D075, session key aes256-cts/F2D7
> 
> The only thing I see there that is concerning is:
> 
> [27472] 1482320667.692241: Retrieving ipa-dnskeysyncd/server.example.com at EXAMPLE.COM -> ldap/server.example.com at EXAMPLE.COM from FILE:/tmp/ipa-dnskeysyncd.ccache with result: -1765328243/Matching credential not found (filename: /tmp/ipa-dnskeysyncd.ccache)
> 
> Is that the problem?

No, this is fine. It just shows that the credential was not found in
credentials cache. The next part of the log shows that the code goes not and
retrieves fresh credential from KDC and stores it into the credentials cache.

So, the Kerberos part certainly works... Next step is to look into access log
from LDAP server to see what is logged in there. Please look into
/var/log/dirsrv/slapd-*/access
and look for lines concerning ipa-dnskeysyncd/server.example.com at EXAMPLE.COM
principal.

I'm really curious what you will find out :-)

-- 
Petr^2 Spacek