[Freeipa-users] Intermittent Issues changing passwords since updating to ipa v3 and sasl_bind timeouts ..
Matt Bryant
matthew.bryant at melbourneit.com.au
Mon Nov 25 23:47:10 UTC 2013
After some further digging I tend to agree that its in the LDAP arena
where the issue lies .. but there is nothing in the ldap_child log thats
helping out .. (btw the other replica IPA servers dont seem to encounter
this issue just the master (ie the server with CA responsibility) ...
Also more logs (sigh) dont understand though how a server can be marked
as working and in the same second fail ... or what call is causing an
input/output error ... :(
(Tue Nov 26 09:14:58 2013) [sssd[be[ipa.server-noc.com]]]
[sasl_bind_send] (0x0100): Executing sasl bind mech: GSSAPI, user:
host/tardis.ipa.server-noc.com
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sasl_bind_send] (0x0020): ldap_sasl_bind failed (-5)[Timed out]
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sasl_bind_send] (0x0080): Extended failure message: [unknown error]
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[fo_set_port_status] (0x0100): Marking port 0 of server
'tardis.ipa.server-noc.com' as 'not working'
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_handle_release] (0x2000): Trace: sh[0x17dcf50], connected[1],
ops[(nil)], ldap[0x17d6920], destructor_lock[0], release_memory[0]
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[remove_connection_callback] (0x4000): Successfully removed connection
callback.
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_done] (0x4000): notify error to op #1: 5
[Input/output error]
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[acctinfo_callback] (0x0100): Request processed. Returned 3,5,User
lookup failed
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_release_conn_data] (0x4000): releasing unused connection
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): dbus conn: 174A470
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): Dispatching.
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[be_get_account_info] (0x0100): Got request for [4097][1][name=nobody]
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_step] (0x4000): beginning to connect
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[get_server_status] (0x1000): Status of server
'tardis.ipa.server-noc.com' is 'working'
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[get_port_status] (0x1000): Port status of port 0 for server
'tardis.ipa.server-noc.com' is 'not working'
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[fo_resolve_service_send] (0x0020): No available servers for service 'IPA'
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[be_resolve_server_done] (0x1000): Server resolution failed: 5
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_done] (0x0020): Failed to connect, going offline (5
[Input/output error])
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[be_mark_offline] (0x2000): Going offline!
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[be_run_offline_cb] (0x0080): Going offline. Running callbacks.
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_done] (0x4000): notify offline to op #1
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[acctinfo_callback] (0x0100): Request processed. Returned 1,11,Offline
(Tue Nov 26 09:15:04 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_release_conn_data] (0x4000): releasing unused connection
...
...
(Tue Nov 26 09:16:12 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): dbus conn: 171FDB0
(Tue Nov 26 09:16:12 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): Dispatching.
(Tue Nov 26 09:16:12 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_message_handler] (0x4000): Received SBUS method [ping]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): dbus conn: 174A470
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): Dispatching.
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_get_account_info] (0x0100): Got request for [4097][1][idnumber=493]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_get_account_info] (0x0100): Request processed. Returned 1,11,Fast
reply - offline
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_step] (0x4000): beginning to connect
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[get_server_status] (0x1000): Status of server
'tardis.ipa.server-noc.com' is 'working'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[get_port_status] (0x1000): Port status of port 0 for server
'tardis.ipa.server-noc.com' is 'not working'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[get_port_status] (0x0100): Reseting the status of port 0 for server
'tardis.ipa.server-noc.com'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to
10 seconds
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[get_server_status] (0x1000): Status of server
'tardis.ipa.server-noc.com' is 'working'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_resolve_server_process] (0x1000): Saving the first resolved server
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_resolve_server_process] (0x0200): Found address for server
tardis.ipa.server-noc.com: [203.147.190.30] TTL 7200
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[ipa_resolve_callback] (0x0400): Constructed uri
'ldap://tardis.ipa.server-noc.com'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sss_ldap_init_send] (0x4000): Using file descriptor [19] for LDAP
connection.
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sss_ldap_init_send] (0x0400): Setting 10 seconds timeout for connecting
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to
[ldap://tardis.ipa.server-noc.com:389/??base] with fd [19].
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_rootdse_send] (0x4000): Getting rootdse
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(objectclass=*)][].
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[supportedExtension]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[supportedLDAPVersion]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[supportedSASLMechanisms]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[domainControllerFunctionality]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[defaultNamingContext]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[highestCommittedUSN]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): dbus conn: 174A470
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): Dispatching.
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_get_account_info] (0x0100): Got request for [4097][1][*]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_process_result] (0x2000): Trace: sh[0x171e770], connected[1],
ops[0x17dded0], ldap[0x17378e0]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_entry] (0x4000): OriginalDN: [].
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [namingContexts]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [defaultnamingcontext]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [supportedControl]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for
[supportedSASLMechanisms]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [vendorName]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [vendorVersion]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [dataversion]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [netscapemdsuffix]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_parse_range] (0x2000): No sub-attributes for [lastusn]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_process_result] (0x2000): Trace: sh[0x171e770], connected[1],
ops[0x17dded0], ldap[0x17378e0]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no
errmsg set
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_rootdse_done] (0x2000): Got rootdse
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_server_opts_from_rootdse] (0x4000): USN value: 7097911 (int:
7097911)
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_kinit_send] (0x0400): Attempting kinit (default,
host/tardis.ipa.server-noc.com, SERVER-IPA, 86400)
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service IPA
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[get_server_status] (0x1000): Status of server
'tardis.ipa.server-noc.com' is 'working'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to
10 seconds
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[get_server_status] (0x1000): Status of server
'tardis.ipa.server-noc.com' is 'working'
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_resolve_server_process] (0x1000): Saving the first resolved server
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_resolve_server_process] (0x0200): Found address for server
tardis.ipa.server-noc.com: [203.147.190.30] TTL 7200
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get TGT...
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[create_tgt_req_send_buffer] (0x1000): buffer size: 56
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[child_handler_setup] (0x2000): Setting up signal handler up for pid
[26046]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[child_handler_setup] (0x2000): Signal handler set up for pid [26046]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt child
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_process_result] (0x2000): Trace: sh[0x171e770], connected[1],
ops[(nil)], ldap[0x17378e0]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[write_pipe_handler] (0x0400): All data has been sent!
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): dbus conn: 174A470
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): Dispatching.
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_get_account_info] (0x0100): Got request for [4098][1][*]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): dbus conn: 174A470
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): Dispatching.
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[be_get_account_info] (0x0100): Got request for [4097][1][idnumber=493]
(Tue Nov 26 09:16:21 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_step] (0x4000): waiting for connection to complete
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): dbus conn: 171FDB0
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): Dispatching.
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_message_handler] (0x4000): Received SBUS method [ping]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[child_sig_handler] (0x1000): Waiting for child [26046].
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[child_sig_handler] (0x0100): child [26046] finished successfully.
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sss_child_handler] (0x2000): waitpid failed [10]: No child processes
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[read_pipe_handler] (0x0400): EOF received, client finished
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_tgt_recv] (0x0400): Child responded: 0
[FILE:/var/lib/sss/db/ccache_SERVER-IPA], expired on [1385507781]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_cli_auth_step] (0x0100): expire timeout is 900
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_cli_auth_step] (0x1000): the connection will expire at 1385422282
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sasl_bind_send] (0x0100): Executing sasl bind mech: GSSAPI, user:
host/tardis.ipa.server-noc.com
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[fo_set_port_status] (0x0100): Marking port 0 of server
'tardis.ipa.server-noc.com' as 'working'
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[set_server_common_status] (0x0100): Marking server
'tardis.ipa.server-noc.com' as 'working'
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_done] (0x2000): Old USN: 7097881, New USN: 7097911
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_done] (0x4000): notify connected to op #1
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_users_next_base] (0x0400): Searching for users with base
[cn=accounts,dc=server-ipa]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(uidNumber=493)(objectclass=posixAccount))][cn=accounts,dc=server-ipa].
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[krbPasswordExpiration]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[userAccountControl]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[loginExpirationTime]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[loginAllowedTimeMap]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_done] (0x4000): notify connected to op #2
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_users_next_base] (0x0400): Searching for users with base
[cn=accounts,dc=server-ipa]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(uidNumber=493)(objectclass=posixAccount))][cn=accounts,dc=server-ipa].
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[krbPasswordExpiration]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[userAccountControl]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[loginExpirationTime]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[loginAllowedTimeMap]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 6
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_done] (0x4000): caching successful connection after
2 notifies
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[be_run_online_cb] (0x0080): Going online. Running callbacks.
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): dbus conn: 174A470
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_dispatch] (0x4000): Dispatching.
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[be_get_account_info] (0x0100): Got request for [4097][1][idnumber=495]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_step] (0x4000): reusing cached connection
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_users_next_base] (0x0400): Searching for users with base
[cn=accounts,dc=server-ipa]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[(&(uidNumber=495)(objectclass=posixAccount))][cn=accounts,dc=server-ipa].
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uid]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [homeDirectory]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbPrincipalName]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsUniqueId]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [entryUSN]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowLastChange]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMin]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowMax]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowWarning]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowInactive]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowExpire]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [shadowFlag]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [krbLastPwdChange]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[krbPasswordExpiration]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [pwdAttribute]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [authorizedService]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[userAccountControl]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [nsAccountLock]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [host]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginDisabled]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[loginExpirationTime]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[loginAllowedTimeMap]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 7
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_id_op_connect_step] (0x4000): reusing cached connection
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[objectclass=ipaNTTrustedDomain][cn=trusts,dc=server-ipa].
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaNTFlatName]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaNTTrustedDomainSID]
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 8
(Tue Nov 26 09:16:22 2013) [sssd[be[ipa.server-noc.com]]]
[delayed_online_authentication_callback] (0x0200): Backend is online,
starting delayed online authentication.
also seeing these errors ...
Tue Nov 26 09:42:02 2013) [sssd[be[ipa.server-noc.com]]] [ldb] (0x4000):
start ldb transaction (nesting: 0)
(Tue Nov 26 09:42:02 2013) [sssd[be[ipa.server-noc.com]]]
[sysdb_update_ranges] (0x0400): Adding range [SERVER-IPA_id_range].
(Tue Nov 26 09:42:02 2013) [sssd[be[ipa.server-noc.com]]]
[sysdb_range_create] (0x0040): Invalid range, expected that either the
secondary base rid or the SID of the trusted domain is set, but not both
or none of them.
(Tue Nov 26 09:42:02 2013) [sssd[be[ipa.server-noc.com]]]
[sysdb_range_create] (0x0400): Error: 22 (Invalid argument)
(Tue Nov 26 09:42:02 2013) [sssd[be[ipa.server-noc.com]]]
[sysdb_update_ranges] (0x0040): sysdb_range_create failed.
(Tue Nov 26 09:42:02 2013) [sssd[be[ipa.server-noc.com]]] [ldb]
(0x4000): cancel ldb transaction (nesting: 0)
(Tue Nov 26 09:42:02 2013) [sssd[be[ipa.server-noc.com]]]
[ipa_subdomains_handler_ranges_done] (0x0040): sysdb_update_ranges failed.
Have not setup any AD trusts etc ...
rgds
Matt B.
On 11/25/2013 06:49 PM, Sumit Bose wrote:
> On Mon, Nov 25, 2013 at 09:23:22AM +1000, Matt Bryant wrote:
>> All,
>>
>> Was wondering if anyone can help out or point us the in right
>> direction. Ever since we updated from IPA v2.1 to IPA v3.0 have been
>> seeing some intermittent errors when trying to change passwords etc.
>> Getting the error cannot change password since system offline.
>>
>> Have increased the logging and found that quite frequently the
>> sasl_bind using the host principle is timing out and failing ...
>> (whether this is red herring or not dont know but cant be good
>> anyhow)
>>
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_kinit_send] (0x0400): Attempting kinit (default,
>> host/tardis.ipa.server-noc.com, SERVER-IPA, 86400)
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_kinit_next_kdc] (0x1000): Resolving next KDC for service IPA
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA'
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [get_server_status] (0x1000): Status of server
>> 'tardis.ipa.server-noc.com' is 'working'
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set
>> to 10 seconds
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [get_server_status] (0x1000): Status of server
>> 'tardis.ipa.server-noc.com' is 'working'
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [be_resolve_server_process] (0x1000): Saving the first resolved
>> server
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [be_resolve_server_process] (0x0200): Found address for server
>> tardis.ipa.server-noc.com: [203.147.190.30] TTL 7200
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get
>> TGT...
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [create_tgt_req_send_buffer] (0x1000): buffer size: 56
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [child_handler_setup] (0x2000): Setting up signal handler up for pid
>> [3734]
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [child_handler_setup] (0x2000): Signal handler set up for pid [3734]
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [set_tgt_child_timeout] (0x0400): Setting 6 seconds timeout for tgt
>> child
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_process_result] (0x2000): Trace: sh[0xa45960], connected[1],
>> ops[(nil)], ldap[0xa12200]
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [write_pipe_handler] (0x0400): All data has been sent!
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [child_sig_handler] (0x1000): Waiting for child [3734].
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [child_sig_handler] (0x0100): child [3734] finished successfully.
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sss_child_handler] (0x2000): waitpid failed [10]: No child
>> processes
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [read_pipe_handler] (0x0400): EOF received, client finished
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_get_tgt_recv] (0x0400): Child responded: 0
>> [FILE:/var/lib/sss/db/ccache_SERVER-IPA], expired on [1385420045]
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_cli_auth_step] (0x0100): expire timeout is 900
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_cli_auth_step] (0x1000): the connection will expire at
>> 1385334545
>> (Mon Nov 25 08:54:05 2013) [sssd[be[ipa.server-noc.com]]]
>> [sasl_bind_send] (0x0100): Executing sasl bind mech: GSSAPI, user:
>> host/tardis.ipa.server-noc.com
>> (Mon Nov 25 08:54:11 2013) [sssd[be[ipa.server-noc.com]]]
>> [sasl_bind_send] (0x0020): ldap_sasl_bind failed (-5)[Timed out]
>> (Mon Nov 25 08:54:11 2013) [sssd[be[ipa.server-noc.com]]]
>> [sasl_bind_send] (0x0080): Extended failure message: [unknown error]
>> (Mon Nov 25 08:54:11 2013) [sssd[be[ipa.server-noc.com]]]
>> [fo_set_port_status] (0x0100): Marking port 0 of server
>> 'tardis.ipa.server-noc.com' as 'not working'
>> (Mon Nov 25 08:54:11 2013) [sssd[be[ipa.server-noc.com]]]
>> [sdap_handle_release] (0x2000): Trace: sh[0xa45960], connected[1],
>> ops[(nil)], ldap[0xa12200], destructor_lock[0], release_memory[0]
>> ..
>> ..
>>
>> it then goes on to connect to fail over server and succeed and
>> shortly after the master server is tested and marked as working
>> again ... works for a couple of times then time out again .. any
>> pointers gratefully received.
> According to the logs I would say that this timeout happens on the
> LDAP server side. Do you have a chance to check the server logs to see
> what happens at this time on the server?
>
> You can increase the timeout value on the client by setting
> ldap_opt_timeout to a larger value then 6 (the default). But please note
> that the operation might take longer then letting SSSD fail over to the
> next server.
>
> HTH
>
> bye,
> Sumit
>
>>
>> packages used ...
>>
>> ipa-server-3.0.0-25.el6.x86_64
>> sssd-1.9.2-82.11.el6_4.x86_64
>>
>> rgds
>>
>> Matt Bryant
>>
>> _______________________________________________
>> Freeipa-users mailing list
>> Freeipa-users at redhat.com
>> https://www.redhat.com/mailman/listinfo/freeipa-users
> _______________________________________________
> Freeipa-users mailing list
> Freeipa-users at redhat.com
> https://www.redhat.com/mailman/listinfo/freeipa-users
More information about the Freeipa-users
mailing list