Hello,

some new information. We can reproduce timeout problems on all environments we tested. One special think is, if we test with an centos 7 client, we have no problems. All other clients (Debian 8/9, Ubuntu 16.04, Centos 6) runs in timeout. It’s seems we have some trouble with kerberos. I run kinit on a Debian 9 machine without first freeipa server:

date; KRB5_TRACE=/dev/stderr kinit -k -t /etc/krb5.keytab host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM; date
Fr 1. Sep 12:12:01 CEST 2017                                                                                                                                                                                       [3322] 1504260721.586024: Getting initial credentials for host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM
[3322] 1504260721.586884: Looked up etypes in keytab: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac
[3322] 1504260721.587369: Sending request (218 bytes) to IPA.EXAMPLE.COM
[3322] 1504260736.605610: Resolving hostname ipa-lx-test-02.ipa.example.com.
[3322] 1504260741.613421: Sending initial UDP request to dgram <ip_second_freepa_server>:88
[3322] 1504260741.620190: Received answer (346 bytes) from dgram <ip_second_freepa_server>:88
[3322] 1504260751.629540: Response was from master KDC                          
[3322] 1504260751.630209: Received error from KDC: -1765328359/zusätzlich Vorauthentifizierung erforderlich
[3322] 1504260751.630465: Processing preauth types: 136, 19, 2, 133
[3322] 1504260751.630491: Selected etype info: etype aes256-cts, salt "IPA.EXAMPLE.COMhostipa-lx-test-debian9.ipa.example.com", params ""
[3322] 1504260751.630519: Received cookie: MIT                      
[3322] 1504260751.630793: Retrieving host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM from FILE:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[3322] 1504260751.630840: AS key obtained for encrypted timestamp: aes256-cts/6BAE
[3322] 1504260751.630953: Encrypted timestamp (for 1504260741.619515): plain 301AA011180F32303137303930313130313232315AA10502030973FB, encrypted 159D40A2802FF0B5863C075284E3D5086DFF4CF24951374647E501ECA2F2D09230
C57880876C2E55209D23B678D12D54A464D52130546708                                                                                                              
[3322] 1504260751.631066: Preauth module encrypted_timestamp (2) (real) returned: 0/Success                                                                                        
[3322] 1504260751.631084: Produced preauth for next request: 133, 2                                                                              
[3322] 1504260751.631125: Sending request (313 bytes) to IPA.EXAMPLE.COM                                                                                                                                          [3322] 1504260766.647110: Resolving hostname ipa-lx-test-01.ipa.example.com.
[3322] 1504260771.653349: Sending initial UDP request to dgram <ip_first_freepa_server>:88                                                              
[3322] 1504260772.654458: Resolving hostname ipa-lx-test-02.ipa.example.com.                                                                                                                                      [3322] 1504260777.660742: Sending initial UDP request to dgram <ip_second_freepa_server>:88
[3322] 1504260777.710507: Received answer (853 bytes) from dgram <ip_second_freepa_server>:88
[3322] 1504260787.720438: Response was from master KDC
[3322] 1504260787.720549: Processing preauth types: 19
[3322] 1504260787.720571: Selected etype info: etype aes256-cts, salt "IPA.EXAMPLE.COMhostipa-lx-test-debian9.ipa.example.com", params ""
[3322] 1504260787.720600: Produced preauth for next request: (empty)
[3322] 1504260787.720638: AS key determined by preauth: aes256-cts/6BAE
[3322] 1504260787.720752: Decrypted AS reply; session key is: aes256-cts/AD23
[3322] 1504260787.720793: FAST negotiation: available
[3322] 1504260787.720839: Initializing KEYRING:persistent:0:krb_ccache_y1364Hz with default princ host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM
[3322] 1504260787.720928: Storing host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in KEYRING:persistent:0:krb_ccache_y1364Hz
[3322] 1504260787.721029: Storing config in KEYRING:persistent:0:krb_ccache_y1364Hz for krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM: fast_avail: yes
[3322] 1504260787.721070: Storing host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM@X-CACHECONF: in KEYRING:persistent:0:kr
b_ccache_y1364Hz
[3322] 1504260787.721153: Storing config in KEYRING:persistent:0:krb_ccache_y1364Hz for krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM: pa_type: 2
[3322] 1504260787.721184: Storing host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM@X-CACHECONF: in KEYRING:persistent:0:krb_c
cache_y1364Hz
Fr 1. Sep 12:13:07 CEST 2017

