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.
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@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@redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-users

_______________________________________________
Freeipa-users mailing list
Freeipa-users@redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-users

Reply via email to