[Freeipa-users] Intermittent Issues changing passwords since updating to ipa v3 and sasl_bind timeouts ..

Sumit Bose sbose at redhat.com
Tue Nov 26 08:41:28 UTC 2013 

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.
>

More information about the Freeipa-users mailing list