And than with first ipa server:

date; KRB5_TRACE=/dev/stderr kinit -k -t /etc/krb5.keytab host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM; date
Fr 1. Sep 12:52:29 CEST 2017
[3367] 1504263149.757320: Getting initial credentials for host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM
[3367] 1504263149.758392: Looked up etypes in keytab: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac
[3367] 1504263149.758871: Sending request (218 bytes) to IPA.EXAMPLE.COM
[3367] 1504263149.761654: Resolving hostname ipa-lx-test-01.ipa.example.com.
[3367] 1504263149.763472: Sending initial UDP request to dgram <ip_first_freepa_server>:88
[3367] 1504263149.768906: Received answer (346 bytes) from dgram <ip_first_freepa_server>:88
[3367] 1504263149.770289: Response was from master KDC
[3367] 1504263149.770598: Received error from KDC: -1765328359/zusätzlich Vorauthentifizierung erforderlich
[3367] 1504263149.770961: Processing preauth types: 136, 19, 2, 133
[3367] 1504263149.770983: Selected etype info: etype aes256-cts, salt "IPA.EXAMPLE.COMhostipa-lx-test-debian9.ipa.example.com", params ""
[3367] 1504263149.771230: Received cookie: MIT
[3367] 1504263149.771843: Retrieving host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM from FILE:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[3367] 1504263149.772284: AS key obtained for encrypted timestamp: aes256-cts/6BAE
[3367] 1504263149.772629: Encrypted timestamp (for 1504263149.854417): plain 301AA011180F32303137303930313130353232395AA10502030D0991, encrypted 321783A9E5E7B15D62F61B9D0177E7284193EE6AE531CDD730E021E149A4C1AD4C
1970D2DC5C5A608CD8B1CB24E1737BA916BDF62B73330B
[3367] 1504263149.773120: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[3367] 1504263149.773135: Produced preauth for next request: 133, 2
[3367] 1504263149.773601: Sending request (313 bytes) to IPA.EXAMPLE.COM
[3367] 1504263149.775373: Resolving hostname ipa-lx-test-02.ipa.example.com.
[3367] 1504263149.776259: Sending initial UDP request to dgram <ip_second_freepa_server>:88
[3367] 1504263149.831817: Received answer (853 bytes) from dgram <ip_second_freepa_server>:88
[3367] 1504263149.833719: Response was from master KDC
[3367] 1504263149.834058: Processing preauth types: 19
[3367] 1504263149.834077: Selected etype info: etype aes256-cts, salt "IPA.EXAMPLE.COMhostipa-lx-test-debian9.ipa.example.com", params ""
[3367] 1504263149.834326: Produced preauth for next request: (empty)
[3367] 1504263149.834868: AS key determined by preauth: aes256-cts/6BAE
[3367] 1504263149.835207: Decrypted AS reply; session key is: aes256-cts/5B05
[3367] 1504263149.835510: FAST negotiation: available
[3367] 1504263149.835780: Initializing KEYRING:persistent:0:krb_ccache_y1364Hz with default princ host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM
[3367] 1504263149.836208: Storing host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM -> krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM in KEYRING:persistent:0:krb_ccache_y1364Hz
[3367] 1504263149.836647: Storing config in KEYRING:persistent:0:krb_ccache_y1364Hz for krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM: fast_avail: yes
[3367] 1504263149.837000: Storing host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM@X-CACHECONF: in KEYRING:persistent:0:kr
b_ccache_y1364Hz
[3367] 1504263149.837513: Storing config in KEYRING:persistent:0:krb_ccache_y1364Hz for krbtgt/IPA.EXAMPLE.COM@IPA.EXAMPLE.COM: pa_type: 2
[3367] 1504263149.837836: Storing host/ipa-lx-test-debian9.ipa.example.com@IPA.EXAMPLE.COM -> krb5_ccache_conf_data/pa_type/krbtgt\/IPA.EXAMPLE.COM\@IPA.EXAMPLE.COM@X-CACHECONF: in KEYRING:persistent:0:krb_c
cache_y1364Hz
Fr 1. Sep 12:52:29 CEST 2017

If we change /etc/resolv.conf that second freeipa server is listed before first server, we got our ticket as expected:

