Re: [Freeipa-users] Intermittent Issues changing passwords since updating to ipa v3 and sasl_bind timeouts ..
On Tue, Nov 26, 2013 at 03:07:30PM +1000, Matt Bryant wrote: OK so been running some tcpdumps on this issue and the wierd thing is .. can see the initial sasl bind request followed by ack from ldap ... then nothing ldap/gssapi related until the unbind request post the 6s timeout period ... so no friggin idea whats going on just a big resounding nothing ... 14:20:47.065606 IP tardis.ipa.server-noc.com.40953 tardis.ipa.server-noc.com.ldap: Flags [P.], seq 261:974, ack 1502, win 280, options [nop,nop,TS val 23677005 ecr 23676785], length 713 14:20:47.104816 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.40953: Flags [.], ack 974, win 276, options [nop,nop,TS val 23677045 ecr 23677005], length 0 14:20:53.066009 IP tardis.ipa.server-noc.com.40953 tardis.ipa.server-noc.com.ldap: Flags [P.], seq 974:981, ack 1502, win 280, options [nop,nop,TS val 23683006 ecr 23677045], length 7 14:20:53.066021 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.40953: Flags [.], ack 981, win 276, options [nop,nop,TS val 23683006 ecr 23683006], length 0 14:20:53.066100 IP tardis.ipa.server-noc.com.40953 tardis.ipa.server-noc.com.ldap: Flags [F.], seq 981, ack 1502, win 280, options [nop,nop,TS val 23683006 ecr 23683006], length 0 14:20:53.105731 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.40953: Flags [.], ack 982, win 276, options [nop,nop,TS val 23683046 ecr 23683006], length 0 14:20:53.111470 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.40953: Flags [F.], seq 1502, ack 982, win 276, options [nop,nop,TS val 23683051 ecr 23683006], length 0 14:20:53.111486 IP tardis.ipa.server-noc.com.40953 tardis.ipa.server-noc.com.ldap: Flags [.], ack 1503, win 280, options [nop,nop,TS val 23683051 ecr 23683051], length 0 Comparing that to a connection that works and brings the backend online .. 14:22:01.193809 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [S], seq 3387425755, win 32792, options [mss 16396,sackOK,TS val 23751134 ecr 0,nop,wscale 7], length 0 14:22:01.193833 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.41031: Flags [S.], seq 1024653772, ack 3387425756, win 32768, options [mss 16396,sackOK,TS val 23751134 ecr 23751134,nop,wscale 7], length 0 14:22:01.193848 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [.], ack 1, win 257, options [nop,nop,TS val 23751134 ecr 23751134], length 0 14:22:01.194371 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [P.], seq 1:261, ack 1, win 257, options [nop,nop,TS val 23751134 ecr 23751134], length 260 14:22:01.194385 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.41031: Flags [.], ack 261, win 265, options [nop,nop,TS val 23751134 ecr 23751134], length 0 14:22:01.195187 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.41031: Flags [P.], seq 1:1502, ack 261, win 265, options [nop,nop,TS val 23751135 ecr 23751134], length 1501 14:22:01.195201 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [.], ack 1502, win 280, options [nop,nop,TS val 23751135 ecr 23751135], length 0 14:22:01.443288 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [P.], seq 261:953, ack 1502, win 280, options [nop,nop,TS val 23751383 ecr 23751135], length 692 14:22:01.470047 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.41031: Flags [P.], seq 1502:1677, ack 953, win 276, options [nop,nop,TS val 23751410 ecr 23751383], length 175 14:22:01.470062 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [.], ack 1677, win 304, options [nop,nop,TS val 23751410 ecr 23751410], length 0 14:22:01.470469 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [P.], seq 953:975, ack 1677, win 304, options [nop,nop,TS val 23751410 ecr 23751410], length 22 14:22:01.471249 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.41031: Flags [P.], seq 1677:1725, ack 975, win 276, options [nop,nop,TS val 23751411 ecr 23751410], length 48 14:22:01.471298 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [P.], seq 975:1031, ack 1725, win 304, options [nop,nop,TS val 23751411 ecr 23751411], length 56 14:22:01.484334 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.41031: Flags [P.], seq 1725:1739, ack 1031, win 276, options [nop,nop,TS val 23751424 ecr 23751411], length 14 14:22:01.485505 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [P.], seq 1031:1656, ack 1739, win 304, options [nop,nop,TS val 23751425 ecr 23751424], length 625 14:22:01.486736 IP tardis.ipa.server-noc.com.41031 tardis.ipa.server-noc.com.ldap: Flags [P.], seq 1656:2284, ack 1739, win 304, options [nop,nop,TS val 23751427 ecr 23751424], length 628 14:22:01.486747 IP tardis.ipa.server-noc.com.ldap tardis.ipa.server-noc.com.41031: Flags [.],
Re: [Freeipa-users] Intermittent Issues changing passwords since updating to ipa v3 and sasl_bind timeouts ..
Sumit,
Its a little tricky but ran up a script that did a ldapsearch every 2
seconds ... the following took place almost same time as one of the
sasl_bind timeouts ...
Start: .Wed Nov 27 07:55:03 EST 2013
ldap_url_parse_ext(ldap://tardis.ipa.server-noc.com)
ldap_create
ldap_url_parse_ext(ldap://tardis.ipa.server-noc.com:389/??base)
ldap_sasl_interactive_bind_s: user selected: GSSAPI
ldap_int_sasl_bind: GSSAPI
ldap_new_connection 1 1 0
ldap_int_open_connection
ldap_connect_to_host: TCP tardis.ipa.server-noc.com:389
ldap_new_socket: 3
ldap_prepare_socket: 3
ldap_connect_to_host: Trying 203.147.190.30:389
ldap_pvt_connect: fd: 3 tm: 6 async: 0
ldap_ndelay_on: 3
ldap_int_poll: fd: 3 tm: 6
ldap_is_sock_ready: 3
ldap_ndelay_off: 3
ldap_pvt_connect: 0
ldap_int_sasl_open: host=tardis.ipa.server-noc.com
SASL/GSSAPI authentication started
ldap_sasl_bind_s
ldap_sasl_bind
ldap_send_initial_request
ldap_send_server_request
ber_scanf fmt ({it) ber:
ber_scanf fmt ({i) ber:
ber_flush2: 692 bytes to sd 3
ldap_result ld 0xdbf4a0 msgid 1
wait4msg ld 0xdbf4a0 msgid 1 (infinite timeout)
wait4msg continue ld 0xdbf4a0 msgid 1 all 1
** ld 0xdbf4a0 Connections:
* host: tardis.ipa.server-noc.com port: 389 (default)
refcnt: 2 status: Connected
last used: Wed Nov 27 07:55:03 2013
** ld 0xdbf4a0 Outstanding Requests:
* msgid 1, origid 1, status InProgress
outstanding referrals 0, parent count 0
ld 0xdbf4a0 request count 1 (abandoned 0)
** ld 0xdbf4a0 Response Queue:
Empty
ld 0xdbf4a0 response count 0
ldap_chkResponseList ld 0xdbf4a0 msgid 1 all 1
ldap_chkResponseList returns ld 0xdbf4a0 NULL
ldap_int_select
read1msg: ld 0xdbf4a0 msgid 1 all 1
ber_get_next
ber_get_next: tag 0x30 len 172 contents:
read1msg: ld 0xdbf4a0 msgid 1 message type bind
ber_scanf fmt ({eAA) ber:
read1msg: ld 0xdbf4a0 0 new referrals
read1msg: mark request completed, ld 0xdbf4a0 msgid 1
request done: ld 0xdbf4a0 msgid 1
res_errno: 14, res_error: , res_matched:
ldap_free_request (origid 1, msgid 1)
ldap_parse_sasl_bind_result
ber_scanf fmt ({eAA) ber:
ber_scanf fmt (O) ber:
ldap_parse_result
ber_scanf fmt ({iAA) ber:
ber_scanf fmt (x) ber:
ber_scanf fmt (}) ber:
ldap_msgfree
sasl_client_step: 1
ldap_sasl_bind_s
ldap_sasl_bind
ldap_send_initial_request
ldap_send_server_request
ber_scanf fmt ({it) ber:
ber_scanf fmt ({i) ber:
ber_flush2: 22 bytes to sd 3
ldap_result ld 0xdbf4a0 msgid 2
wait4msg ld 0xdbf4a0 msgid 2 (infinite timeout)
wait4msg continue ld 0xdbf4a0 msgid 2 all 1
** ld 0xdbf4a0 Connections:
* host: tardis.ipa.server-noc.com port: 389 (default)
refcnt: 2 status: Connected
last used: Wed Nov 27 07:55:08 2013
** ld 0xdbf4a0 Outstanding Requests:
* msgid 2, origid 2, status InProgress
outstanding referrals 0, parent count 0
ld 0xdbf4a0 request count 1 (abandoned 0)
** ld 0xdbf4a0 Response Queue:
Empty
ld 0xdbf4a0 response count 0
ldap_chkResponseList ld 0xdbf4a0 msgid 2 all 1
ldap_chkResponseList returns ld 0xdbf4a0 NULL
ldap_int_select
read1msg: ld 0xdbf4a0 msgid 2 all 1
ber_get_next
ber_get_next: tag 0x30 len 46 contents:
read1msg: ld 0xdbf4a0 msgid 2 message type bind
ber_scanf fmt ({eAA) ber:
read1msg: ld 0xdbf4a0 0 new referrals
read1msg: mark request completed, ld 0xdbf4a0 msgid 2
request done: ld 0xdbf4a0 msgid 2
res_errno: 14, res_error: , res_matched:
ldap_free_request (origid 2, msgid 2)
ldap_parse_sasl_bind_result
ber_scanf fmt ({eAA) ber:
ber_scanf fmt (O) ber:
ldap_parse_result
ber_scanf fmt ({iAA) ber:
ber_scanf fmt (x) ber:
ber_scanf fmt (}) ber:
ldap_msgfree
sasl_client_step: 0
ldap_sasl_bind_s
ldap_sasl_bind
ldap_send_initial_request
ldap_send_server_request
ber_scanf fmt ({it) ber:
ber_scanf fmt ({i) ber:
ber_flush2: 56 bytes to sd 3
ldap_result ld 0xdbf4a0 msgid 3
wait4msg ld 0xdbf4a0 msgid 3 (infinite timeout)
wait4msg continue ld 0xdbf4a0 msgid 3 all 1
** ld 0xdbf4a0 Connections:
* host: tardis.ipa.server-noc.com port: 389 (default)
refcnt: 2 status: Connected
last used: Wed Nov 27 07:55:08 2013
** ld 0xdbf4a0 Outstanding Requests:
* msgid 3, origid 3, status InProgress
outstanding referrals 0, parent count 0
ld 0xdbf4a0 request count 1 (abandoned 0)
** ld 0xdbf4a0 Response Queue:
Empty
ld 0xdbf4a0 response count 0
ldap_chkResponseList ld 0xdbf4a0 msgid 3 all 1
ldap_chkResponseList returns ld 0xdbf4a0 NULL
ldap_int_select
read1msg: ld 0xdbf4a0 msgid 3 all 1
ber_get_next
ber_get_next: tag 0x30 len 12 contents:
read1msg: ld 0xdbf4a0 msgid 3 message type bind
ber_scanf fmt ({eAA) ber:
read1msg: ld 0xdbf4a0 0 new referrals
read1msg: mark request completed, ld 0xdbf4a0 msgid 3
request done: ld 0xdbf4a0 msgid 3
res_errno: 0, res_error: , res_matched:
ldap_free_request (origid 3, msgid 3)
ldap_parse_sasl_bind_result
ber_scanf fmt ({eAA) ber:
ldap_parse_result
ber_scanf fmt ({iAA) ber:
ber_scanf fmt (}) ber:
ldap_msgfree
SASL username: host/tardis.ipa.server-noc.com@SERVER-IPA
SASL SSF: 56
ldap_pvt_sasl_generic_install
SASL data security layer installed.
Re: [Freeipa-users] Intermittent Issues changing passwords since updating to ipa v3 and sasl_bind timeouts ..
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
Re: [Freeipa-users] Intermittent Issues changing passwords since updating to ipa v3 and sasl_bind timeouts ..
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
