Bug 755119 - 389 DS DNA Plugin / Replication failing on GSSAPI
Summary: 389 DS DNA Plugin / Replication failing on GSSAPI
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: 389
Classification: Retired
Component: Replication - General
Version: 1.2.10
Hardware: All
OS: Linux
unspecified
urgent
Target Milestone: ---
Assignee: Rich Megginson
QA Contact: Chandrasekar Kannan
URL:
Whiteboard:
Depends On:
Blocks: 389_1.2.10
TreeView+ depends on / blocked
 
Reported: 2011-11-18 21:59 UTC by Jr Aquino
Modified: 2015-01-04 23:51 UTC (History)
2 users (show)

Fixed In Version: 389-ds-base-1.2.10.a7
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2012-02-07 16:14:49 UTC


Attachments (Terms of Use)
Replica Server's 389 DS Error log (213.12 KB, text/plain)
2011-11-18 22:01 UTC, Jr Aquino
no flags Details

Description Jr Aquino 2011-11-18 21:59:32 UTC
Description of problem:
There appears to be a race failing when the DNA Plugin attempts to make a uid range replication request backed by gssapi.

Version-Release number of selected component (if applicable):
389-ds-base-libs-1.2.10-0.5.a5.fc15.x86_64
389-ds-base-1.2.10-0.5.a5.fc15.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Install IPA Server (ipa-server-install)
2. Prepare Replica (ipa-replica-prepare replica-hostname)
3. Transfer resulting replica-hostname.gpg
4. Install Replica (ipa-replica-install replica-hostname.gpg)
5. kinit admin
6. Attempt to create new user (ipa user-add test)

Actual results:
ipa: ERROR: Operations error: Allocation of a new value for range cn=posix ids,cn=distributed numeric assignment plugin,cn=plugins,cn=config failed! Unable to proceed.

Expected results:
Expected new user to be added and range to be transferred.

Additional info:

Comment 1 Jr Aquino 2011-11-18 22:01:07 UTC
Created attachment 534505 [details]
Replica Server's 389 DS Error log

Comment 2 Rich Megginson 2011-11-18 22:03:52 UTC
Looks like there is some problem with two threads attempting to do krb auth to the same server at the same time using the same credentials
the first thread comes in - it creates a new memory cache
then the other thread hits the krb code and sees an existing mem cache
then the first thread comes back and has the bind error
Looks like the first thread is attempting to use the kerberos credentials from the cache while the other thread is accessing those same credentials and that bubbles up to the ldap_sasl_bind layer as error -1
perhaps the big krb5_lock is not big enough
may have to expand the scope of the mutex to include the entire slapd_ldap_sasl_interactive_bind() function

Comment 3 Simo Sorce 2011-11-22 18:04:34 UTC
2 threads should be able to use the same credential cache even at the same time.
The only thing is that they should use separate kerberos contexts.
Do we know if the krb context is shared by chance ?

