[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 22:14:04 UTC 2013
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 at SERVER-IPA
SASL SSF: 56
ldap_pvt_sasl_generic_install
SASL data security layer installed.
ldap_search_ext
put_filter: "uid=admin"
put_filter: default
put_simple_filter: "uid=admin"
ldap_send_initial_request
ldap_send_server_request
ber_scanf fmt ({it) ber:
ber_scanf fmt ({) ber:
ber_flush2: 53 bytes to sd 3
ldap_result ld 0xdbf4a0 msgid -1
wait4msg ld 0xdbf4a0 msgid -1 (infinite timeout)
wait4msg continue ld 0xdbf4a0 msgid -1 all 0
** 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 4, origid 4, 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 0
ldap_chkResponseList returns ld 0xdbf4a0 NULL
ldap_int_select
read1msg: ld 0xdbf4a0 msgid -1 all 0
ber_get_next
ber_get_next: tag 0x30 len 268 contents:
read1msg: ld 0xdbf4a0 msgid 4 message type search-entry
ldap_get_dn_ber
ber_scanf fmt ({ml{) ber:
ldap_dn2ufn
ldap_dn_normalize
ber_scanf fmt ({xx) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ldap_msgfree
ldap_result ld 0xdbf4a0 msgid -1
wait4msg ld 0xdbf4a0 msgid -1 (infinite timeout)
wait4msg continue ld 0xdbf4a0 msgid -1 all 0
** 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 4, origid 4, 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 0
ldap_chkResponseList returns ld 0xdbf4a0 NULL
ldap_int_select
read1msg: ld 0xdbf4a0 msgid -1 all 0
ber_get_next
ber_get_next: tag 0x30 len 1518 contents:
read1msg: ld 0xdbf4a0 msgid 4 message type search-entry
ldap_get_dn_ber
ber_scanf fmt ({ml{) ber:
ldap_dn2ufn
ldap_dn_normalize
ber_scanf fmt ({xx) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ber_scanf fmt ({mM}) ber:
ldap_get_attribute_ber
ldap_msgfree
ldap_result ld 0xdbf4a0 msgid -1
wait4msg ld 0xdbf4a0 msgid -1 (infinite timeout)
wait4msg continue ld 0xdbf4a0 msgid -1 all 0
** 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 4, origid 4, 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 0
ldap_chkResponseList returns ld 0xdbf4a0 NULL
ldap_int_select
read1msg: ld 0xdbf4a0 msgid -1 all 0
ber_get_next
ber_get_next: tag 0x30 len 12 contents:
read1msg: ld 0xdbf4a0 msgid 4 message type search-result
ber_scanf fmt ({eAA) ber:
read1msg: ld 0xdbf4a0 0 new referrals
read1msg: mark request completed, ld 0xdbf4a0 msgid 4
request done: ld 0xdbf4a0 msgid 4
res_errno: 0, res_error: <>, res_matched: <>
ldap_free_request (origid 4, msgid 4)
ldap_parse_result
ber_scanf fmt ({iAA) ber:
ber_scanf fmt (}) ber:
ldap_err2string
ldap_msgfree
ldap_free_connection 1 1
ldap_send_unbind
ber_flush2: 7 bytes to sd 3
ldap_free_connection: actually freed
# extended LDIF
#
# LDAPv3
# base <dc=server-ipa> with scope subtree
# filter: uid=admin
# requesting: ALL
#
# admin, users, compat, server-ipa
dn: uid=admin,cn=users,cn=compat,dc=server-ipa
objectClass: posixAccount
objectClass: top
gecos: Administrator
cn: Administrator
uidNumber: xxxxxxxx
gidNumber: xxxxxxxx
loginShell: /bin/bash
homeDirectory: /home/admin
uid: admin
# admin, users, accounts, server-ipa
dn: uid=admin,cn=users,cn=accounts,dc=server-ipa
krbLastSuccessfulAuth: 20131124214435Z
krbLoginFailedCount: 0
krbLastFailedAuth: 20131014050743Z
memberOf: cn=admins,cn=groups,cn=accounts,dc=server-ipa
memberOf: cn=replication administrators,cn=privileges,cn=pbac,dc=server-ipa
memberOf: cn=add replication agreements,cn=permissions,cn=pbac,dc=server-ipa
memberOf: cn=modify replication
agreements,cn=permissions,cn=pbac,dc=server-ip
a
memberOf: cn=remove replication
agreements,cn=permissions,cn=pbac,dc=server-ip
a
memberOf: cn=host enrollment,cn=privileges,cn=pbac,dc=server-ipa
memberOf: cn=manage host keytab,cn=permissions,cn=pbac,dc=server-ipa
memberOf: cn=enroll a host,cn=permissions,cn=pbac,dc=server-ipa
memberOf: cn=add krbprincipalname to a
host,cn=permissions,cn=pbac,dc=server-i
pa
memberOf: cn=unlock user accounts,cn=permissions,cn=pbac,dc=server-ipa
memberOf: cn=manage service keytab,cn=permissions,cn=pbac,dc=server-ipa
memberOf: cn=trust admins,cn=groups,cn=accounts,dc=server-ipa
krbPasswordExpiration: 20140108225426Z
krbExtraData:: xxxxxxxxxx
krbTicketFlags: 128
krbLastPwdChange: 20131010225426Z
objectClass: top
objectClass: person
objectClass: posixaccount
objectClass: krbprincipalaux
objectClass: krbticketpolicyaux
objectClass: inetuser
objectClass: ipaobject
objectClass: ipasshuser
objectClass: ipaSshGroupOfPubKeys
uid: admin
krbPrincipalName: admin at SERVER-IPA
cn: Administrator
sn: Administrator
uidNumber: xxxxxxxx
gidNumber: xxxxxxxx
homeDirectory: /home/admin
loginShell: /bin/bash
gecos: Administrator
ipaUniqueID: xxxxxxxxxxxxxxx
# search result
search: 4
result: 0 Success
# numResponses: 3
# numEntries: 2
End: .Wed Nov 27 07:55:08 EST 2013
the whole thing still takes < 6secs but most are coming back within the
same second .. and the point it seems to slow down around is the initial
ldap_int_select ...
ldap_int_select
read1msg: ld 0xdbf4a0 msgid 1 all 1
ber_get_next
rgds
Matt B.
On 11/26/2013 06:41 PM, Sumit Bose wrote:
> 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 [.], 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 ...
> no, I have not seen this. Some general comments about the SSSD log
> files. The ldap_child only handles the part of getting a Kerberos
> ticket. The complete bind happens inside the OpenLDAP ldap_sasl_bind()
> call where we currently do not get any debug output from.
>
> Can you try if you see the same delay with the ldapsearch command line
> utility? You can use the same credentials as SSSD if you call e.g:
>
> KRB5CCNAME=FILE:/var/lib/sss/db/ccache_YOUR.DOMAIN ldapsearch -Y GSSAPI \
> -H ldap://your.ipa.server -b 'dc=ipa,dc=domain' uid=admin
>
> If it can be reproduced with ldapsearch you can use the option '-d -1'
> to get full debug output.
>
> I wonder if your server is a busy on handling lots of encrypted
> connections? In this case, depending on how the session keys for those
> connections are generated, the entropy pool might be too small to
> generate a sufficient amount of random data for the keys which would
> lead to a timeout in the application until enough entropy is gathered.
> But I have to admit that I do not know which source of random data 389ds
> is using.
>
> bye,
> Sumit
>
>> rgds
>>
>> Matt B.
>>
> _______________________________________________
> 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