Bug 518084 - Out of order retro change log records
Summary: Out of order retro change log records
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Directory Server
Classification: Red Hat
Component: Server - Plugins
Version: 8.1
Hardware: All
OS: All
high
high
Target Milestone: ---
: ---
Assignee: Nathan Kinder
QA Contact: Viktor Ashirov
URL:
Whiteboard:
Depends On:
Blocks: 434914 389_1.2.6
TreeView+ depends on / blocked
 
Reported: 2009-08-18 20:13 UTC by Endi Sukma Dewata
Modified: 2016-05-06 14:29 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-05-06 14:29:18 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
Patch (7.87 KB, patch)
2009-12-15 20:32 UTC, Nathan Kinder
rmeggins: review+
Details | Diff
Revised Patch (7.87 KB, patch)
2009-12-15 20:58 UTC, Nathan Kinder
nhosoi: review+
Details | Diff

Description Endi Sukma Dewata 2009-08-18 20:13:01 UTC
Adding a new user in IPA 2.0 with DS 8.1 generates several retro change log records which are not in the correct order. This problem is blocking applications which rely on the ability to play back the retro change log records correctly such as the IPA-Samba synchronization tool.

IPA 1.2 with DS 8.1 doesn't have this problem. However, the problem may lie on how DS generates the change log records, not necessarily IPA's problem.

Steps to reproduce:
1. Install IPA 2.0 with DS 8.1.
2. Enable retro change log, restart DS.
3. Use IPA CLI to add a new user.
4. Inspect change log records in DS.
  
These are the change log records generated by DS:

1. Modify the memberOf attribute of the new user.
2. Modify the member attribute of the ipausers group.
3. Modify the krbLastPwdChange and krbPasswordExpiration of the new user.
4. Add the new user.

The correct behavior is: record #4 should be the first, the others can be in any order.

Comment 1 Nathan Kinder 2009-12-14 20:49:33 UTC
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.

Comment 2 Rich Megginson 2009-12-14 20:52:15 UTC
Are you doing operations that in turn generate internal ADD or MOD operations?

Comment 3 Nathan Kinder 2009-12-14 21:16:12 UTC
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.

Comment 4 Nathan Kinder 2009-12-14 21:41:41 UTC
> 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).

Comment 5 Endi Sukma Dewata 2009-12-14 22:35:42 UTC
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.

Comment 6 Nathan Kinder 2009-12-14 22:54:13 UTC
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.

Comment 7 Nathan Kinder 2009-12-15 20:32:38 UTC
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.

Comment 8 Nathan Kinder 2009-12-15 20:58:36 UTC
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.

Comment 9 Nathan Kinder 2009-12-15 22:19:34 UTC
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

Comment 10 Jenny Severance 2010-05-13 19:30:57 UTC
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


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