date; KRB5_TRACE=/dev/stderr kinit -k -t /etc/krb5.keytab host/ipa-lx-test-debian9.nbg.webtrekk.com@NBG.WEBTREKK.COM; date
Fr 1. Sep 13:23:26 CEST 2017
[377] 1504265006.312401: Getting initial credentials for host/ipa-lx-test-debian9.nbg.webtrekk.com@NBG.WEBTREKK.COM
[377] 1504265006.313134: Looked up etypes in keytab: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac
[377] 1504265006.313281: Sending request (218 bytes) to NBG.WEBTREKK.COM
[377] 1504265006.315715: Resolving hostname ipa-lx-test-02.nbg.webtrekk.com.
[377] 1504265006.317085: Sending initial UDP request to dgram 172.25.5.158:88
[377] 1504265006.321621: Received answer (346 bytes) from dgram 172.25.5.158:88
[377] 1504265006.322942: Response was from master KDC
[377] 1504265006.323002: Received error from KDC: -1765328359/zusätzlich Vorauthentifizierung erforderlich
[377] 1504265006.323070: Processing preauth types: 136, 19, 2, 133
[377] 1504265006.323091: Selected etype info: etype aes256-cts, salt "NBG.WEBTREKK.COMhostipa-lx-test-debian9.nbg.webtrekk.com", params ""
[377] 1504265006.323108: Received cookie: MIT
[377] 1504265006.323286: Retrieving host/ipa-lx-test-debian9.nbg.webtrekk.com@NBG.WEBTREKK.COM from FILE:/etc/krb5.keytab (vno 0, enctype aes256-cts) with result: 0/Success
[377] 1504265006.323324: AS key obtained for encrypted timestamp: aes256-cts/6BAE
[377] 1504265006.323424: Encrypted timestamp (for 1504265006.319960): plain 301AA011180F32303137303930313131323332365AA105020304E1D8, encrypted 98F9D8555750DAFCB63346659ED490F7731E94C675EF45D643669E8107950B404CCF6DA4EA78D1F9CBDDFD896CAEDA11809DA855647D4C27
[377] 1504265006.323452: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[377] 1504265006.323467: Produced preauth for next request: 133, 2
[377] 1504265006.323499: Sending request (313 bytes) to NBG.WEBTREKK.COM
[377] 1504265006.324868: Resolving hostname ipa-lx-test-01.nbg.webtrekk.com.
[377] 1504265006.325426: Sending initial UDP request to dgram 172.25.5.153:88
[377] 1504265007.326527: Resolving hostname ipa-lx-test-02.nbg.webtrekk.com.
[377] 1504265007.327750: Sending initial UDP request to dgram 172.25.5.158:88
[377] 1504265007.411975: Received answer (853 bytes) from dgram 172.25.5.158:88
[377] 1504265007.413248: Response was from master KDC
[377] 1504265007.413311: Processing preauth types: 19
[377] 1504265007.413335: Selected etype info: etype aes256-cts, salt "NBG.WEBTREKK.COMhostipa-lx-test-debian9.nbg.webtrekk.com", params ""
[377] 1504265007.413353: Produced preauth for next request: (empty)
[377] 1504265007.413374: AS key determined by preauth: aes256-cts/6BAE
[377] 1504265007.413480: Decrypted AS reply; session key is: aes256-cts/7D39
[377] 1504265007.413523: FAST negotiation: available
[377] 1504265007.413570: Initializing KEYRING:persistent:0:krb_ccache_y1364Hz with default princ host/ipa-lx-test-debian9.nbg.webtrekk.com@NBG.WEBTREKK.COM
[377] 1504265007.413655: Storing host/ipa-lx-test-debian9.nbg.webtrekk.com@NBG.WEBTREKK.COM -> krbtgt/NBG.WEBTREKK.COM@NBG.WEBTREKK.COM in KEYRING:persistent:0:krb_ccache_y1364Hz
[377] 1504265007.413759: Storing config in KEYRING:persistent:0:krb_ccache_y1364Hz for krbtgt/NBG.WEBTREKK.COM@NBG.WEBTREKK.COM: fast_avail: yes
[377] 1504265007.413800: Storing host/ipa-lx-test-debian9.nbg.webtrekk.com@NBG.WEBTREKK.COM -> krb5_ccache_conf_data/fast_avail/krbtgt\/NBG.WEBTREKK.COM\@NBG.WEBTREKK.COM@X-CACHECONF: in KEYRING:persistent:0:krb_ccache_y1364Hz
[377] 1504265007.413886: Storing config in KEYRING:persistent:0:krb_ccache_y1364Hz for krbtgt/NBG.WEBTREKK.COM@NBG.WEBTREKK.COM: pa_type: 2
[377] 1504265007.413918: Storing host/ipa-lx-test-debian9.nbg.webtrekk.com@NBG.WEBTREKK.COM -> krb5_ccache_conf_data/pa_type/krbtgt\/NBG.WEBTREKK.COM\@NBG.WEBTREKK.COM@X-CACHECONF: in KEYRING:persistent:0:krb_ccache_y1364Hz
Fr 1. Sep 13:23:27 CEST 2017

