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/[email protected] 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/[email protected] > [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/[email protected] 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/[email protected] > [27472] 1482320667.513881: Storing > ipa-dnskeysyncd/[email protected] -> > krbtgt/[email protected] in FILE:/tmp/ipa-dnskeysyncd.ccache > [27472] 1482320667.513974: Storing config in FILE:/tmp/ipa-dnskeysyncd.ccache > for krbtgt/[email protected]: fast_avail: yes > [27472] 1482320667.514022: Storing > ipa-dnskeysyncd/[email protected] -> > 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/[email protected]: pa_type: 2 > [27472] 1482320667.514102: Storing > ipa-dnskeysyncd/[email protected] -> > 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/[email protected] -> > 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/[email protected] for server principal > ldap/[email protected] > [27472] 1482320667.692119: Getting credentials > ipa-dnskeysyncd/[email protected] -> > ldap/[email protected] using ccache > FILE:/tmp/ipa-dnskeysyncd.ccache > [27472] 1482320667.692241: Retrieving > ipa-dnskeysyncd/[email protected] -> > ldap/[email protected] from FILE:/tmp/ipa-dnskeysyncd.ccache > with result: -1765328243/Matching credential not found (filename: > /tmp/ipa-dnskeysyncd.ccache) > [27472] 1482320667.692330: Retrieving > ipa-dnskeysyncd/[email protected] -> > krbtgt/[email protected] from FILE:/tmp/ipa-dnskeysyncd.ccache with > result: 0/Success > [27472] 1482320667.692342: Starting with TGT for client realm: > ipa-dnskeysyncd/[email protected] -> > krbtgt/[email protected] > [27472] 1482320667.692350: Requesting tickets for > ldap/[email protected], 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/[email protected] -> > ldap/[email protected] with session key aes256-cts/F2D7 > [27472] 1482320667.698130: TGS request result: 0/Success > [27472] 1482320667.698138: Received creds for desired service > ldap/[email protected] > [27472] 1482320667.698150: Storing > ipa-dnskeysyncd/[email protected] -> > ldap/[email protected] in FILE:/tmp/ipa-dnskeysyncd.ccache > [27472] 1482320667.698320: Creating authenticator for > ipa-dnskeysyncd/[email protected] -> > ldap/[email protected], 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/[email protected] -> > ldap/[email protected] 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/[email protected] 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
