Bug 518084

How often does this happen?  Does the LDAP server need to be under any load?

I have been unable to reproduce this problem with current IPAv2 code on F12 using the 389-ds-base 1.2.3.

Are you doing operations that in turn generate internal ADD or MOD operations?

I am doing an "ipa user-add", which is what Endi was doing as well I believe.  This results in 3 operations that are logged to the retro changelog in teh following order:

  1 - ADD of the user entry.
  2 - MOD of the user entry to add memberOf attribute (internal operation).
  3 - MOD of ipa-users group to add the new user to the group.

> I am doing an "ipa user-add", which is what Endi was doing as well I believe. 
> This results in 3 operations that are logged to the retro changelog in teh
> following order:
> 
>   1 - ADD of the user entry.
>   2 - MOD of the user entry to add memberOf attribute (internal operation).
>   3 - MOD of ipa-users group to add the new user to the group.  

Thinking about this some more, operation #3 (the add of the user to the group) is the operation that triggered operation #2 (the internal operation to add memberOf to the user entry).(In reply to comment #3).  This is the actual order that the operations occur in the server.  It is not the same issue as the original report, since the operations could not actually occur in that order (modifying an entry before it exists makes no sense).

Here is the result with IPA 1.9.0 and DS 1.2.5 RC2:

% ipa user-add
first: Endi
last: Dewata
user [edewata]:

It will generate the same change logs as in comment #3. However if password is provided, the result will be different:

% ipa user-add --password
first: Endi
last: Dewata
user [edewata]:
password: secret
Enter password again to verify: secret

It will generate the same change logs as in comment #1.

So specifying the password during user creation apparently generates different sets of operations and they are executed in different order.

I think this should be fixable by ordering the plug-ins such that the retro changelog plug-in is the first post-op plug-in to execute.  I will run some tests with this change.  This approach would not catch any internal operations that are triggered at the pre-op stage, as those operations would indeed happen before the operation that initiated the internal operation.  I think this is fine though.

Created attachment 378624 [details]
Patch

When using the retro changelog plugin, post-op plugins that perform internal operations (such as memberOf) can result in the internal operation preceeding the original operation in the changelog.
    
The fix is to give the retro changelog a higher precedence than the other post-op plugins.  This required some core server changes to be made around the plugin precedence to allow an object plugin to pass it's precedence into it's calls to slapi_register_plugin() when it registers other plugin types.
    
I added an update LDIF to set the plugin precedence when running "setup-ds.pl -u".  I also noticed an AVC when restarting after the update due to the schema.bak directory that is created.  I've adjusted the dirsrv SELinux policy to deal with this AVC.

Created attachment 378629 [details]
Revised Patch

This revised patch addresses an issue caught by Noriko with my previous patch.  I was casting the precedence to the wrong type in slapi_pblock_set().  I had missed this in testing since I don't actuall call slapi_pblock_set() to set the precedence in the server code, but wanted to supply that capability to plugins.

Pushed patch from comment #8 (after running autogen.sh) to master.  Thanks for the reviews!

Counting objects: 40, done.
Delta compression using 2 threads.
Compressing objects: 100% (20/20), done.
Writing objects: 100% (21/21), 2.50 KiB, done.
Total 21 (delta 17), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
   24e6ca2..cf0fcc5  master -> master

verified - RHEL 4

version:
redhat-ds-base-8.2.0-2010051204.el4dsrv

changes are showing up in the correct order in the changelog:
dbid: 4bec9c99000000010000
        replgen: 1273797785 Thu May 13 20:43:05 2010
        csn: 4bec9c99000000010000
        uniqueid: 9a1b1682-1dd111b2-8dc0d8c2-02340000
        parentuniqueid: 75bf3a27-1dd211b2-b05382e1-696e0000
        dn: uid=jgalipea,ou=People,dc=example,dc=com
        operation: add
                objectClass: top
                objectClass: person
                objectClass: organizationalPerson
                objectClass: inetorgperson
                objectClass: inetuser
                objectClass: groupofnames
                uid: JGalipea
                givenName: Jenny
                sn: Galipeau
                cn: Jenny Galipeau
                memberOf: uid=TUser,ou=People,dc=example,dc=com
                creatorsName: cn=directory manager
                modifiersName: cn=directory manager
                createTimestamp: 20100514004305Z
                modifyTimestamp: 20100514004305Z
                nsUniqueId: 9a1b1682-1dd111b2-8dc0d8c2-02340000

dbid: 4bec9c99000200010000
        replgen: 1273797785 Thu May 13 20:43:05 2010
        csn: 4bec9c99000200010000
        uniqueid: 9a1b1682-1dd111b2-8dc0d8c2-02340000
        dn: uid=jgalipea,ou=people,dc=example,dc=com
        operation: modify
                memberOf: cn=Test,ou=groups,dc=example,dc=com
                modifiersname: cn=directory manager
                modifytimestamp: 20100514004305Z

dbid: 4bec9c99000300010000
        replgen: 1273797785 Thu May 13 20:43:05 2010
        csn: 4bec9c99000300010000
        uniqueid: 9a1b1681-1dd111b2-8dc0d8c2-02340000
        dn: cn=test,ou=groups,dc=example,dc=com
        operation: modify
                member: uid=jgalipea,ou=People,dc=example,dc=com
                modifiersname: cn=directory manager
                modifytimestamp: 20100514004305Z

-

time: 20100513184732
dn: cn=test,ou=groups,dc=example,dc=com
changetype: modify
add: member
member: uid=jgalipea,ou=People,dc=example,dc=com
-
replace: modifiersname
modifiersname: cn=directory manager
-
replace: modifytimestamp
modifytimestamp: 20100513224732Z