Is this a normal behavior ? How can we work with this ?

Michael

Am 31.08.2017 um 09:32 schrieb Michael Gusek via FreeIPA-users:

Hi,

just for info. We restart our setup on an other stage in our dc with same result, we run in timeouts if first installed ipa server not available. So we give it a try in a complete different environment, with successfully failover. It  seem's we have a problem in our dc and we will have a deeper look on our environment.

Thanks,

Michael


Am 24.08.2017 um 21:12 schrieb Jakub Hrozek via FreeIPA-users:
On Thu, Aug 24, 2017 at 10:12:55AM +0200, Michael Gusek via FreeIPA-users wrote:
Hello Jakub,

here the first lines of ldap_child.log

|(Wed Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]] [main] (0x0400):
ldap_child started. (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [main] (0x2000): context initialized (Wed Aug
23 16:07:11 2017) [[sssd[ldap_child[2104]]]] [unpack_buffer] (0x1000):
total buffer size: 81 (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [unpack_buffer] (0x1000): realm_str size: 16
(Wed Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]] [unpack_buffer]
(0x1000): got realm_str: IPA.EXAMPLE.COM (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [unpack_buffer] (0x1000): princ_str size: 41
(Wed Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]] [unpack_buffer]
(0x1000): got princ_str: host/ipa-lx-test-debian9.ípa.example.com (Wed
Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]] [unpack_buffer]
(0x1000): keytab_name size: 0 (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [unpack_buffer] (0x1000): lifetime: 86400
(Wed Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]] [unpack_buffer]
(0x0200): Will run as [0][0]. (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [privileged_krb5_setup] (0x2000): Kerberos
context initialized (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [main] (0x2000): Kerberos context initialized
(Wed Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]] [become_user]
(0x0200): Trying to become user [0][0]. (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [become_user] (0x0200): Already user [0].
(Wed Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]] [main] (0x2000):
Running as [0][0]. (Wed Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]]
[main] (0x2000): getting TGT sync (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [ldap_child_get_tgt_sync] (0x2000): got
realm_name: [IPA.EXAMPLE.COM] (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [ldap_child_get_tgt_sync] (0x0100): Principal
name is: [host/ipa-lx-test-debian9.ípa.example.com@IPA.EXAMPLE.COM] (Wed
Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]]
[ldap_child_get_tgt_sync] (0x0100): Using keytab
[MEMORY:/etc/krb5.keytab] (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [ldap_child_get_tgt_sync] (0x0100): Will
canonicalize principals (Wed Aug 23 16:07:11 2017)
[[sssd[ldap_child[2104]]]] [sss_child_krb5_trace_cb] (0x4000): [2104]
1503497231.122092: Getting initial credentials for
host/ipa-lx-test-debian9.ípa.example.com@IPA.EXAMPLE.COM (Wed Aug 23
16:07:11 2017) [[sssd[ldap_child[2104]]]] [sss_child_krb5_trace_cb]
(0x4000): [2104] 1503497231.122313: Looked up etypes in keytab:
aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1,
rc4-hmac (Wed Aug 23 16:07:11 2017) [[sssd[ldap_child[2104]]]]
[sss_child_krb5_trace_cb] (0x4000): [2104] 1503497231.122451: Sending
request (218 bytes) to IPA.EXAMPLE.COM (Wed Aug 23 16:07:17 2017)
[[sssd[ldap_child[2104]]]] [sig_term_handler] (0x0010): Received signal
[Terminated] [15], shutting down (Wed Aug 23 16:07:17 2017)
[[sssd[ldap_child[2104]]]] [sig_term_handler] (0x0010): Unlink file
[/var/lib/sss/db/ccache_IPA.EXAMPLE.COM_TmKHkD] (Wed Aug 23 16:07:17
2017) [[sssd[ldap_child[2105]]]] [main] (0x0400): ldap_child started.
(Wed Aug 23 16:07:17 2017) [[sssd[ldap_child[2105]]]] [main] (0x2000):
context initialized |

We connect to IPA.EXAMPLE.COM, this is not helpfull. You can see, there
is a delay of 5 seconds. Later in this file, you can see, we try to
connect to second server ipa-lx-test-02.ípa.example.com.
Right, sssd says it does, but I really wonder why the ldap_child
timeouts even in that case. Are there any log entries in the
ipa-lx-test-02.ípa.example.com's log files around the time sssd connects
to it?

And also -- could you run a simple tcpdump (tcpdump -i eth1 -x "port
88 or port 53") to see what hosts does sssd talk to and what hosts does
it discover?

What I'm wondering is -- does SSSD really talk to the right server at
that time or does it keep trying the bad one even if it should be trying
the one that is up?

By the way, I'm suprised that the failover doesn't work for you. This is a
quite basic feature that had been developed years ago. Can you also specify
exactly how you bring one of the IDM servers down? Do you power it off,
run ipactl stop, ...?

|(Wed Aug 23 16:10:14 2017) [[sssd[ldap_child[2129]]]]
[sss_child_krb5_trace_cb] (0x4000): [2129] 1503497414.357486: Getting
initial credentials for
host/ipa-lx-test-debian9.ípa.example.com@IPA.EXAMPLE.COM (Wed Aug 23
16:10:14 2017) [[sssd[ldap_child[2129]]]] [sss_child_krb5_trace_cb]
(0x4000): [2129] 1503497414.357715: Looked up etypes in keytab:
aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1,
rc4-hmac (Wed Aug 23 16:10:14 2017) [[sssd[ldap_child[2129]]]]
[sss_child_krb5_trace_cb] (0x4000): [2129] 1503497414.357842: Sending
request (218 bytes) to IPA.EXAMPLE.COM (Wed Aug 23 16:10:14 2017)
[[sssd[ldap_child[2129]]]] [sss_child_krb5_trace_cb] (0x4000): [2129]
1503497414.360574: Resolving hostname ipa-lx-test-02.ípa.example.com.
(Wed Aug 23 16:10:14 2017) [[sssd[ldap_child[2129]]]]
[sss_child_krb5_trace_cb] (0x4000): [2129] 1503497414.362141: Sending
initial UDP request to dgram <ip_of_ipa-lx-test-02>:88 (Wed Aug 23
16:10:14 2017) [[sssd[ldap_child[2129]]]] [sss_child_krb5_trace_cb]
(0x4000): [2129] 1503497414.367725: Received answer (346 bytes) from
dgram <ip_of_ipa-lx-test-02>:88 (Wed Aug 23 16:10:19 2017)
[[sssd[ldap_child[2129]]]] [sss_child_krb5_trace_cb] (0x4000): [2129]
1503497419.374601: Response was from master KDC |

I think this was my test with ‘kinit admin@IPA.EXAMPLE.COM’. You can
find whole log file attached. From my point of view, failover to second
KDC is not fast enough and we should set some timeouts in sssd.conf or
krb5.conf ?
Well, kinit doesn't talk to sssd..

sssd only has interfaces towards the NSS and PAM subsystems, so kinit
talks straight to libkrb5. What /KDCs/ does kinit talk to depends on
libkrb5 configuration. In your case, it doesn't contain any KDCs, so
it's either what SSSD tells libkrb5 to look at (through a kdcinfo file
interface) DNS (because dns_lookup_kdc = true) in this order. And the
kdcinfo files should not be generated unless sssd can switch to the
'online' mode here.

krb5.conf from ipa-lx-test-debian9:

|#File modified by ipa-client-install includedir
/var/lib/sss/pubconf/krb5.include.d/ [libdefaults] default_realm =
IPA.EXAMPLE.COM dns_lookup_realm = true dns_lookup_kdc = true rdns =
false ticket_lifetime = 24h forwardable = yes default_ccache_name =
KEYRING:persistent:%{uid} [realms] IPA.EXAMPLE.COM = { pkinit_anchors =
FILE:/etc/ipa/ca.crt } [domain_realm] .ipa.example.com = IPA.EXAMPLE.COM
ipa.example.com = IPA.EXAMPLE.COM |

Regards,

Michael

Am 23.08.2017 um 22:20 schrieb Jakub Hrozek via FreeIPA-users:

On Wed, Aug 23, 2017 at 05:13:13PM +0200, Michael Gusek via FreeIPA-users wrote:
Hi,

we are testing a FreeIPA trust to an Active Directory. Trust itself
works, we are happy. Now we tested a failure on FreeIPA site. We have
two instances, both with same roles. If we poweroff first installed
server, and clean sssd caches with restart of sssd on client side , sssd
service can’t establish a connection to second instance.

ipa-lx-test-01.ipa.example.com is the first installed FreeIPA with
ipa-server-4.4.0-14.el7.centos.7.x86_64 on latest CentOS7
ipa-lx-test-02.ipa.example.com is the second installed FreeIPA with
ipa-server-4.4.0-14.el7.centos.7.x86_64 on latest CentOS7
ipa-lx-test-debian9.ipa.example.com is a latest Debian 9.1 with sssd
1.15.0-3

For deeper inspection full log is attached. In logs we found something
like this:
OK, so as you say communication with the KDC failed:
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [be_resolve_server_process] (0x0200): Found address for server ipa-lx-test-02.ipa.example.com: [x.x.x.x] TTL 1200                                       
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT...                                                                              
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [create_tgt_req_send_buffer] (0x0400): buffer size: 81                                                                                                  
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [2104]                                                                             
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [2104]                                                                                    
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child                                                                               
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x558252c35750], connected[1], ops[(nil)], ldap[0x558252c130c0]                                               
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_process_result] (0x2000): Trace: end of ldap_result list                                                                                          
(Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [write_pipe_handler] (0x0400): All data has been sent!                                                                                                  
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [get_tgt_timeout_handler] (0x4000): timeout for sending SIGTERM to tgt child [2104] reached.                                                            
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [get_tgt_timeout_handler] (0x0400): Setting 2 seconds timeout for sending SIGKILL to tgt child                                                          
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [read_pipe_handler] (0x0400): EOF received, client finished                                                                                             
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [child_sig_handler] (0x1000): Waiting for child [2104].                                                                                                 
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [child_sig_handler] (0x0020): child [2104] failed with status [7].                                                                                      
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [child_callback] (0x0020): LDAP child was terminated due to timeout                                                                                     
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [sdap_kinit_done] (0x0080): Communication with KDC timed out, trying the next one                                                                       
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_NOT_WORKING. Called from: ../src/providers/ldap/sdap_async_connection.c: sdap_kinit_done: 1207  
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'ipa-lx-test-02.ipa.example.com' as 'not working'                                             
(Wed Aug 23 16:07:17 2017) [sssd[be[ipa.example.com]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'ipa-lx-test-02.ipa.example.com' as 'not working' 

Could you check in the ldap_child.log which KDC did SSSD try to talk to
and what takes so long?
_______________________________________________
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org
​
-- 

________________________________________________


*Michael**Gusek*| System Administrator| Webtrekk GmbH |
*t*+49 30 755 415 302| *f *+49 30 755 415 100 | *w *www.webtrekk.com
<https://www.webtrekk.com/?wt_mc=signature.-.-.-.homepageURL>
Amtsgericht/Local Court Berlin, HRB 93435 B | Geschäftsführer/CEO
Christian Sauer und Wolf Lichtenstein


_______________________________________________
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org
_______________________________________________
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

--

________________________________________________


Michael Gusek | System Administrator | Webtrekk GmbH |
t +49 30 755 415 302 | f +49 30 755 415 100 | w www.webtrekk.com
Amtsgericht/Local Court Berlin, HRB 93435 B | Geschäftsführer/CEO Christian Sauer und Wolf Lichtenstein




_______________________________________________
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org

--

________________________________________________


Michael Gusek | System Administrator | Webtrekk GmbH |
t +49 30 755 415 302 | f +49 30 755 415 100 | w www.webtrekk.com
Amtsgericht/Local Court Berlin, HRB 93435 B | Geschäftsführer/CEO Christian Sauer und Wolf Lichtenstein