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
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?
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.
|(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 ?
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
Oh, i missed logfile.
Am 24.08.2017 um 10:12 schrieb Michael Gusek via FreeIPA-users:
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.
|(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 ?
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
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
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
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 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@lists.fedorahosted.org
-
Jakub Hrozek -
Michael Gusek