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:

|(Wed Aug 23 16:07:06 2017) [sssd[be[ipa.example.com]]] [set_server_common_status] (0x0100): Marking server 'ipa-lx-test-01.ipa.example.com' as 'name resolved' (Wed Aug 23 16:07:06 2017) [sssd[be[ipa.example.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Wed Aug 23 16:07:06 2017) [sssd[be[ipa.example.com]]] [be_resolve_server_process] (0x0200): Found address for server ipa-lx-test-01.ipa.example.com: [x.x.x.x] TTL 1200 (Wed Aug 23 16:07:06 2017) [sssd[be[ipa.example.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://ipa-lx-test-01.ipa.example.com' (Wed Aug 23 16:07:06 2017) [sssd[be[ipa.example.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_2zXOse] (Wed Aug 23 16:07:06 2017) [sssd[be[ipa.example.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_2zXOse] (Wed Aug 23 16:07:06 2017) [sssd[be[ipa.example.com]]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [19] for the connection. (Wed Aug 23 16:07:06 2017) [sssd[be[ipa.example.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [sssd_async_connect_done] (0x0020): connect failed [113][Keine Route zum Zielrechner]. (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request failed: [113]: Keine Route zum Zielrechner. (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [sssd_async_socket_state_destructor] (0x0400): closing socket [19] (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [sss_ldap_init_sys_connect_done] (0x0020): sssd_async_socket_init request failed: [113]: Keine Route zum Zielrechner. (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [sdap_sys_connect_done] (0x0020): sdap_async_connect_call request failed: [113]: Keine Route zum Zielrechner. (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [sdap_handle_release] (0x2000): Trace: sh[0x558252c36770], connected[0], ops[(nil)], ldap[(nil)], destructor_lock[0], release_memory[0] (Wed Aug 23 16:07:09 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_cli_connect_done: 1572 (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [fo_set_port_status] (0x0100): Marking port 389 of server 'ipa-lx-test-01.ipa.example.com' as 'not working' (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [fo_set_port_status] (0x0400): Marking port 389 of duplicate server 'ipa-lx-test-01.ipa.example.com' as 'not working' |

Thats true, ‘Keine Route zum Zielrechner’ means ‘no route to host’, first instance is poweroff. Well looking forward in logfile

|(Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [get_server_status] (0x1000): Status of server 'ipa-lx-test-02.ipa.example.com' is 'name not resolved' (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [get_port_status] (0x1000): Port status of port 389 for server 'ipa-lx-test-02.ipa.example.com' is 'neutral' (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [get_server_status] (0x1000): Status of server 'ipa-lx-test-02.ipa.example.com' is 'name not resolved' (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolv_is_address] (0x4000): [ipa-lx-test-02.ipa.example.com] does not look like an IP address (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'ipa-lx-test-02.ipa.example.com' in files (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [set_server_common_status] (0x0100): Marking server 'ipa-lx-test-02.ipa.example.com' as 'resolving name' (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolv_gethostbyname_step] (0x2000): Querying files (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'ipa-lx-test-02.ipa.example.com' in files (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolv_gethostbyname_step] (0x2000): Querying DNS (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'ipa-lx-test-02.ipa.example.com' in DNS (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 6 seconds (Wed Aug 23 16:07:09 2017) [sssd[be[ipa.example.com]]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher (Wed Aug 23 16:07:10 2017) [sssd[be[ipa.example.com]]] [check_fd_timeouts] (0x4000): Checking for DNS timeouts (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [check_fd_timeouts] (0x4000): Checking for DNS timeouts (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [set_server_common_status] (0x0100): Marking server 'ipa-lx-test-02.ipa.example.com' as 'name resolved' (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]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://ipa-lx-test-02.ipa.example.com' (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_U1QQrA] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_U1QQrA] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [19] for the connection. (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldap://ipa-lx-test-02.ipa.example.com:389/??base] with fd [19]. (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_print_server] (0x2000): Searching x.x.x.x:389 (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][]. (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_op_add] (0x2000): New operation 1 timeout 6 (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x558252c35750], connected[1], ops[0x558252c36640], ldap[0x558252c130c0] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_entry] (0x1000): OriginalDN: []. (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [vendorName] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [vendorVersion] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [dataversion] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [netscapemdsuffix] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [changeLog] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [firstchangenumber] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [lastchangenumber] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipatopologypluginversion] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipatopologyismanaged] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaDomainLevel] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedFeatures] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [defaultNamingContext] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_parse_range] (0x2000): No sub-attributes for [lastUSN] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_process_result] (0x2000): Trace: sh[0x558252c35750], connected[1], ops[0x558252c36640], ldap[0x558252c130c0] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_op_destructor] (0x2000): Operation 1 finished (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_rootdse_done] (0x2000): Got rootdse (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [get_naming_context] (0x0200): Using value from [defaultNamingContext] as naming context. (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_set_search_base] (0x0100): Setting option [ldap_sudo_search_base] to [dc=ipa,dc=example,dc=com]. (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [common_parse_search_base] (0x0100): Search base added: [SUDO][dc=ipa,dc=example,dc=com][SUBTREE][] (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_get_server_opts_from_rootdse] (0x4000): USN value: 41151 (int: 41151) (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_kinit_send] (0x0400): Attempting kinit (default, host/ipa-lx-test-debian9.ipa.example.com, ipa.example.com, 86400) (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service IPA (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [get_server_status] (0x1000): Status of server 'ipa-lx-test-02.ipa.example.com' is 'name resolved' (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [get_server_status] (0x1000): Status of server 'ipa-lx-test-02.ipa.example.com' is 'name resolved' (Wed Aug 23 16:07:11 2017) [sssd[be[ipa.example.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (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' |

Ok, second server was found, but we ran in an timeout getting a TGT. If i manually try to get a kerberos ticket it works, but with a long delay.

ipa-lx-test-debian9.ipa.example.com’s sssd.conf:

|[domain/ipa.example.com] cache_credentials = True krb5_store_password_if_offline = True ipa_domain = ipa.example.com id_provider = ipa auth_provider = ipa access_provider = ipa ipa_hostname = ipa-lx-test-debian9.ipa.example.com chpass_provider = ipa ipa_dyndns_update = True ipa_server = _srv_, ipa-lx-test-01.ipa.example.com ldap_tls_cacert = /etc/ipa/ca.crt #subdomain_homedir = /home/%u fallback_homedir = /home/%u default_shell = /bin/bash shell_fallback = /bin/bash debug_level = 10 [sssd] services = nss, sudo, pam, ssh config_file_version = 2 domains = nbg.webtrekk.com default_domain_suffix = example.com full_name_format = %1$s debug_level = 10 [nss] debug_level = 10 [pam] [sudo] [autofs] [ssh] debug_level = 10 [pac] [ifp] |

So some need is help.

Michael

​