Comment 4 Rich Megginson 2011-11-23 03:49:18 UTC
(In reply to comment #3)
> 2 threads should be able to use the same credential cache even at the same
> time.
> The only thing is that they should use separate kerberos contexts.
> Do we know if the krb context is shared by chance ?

Yes, it is shared.  We create a memory cache (a kerberos MEMORY: cache, managed by the kerberos code, not our code) of the credentials so we don't have to do a kinit every time we connect.  We already knew there were some thread safety issues with this, therefore we added a lock around the function that deals with the memory cache.  However, it looks as though we need to make the lock include the entire call to slapi_ldap_interactive_bind() because that code may use the kerberos credentials in the multiple bind stages, outside of our code that gets/sets the kerberos credentials.

Either that, or just not attempt to cache the credentials at all.

Comment 5 Simo Sorce 2011-11-23 14:51:07 UTC
(In reply to comment #4)
> (In reply to comment #3)
> > 2 threads should be able to use the same credential cache even at the same
> > time.
> > The only thing is that they should use separate kerberos contexts.
> > Do we know if the krb context is shared by chance ?
> 
> Yes, it is shared.  We create a memory cache (a kerberos MEMORY: cache, managed
> by the kerberos code, not our code) of the credentials so we don't have to do a
> kinit every time we connect.  We already knew there were some thread safety
> issues with this, therefore we added a lock around the function that deals with
> the memory cache.  However, it looks as though we need to make the lock include
> the entire call to slapi_ldap_interactive_bind() because that code may use the
> kerberos credentials in the multiple bind stages, outside of our code that
> gets/sets the kerberos credentials.
> 
> Either that, or just not attempt to cache the credentials at all.

Rich, a kerberos context and a emmory cache are 2 separate things. You can share memory caches w/o any issue (in theory) because libkrb5 does it's own locking to access credential caches. But it cannot properly work if you share the kerberos context between multiple threads.

Locking around slapi_ldap_interactive_bind() may be a major performance impact. And shouldn't be necessary as internally ldap->sasl->gssapi should create their own krb context not shared between multiple invocations.

I think this maybe an actual krb5 bug if you are not using a share krb5_context, perhaps should be reassigned to krb5 for more investigation ?

Any chance we can get a simple reproducer with multiple binds being performed in parallel to see if it triggers any bug in there ?

Comment 6 Jr Aquino 2011-11-23 18:57:59 UTC
While the logs still indicate the same failures, the cli problem itself
seems to manifest when _delay_ is present.  Locally the errors generate, but
the new user creation succeeds.  When attempting to replicate from
california to las vegas, or any other external location, the cli problem
occurs in conjunction with the errors.  This along with Rich's findings on
kerberos race might explain why this problem has been difficult to
reproduce.

Comment 7 Rich Megginson 2011-11-28 15:17:28 UTC
(In reply to comment #5)
> (In reply to comment #4)
> > (In reply to comment #3)
> > > 2 threads should be able to use the same credential cache even at the same
> > > time.
> > > The only thing is that they should use separate kerberos contexts.
> > > Do we know if the krb context is shared by chance ?
> > 
> > Yes, it is shared.  We create a memory cache (a kerberos MEMORY: cache, managed
> > by the kerberos code, not our code) of the credentials so we don't have to do a
> > kinit every time we connect.  We already knew there were some thread safety
> > issues with this, therefore we added a lock around the function that deals with
> > the memory cache.  However, it looks as though we need to make the lock include
> > the entire call to slapi_ldap_interactive_bind() because that code may use the
> > kerberos credentials in the multiple bind stages, outside of our code that
> > gets/sets the kerberos credentials.
> > 
> > Either that, or just not attempt to cache the credentials at all.
> 
> Rich, a kerberos context and a emmory cache are 2 separate things. You can
> share memory caches w/o any issue (in theory) because libkrb5 does it's own
> locking to access credential caches. But it cannot properly work if you share
> the kerberos context between multiple threads.

The kerberos context is not explicitly shared in the 389 code.  However, looking at the krb 1.6 code, the memory cache was just a simple linked list which was accessed without locking.  I don't know if that has changed since 1.6.

> 
> Locking around slapi_ldap_interactive_bind() may be a major performance impact.

I don't think so, at least, it should not impact performance any more than the current mutex in set_krb5_creds().

> And shouldn't be necessary as internally ldap->sasl->gssapi should create their
> own krb context not shared between multiple invocations.

See above - has this changed since krb 1.6?

> 
> I think this maybe an actual krb5 bug if you are not using a share
> krb5_context, perhaps should be reassigned to krb5 for more investigation ?

It has always been an implicit assumption that the krb5 code is not very thread safe, so it is up to the application programmer to provide appropriate thread safety.

> 
> Any chance we can get a simple reproducer with multiple binds being performed
> in parallel to see if it triggers any bug in there ?

Any volunteers to write such a test program?

Comment 8 Rich Megginson 2011-12-16 17:06:57 UTC
Just tried a test on RHEL6.2 - 3 way MMR - using GSSAPI everywhere - no problems.  I have an F-16 VM so I'm going to try on that platform.  I'm also going to throw DNA into the mix with the 3-way MMR to see if it has something to do with DNA.

Comment 9 Rich Megginson 2011-12-16 22:17:31 UTC
Can't reproduce on F-16 either.
JR - when you got the problem - was this in a VM or a bare metal machine?
Any chance you could attempt to reproduce on F-16?
How large is your database?  Number of entries?

Comment 10 Jr Aquino 2011-12-16 23:07:09 UTC
This is bare metal Production Servers/

I was able to recreate the problems on F15 VM's with an empty database with only the stock entries that FreeIPA installs.

What versions of FreeIPA and 389-ds-base were you testing against?
My issue is with FreeIPA 2.1.3 & 389 1.2.10-0.5 and 1.2.10-0.4

I can try an F16 install from ISO, but I'm not sure what is different between 15 & 16 beside freeipa & 389-ds-base that would manifest this problem.

The /var/log/slapd-DOMAIN-COM/error log catches the error 100% of the time on fresh brand new installs.  Its only the functionality that varies... On local systems / VM's with low latency, the dirsrv errors are present, but the FreeIPA CLI does not produce the error, and the range DOES actually get transferred correctly... It is only the global production infrastructure that has an issue The 3 in question are in Santa Barbara, San Jose, and Las Vegas...

(For reference I just performed and ldapsearch on my production directory and it returned: numEntries: 7982)

Comment 11 Rich Megginson 2011-12-17 00:47:19 UTC
(In reply to comment #10)
> This is bare metal Production Servers/

> 
> I was able to recreate the problems on F15 VM's with an empty database with
> only the stock entries that FreeIPA installs.

Ok.  Good to know.
 
> What versions of FreeIPA and 389-ds-base were you testing against?
> My issue is with FreeIPA 2.1.3 & 389 1.2.10-0.5 and 1.2.10-0.4

I'm not testing with freeipa - trying to isolate the cause - much easier to set up a test environment with plain 389 - if I can't reproduce with plain 389 I will try with ipa

I'm using 389-ds-base-1.2.10.a6 (pre-release code) - I've tried setting up 3-way MMR with the IPA DNA settings - all using GSSAPI - I can see the range transfers working correctly

> I can try an F16 install from ISO, but I'm not sure what is different between
> 15 & 16 beside freeipa & 389-ds-base that would manifest this problem.

I was just wondering if you had seen the errors on a platform other than F-15 - I don't know if the issue is platform related - I will try with F-15 on a bare metal system
 
> The /var/log/slapd-DOMAIN-COM/error log catches the error 100% of the time on
> fresh brand new installs.

This happens every time?

> Its only the functionality that varies... On local
> systems / VM's with low latency, the dirsrv errors are present, but the FreeIPA
> CLI does not produce the error, and the range DOES actually get transferred
> correctly... It is only the global production infrastructure that has an issue
> The 3 in question are in Santa Barbara, San Jose, and Las Vegas...

So on local systems/VM's with low latency, what dirsrv errors are present?  Are you saying that on those systems, you can successfully add users?

When you attempt to add the users and get errors, are you adding the users to the master, or to the new replica?

> 
> (For reference I just performed and ldapsearch on my production directory and
> it returned: numEntries: 7982)

ok - but it sounds like you can reproduce with just the empty ipa database - so not related to database size

Comment 12 Rich Megginson 2011-12-19 22:22:22 UTC
ipa-server-install --idstart=3000 --idmax=50000 is what sets the dna values.

Comment 13 Martin Kosek 2012-01-04 13:13:01 UTC
Upstream ticket:
https://fedorahosted.org/389/ticket/12

Comment 14 Rich Megginson 2012-01-09 19:16:44 UTC
Still cannot reproduce
1) installed latest freeipa-server on F-15 and F-16 on VMs
2) ran on F-15
ipa-server-install -r TESTDOMAIN.COM -n testdomain.com -p password -a password --hostname=f15x8664.testdomain.com --idstart=3000 --idmax=50000 --selfsign --no-host-dns
3) ran on F-15
ipa-replica-prepare -p password f16x8664.testdomain.com
4) scp  replica-info-f16x8664.testdomain.com.gpg root@f16x8664.testdomain.com:/var/lib/ipa
5) on F-16 - applied Martin's patches for 2139 (otherwise ipa-replica-install is b0rken on F-16)
6) on F-16 - ipa-replica-install -ddd -p password -w password --no-host-dns /var/lib/ipa/replica-info-f16x8664.testdomain.com.gpg
7) on F-16 - kinit admin
8) on F-16 - ipa user-add test
First Name: Test
Last Name: User

user was added - no errors observed - I saw the DNA range request went successfully to F-15 from F-16

Maybe it's a timing thing?  Does it happen only when the servers are connected by a WAN, and not on a local network?

Comment 15 Rich Megginson 2012-01-09 22:27:35 UTC
Spoke with JR on IRC
1) ipa user-add fails when the servers are connected by a WAN - it works on a local network
2) you still get GSSAPI errors even though the ipa user-add succeeds on a LAN - which GSSAPI errors are those?

Comment 16 Rich Megginson 2012-01-10 18:00:17 UTC
marking as screened because it has been cloned upstream

Comment 17 Rich Megginson 2012-02-07 16:14:49 UTC
Fixed in version 1.2.10.a7


Note You need to log in before you can comment on or make changes to this bug.