[Freeipa-users] Intermittent Issues changing passwords since updating to ipa v3 and sasl_bind timeouts ..
Matt Bryant
matthew.bryant at melbourneit.com.au
Tue Nov 26 05:07:30 UTC 2013
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 [.], ack 2284, win 297, options
[nop,nop,TS val 23751427 ecr 23751425], length 0
14:22:01.516185 IP tardis.ipa.server-noc.com.41031 >
tardis.ipa.server-noc.com.ldap: Flags [P.], seq 2284:2474, ack 1739, win
304, options [nop,nop,TS val 23751456 ecr 23751427], length 190
14:22:01.555664 IP tardis.ipa.server-noc.com.ldap >
tardis.ipa.server-noc.com.41031: Flags [.], ack 2474, win 308, options
[nop,nop,TS val 23751496 ecr 23751456], length 0
14:22:07.487451 IP tardis.ipa.server-noc.com.41031 >
tardis.ipa.server-noc.com.ldap: Flags [P.], seq 2474:2546, ack 1739, win
304, options [nop,nop,TS val 23757427 ecr 23751496], length 72
14:22:07.487467 IP tardis.ipa.server-noc.com.ldap >
tardis.ipa.server-noc.com.41031: Flags [.], ack 2546, win 308, options
[nop,nop,TS val 23757427 ecr 23757427], length 0
14:22:07.487983 IP tardis.ipa.server-noc.com.41031 >
tardis.ipa.server-noc.com.ldap: Flags [P.], seq 2546:2618, ack 1739, win
304, options [nop,nop,TS val 23757428 ecr 23757427], length 72
14:22:07.487994 IP tardis.ipa.server-noc.com.ldap >
tardis.ipa.server-noc.com.41031: Flags [.], ack 2618, win 308, options
[nop,nop,TS val 23757428 ecr 23757428], length 0
14:22:07.516863 IP tardis.ipa.server-noc.com.41031 >
tardis.ipa.server-noc.com.ldap: Flags [P.], seq 2618:2690, ack 1739, win
304, options [nop,nop,TS val 23757457 ecr 23757428], length 72
14:22:07.516883 IP tardis.ipa.server-noc.com.ldap >
tardis.ipa.server-noc.com.41031: Flags [.], ack 2690, win 308, options
[nop,nop,TS val 23757457 ecr 23757457], length 0
14:22:07.517102 IP tardis.ipa.server-noc.com.41031 >
tardis.ipa.server-noc.com.ldap: Flags [P.], seq 2690:2761, ack 1739, win
304, options [nop,nop,TS val 23757457 ecr 23757457], length 71
14:22:07.517116 IP tardis.ipa.server-noc.com.ldap >
tardis.ipa.server-noc.com.41031: Flags [.], ack 2761, win 308, options
[nop,nop,TS val 23757457 ecr 23757457], length 0
14:22:07.517573 IP tardis.ipa.server-noc.com.41031 >
tardis.ipa.server-noc.com.ldap: Flags [F.], seq 2761, ack 1739, win 304,
options [nop,nop,TS val 23757457 ecr 23757457], length 0
14:22:07.556841 IP tardis.ipa.server-noc.com.ldap >
tardis.ipa.server-noc.com.41031: Flags [.], ack 2762, win 308, options
[nop,nop,TS val 23757497 ecr 23757457], length 0
14:22:13.497311 IP tardis.ipa.server-noc.com.ldap >
tardis.ipa.server-noc.com.41031: Flags [P.], seq 1739:1817, ack 2762,
win 308, options [nop,nop,TS val 23763437 ecr 23757457], length 78
14:22:13.497333 IP tardis.ipa.server-noc.com.41031 >
tardis.ipa.server-noc.com.ldap: Flags [R], seq 3387428517, win 0, length 0
14:22:13.526895 IP tardis.ipa.server-noc.com.ldap >
tardis.ipa.server-noc.com.41031: Flags [R.], seq 1817, ack 2762, win
308, options [nop,nop,TS val 23763467 ecr 23757457], length 0
which using the ol' wireshark relate to
bind request with a bind response traversing back and fro from ldap
server till a bind success from ldap server and the query/queries run ..
so to me it seems that there are times (and quite a few of them) where a
bind request gets no response back from the server ...
Has anyone seen this ...
rgds
Matt B.
-------- Original Message --------
Subject: Re: [Freeipa-users] Intermittent Issues changing passwords
since updating to ipa v3 and sasl_bind timeouts ..
Date: Tue, 26 Nov 2013 11:55:05 +1000
From: Matt Bryant <matthew.bryant at melbourneit.com.au>
To: freeipa-users at redhat.com
Well its definitely the bind to ldap via GSSAPI thats the issue ...
sssd_<domain>
(Tue Nov 26 11:34:08 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 11:34:14 2013) [sssd[be[ipa.server-noc.com]]]
[sasl_bind_send] (0x0020): ldap_sasl_bind failed (-5)[Timed out]
(Tue Nov 26 11:34:14 2013) [sssd[be[ipa.server-noc.com]]]
[sasl_bind_send] (0x0080): Extended failure message: [unknown error]
dirsrv-slapd
26/Nov/2013:11:34:07 +1000] conn=3555 op=1 BIND dn="" method=sasl
version=3 mech=GSSAPI
[26/Nov/2013:11:34:13 +1000] conn=3555 op=2 UNBIND
[26/Nov/2013:11:34:13 +1000] conn=3555 op=2 fd=97 closed - U1
ldp_child
(Tue Nov 26 11:34:07 2013) [[sssd[ldap_child[9689]]]]
[ldap_child_get_tgt_sync] (0x2000): credentials initialized
(Tue Nov 26 11:34:07 2013) [[sssd[ldap_child[9689]]]]
[sss_child_krb5_trace_cb] (0x4000): [9689] 1385429647.891977:
Initializing FILE:/var/lib/sss/db/ccache_SERVER-IPA with default princ
host/tardis.ipa.server-noc.com at SERVER-IPA
(Tue Nov 26 11:34:08 2013) [[sssd[ldap_child[9689]]]]
[sss_child_krb5_trace_cb] (0x4000): [9689] 1385429648.31633: Removing
host/tardis.ipa.server-noc.com at SERVER-IPA ->
krbtgt/SERVER-IPA at SERVER-IPA from FILE:/var/lib/sss/db/ccache_SERVER-IPA
(Tue Nov 26 11:34:08 2013) [[sssd[ldap_child[9689]]]]
[sss_child_krb5_trace_cb] (0x4000): [9689] 1385429648.31677: Storing
host/tardis.ipa.server-noc.com at SERVER-IPA ->
krbtgt/SERVER-IPA at SERVER-IPA in FILE:/var/lib/sss/db/ccache_SERVER-IPA
(Tue Nov 26 11:34:08 2013) [[sssd[ldap_child[9689]]]]
[ldap_child_get_tgt_sync] (0x2000): credentials stored
(Tue Nov 26 11:34:08 2013) [[sssd[ldap_child[9689]]]]
[ldap_child_get_tgt_sync] (0x2000): Got KDC time offset
(Tue Nov 26 11:34:08 2013) [[sssd[ldap_child[9689]]]] [prepare_response]
(0x0400): Building response for result [0]
(Tue Nov 26 11:34:08 2013) [[sssd[ldap_child[9689]]]] [pack_buffer]
(0x2000): response size: 58
(Tue Nov 26 11:34:08 2013) [[sssd[ldap_child[9689]]]] [pack_buffer]
(0x1000): result [0] krberr [0] msgsize [38] msg
[FILE:/var/lib/sss/db/ccache_SERVER-IPA]
(Tue Nov 26 11:34:08 2013) [[sssd[ldap_child[9689]]]] [main] (0x0400):
ldap_child completed successfully
Have even updated config to increase timeout to 10s
ldap_network_timeout = 10
ldap_opt_timeout = 10
but even thats timing out .. given the server IS the ipa server that
runs the ldap and KDC no way it should be taking so long ...
(Tue Nov 26 11:45:36 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 11:45:46 2013) [sssd[be[ipa.server-noc.com]]]
[sasl_bind_send] (0x0020): ldap_sasl_bind failed (-5)[Timed out]
(Tue Nov 26 11:45:46 2013) [sssd[be[ipa.server-noc.com]]]
[sasl_bind_send] (0x0080): Extended failure message: [unknown error]
kdclog
Nov 03 11:45:28 tardis.ipa.server-noc.com krb5kdc[6411](info): AS_REQ (4
etypes {18 17 16 23}) 203.147.190.30: NEEDED_PREAUTH:
host/tardis.ipa.server-noc.com at SERVER-IPA for
krbtgt/SERVER-IPA at SERVER-IPA, Additional pre-authentication required
Nov 03 11:45:28 tardis.ipa.server-noc.com krb5kdc[6410](info): AS_REQ (4
etypes {18 17 16 23}) 203.147.190.30: ISSUE: authtime 1383443128, etypes
{rep=18 tkt=18 ses=18}, host/tardis.ipa.server-noc.com at SERVER-IPA for
krbtgt/SERVER-IPA at SERVER-IPA
Nov 03 11:45:28 tardis.ipa.server-noc.com krb5kdc[6411](info): TGS_REQ
(4 etypes {18 17 16 23}) 203.147.190.30: ISSUE: authtime 1383443128,
etypes {rep=18 tkt=18 ses=18}, host/tardis.ipa.server-noc.com at SERVER-IPA
for ldap/tardis.ipa.server-noc.com at SERVER-IPA
So now how to figure out WHY its taking so long to bind to ldap via
GSSAPI ... any pointers ??
rgds
Matt B.
-------- Original Message --------
Subject: Re: [Freeipa-users] Intermittent Issues changing passwords
since updating to ipa v3 and sasl_bind timeouts ..
Date: Tue, 26 Nov 2013 09:47:10 +1000
From: Matt Bryant <matthew.bryant at melbourneit.com.au>
To: <freeipa-users at redhat.com>
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
_______________________________________________
Freeipa-users mailing list
Freeipa-users at redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-users
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20131126/47fd2699/attachment.htm>
More information about the Freeipa-users
mailing list