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....@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....@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....@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....@example.com
> [27472] 1482320667.513881: Storing 
> ipa-dnskeysyncd/server.example....@example.com -> 
> krbtgt/example....@example.com in FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.513974: Storing config in FILE:/tmp/ipa-dnskeysyncd.ccache 
> for krbtgt/example....@example.com: fast_avail: yes
> [27472] 1482320667.514022: Storing 
> ipa-dnskeysyncd/server.example....@example.com -> 
> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@X-CACHECONF:
>  in FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.514065: Storing config in FILE:/tmp/ipa-dnskeysyncd.ccache 
> for krbtgt/example....@example.com: pa_type: 2
> [27472] 1482320667.514102: Storing 
> ipa-dnskeysyncd/server.example....@example.com -> 
> krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.COM\@EXAMPLE.COM@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....@example.com -> 
> krb5_ccache_conf_data/refresh_time@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....@example.com for server principal 
> ldap/server.example....@example.com
> [27472] 1482320667.692119: Getting credentials 
> ipa-dnskeysyncd/server.example....@example.com -> 
> ldap/server.example....@example.com using ccache 
> FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.692241: Retrieving 
> ipa-dnskeysyncd/server.example....@example.com -> 
> ldap/server.example....@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....@example.com -> 
> krbtgt/example....@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....@example.com -> 
> krbtgt/example....@example.com
> [27472] 1482320667.692350: Requesting tickets for 
> ldap/server.example....@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....@example.com -> 
> ldap/server.example....@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....@example.com
> [27472] 1482320667.698150: Storing 
> ipa-dnskeysyncd/server.example....@example.com -> 
> ldap/server.example....@example.com in FILE:/tmp/ipa-dnskeysyncd.ccache
> [27472] 1482320667.698320: Creating authenticator for 
> ipa-dnskeysyncd/server.example....@example.com -> 
> ldap/server.example....@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....@example.com -> 
> ldap/server.example....@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....@example.com
principal.

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

-- 
Petr^2 Spacek

-- 
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

Reply via email to