Bug 696407

Created attachment 491934 [details]
git patch file (master)

Description: When an entry is turned to be a tombstone, the RDN
part is replaced with this unusual format:
    "nsuniqueid=9a63a581-...-ca8fe9f7,uid=tuser1"
A helper function slapi_rdn_replace_rdn was introduced to support
the replace task, in which function, normalized rdn field "nrdn"
was supposed to have lowered case RDN, but it was not.
This patch fixes it.

Reviewed by Rich (Thank you!!!)

[master]
Pushed to master.
$ git merge tombstone
Updating 8d59cb8..df54e31
Fast-forward
 ldap/servers/slapd/rdn.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

$ git push
Counting objects: 11, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (6/6), done.
Writing objects: 100% (6/6), 846 bytes, done.
Total 6 (delta 4), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
   8d59cb8..df54e31  master -> master

[389-ds-base-1.2.8 branch]
Cherry picked commit df54e31e9010911efbbc3032be0f43c4cd367d7f and pushed to 389-ds-base-1.2.8.
$ git cherry-pick df54e31e9010911efbbc3032be0f43c4cd367d7f
[ds128-local 4f5a894] Bug 696407 - If an entry with a mixed case RDN is turned to be a tombstone, it fails to assemble DN from entryrdn
 1 files changed, 1 insertions(+), 1 deletions(-)

$ git push origin ds128-local:389-ds-base-1.2.8
Counting objects: 11, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (6/6), done.
Writing objects: 100% (6/6), 848 bytes, done.
Total 6 (delta 4), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
   a82b8f0..4f5a894  ds128-local -> 389-ds-base-1.2.8

[RHEL-6 branch]
$ git cherry-pick df54e31e9010911efbbc3032be0f43c4cd367d7f
[RHEL-6 92f9183] Bug 696407 - If an entry with a mixed case RDN is turned to be a tombstone, it fails to assemble DN from entryrdn
 1 files changed, 1 insertions(+), 1 deletions(-)

$ git push redhat RHEL-6:RHEL-6
Counting objects: 11, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (6/6), done.
Writing objects: 100% (6/6), 852 bytes, done.
Total 6 (delta 4), reused 0 (delta 0)
To ssh://git.engineering.redhat.com/srv/git/users/rmeggins/ds.git
   13124d5..92f9183  RHEL-6 -> RHEL-6

ldapsearch -x -h localhost -p 389 -D "cn=Directory Manager" -w Secret123 -b "ou=people,dc=testnew,dc=com" "(&(uid=*) (objectclass=nsTombstone))"
# 5e530c02-8c2e11e0-83f6b85c-b3c05de4, hhmmm, people, testnew.com
dn: nsuniqueid=5e530c02-8c2e11e0-83f6b85c-b3c05de4,uid=hhmmm,ou=people,dc=test
 new,dc=com
uid: hhmmm
givenName: hmm
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: inetorgperson
objectClass: nsTombstone
sn: hmmm
cn: hmm hmmm
nsParentUniqueId: 93aa2aa8-8c2b11e0-83f6b85c-b3c05de4

[root@testvm ~]# tail -f /var/log/dirsrv/slapd-testvm/errors
[08/Jun/2011:12:55:35 +051800] - import userTami: Import complete.  Processed 3 entries (3 were skipped) in 3 seconds. (1.00 entries/sec)
[08/Jun/2011:12:56:01 +051800] - 389-Directory/1.2.8.3 B2011.123.1759 starting up
[08/Jun/2011:12:56:01 +051800] - I'm resizing my cache now...cache was 408346624 and is now 8000000
[08/Jun/2011:12:56:02 +051800] NSMMReplicationPlugin - changelog program - _cl5AppInit: fetched backend dbEnv (1e0ba70)
[08/Jun/2011:12:56:02 +051800] NSMMReplicationPlugin - changelog program - _cl5DBOpen: opened 0 existing databases in /var/lib/dirsrv/slapd-testvm/changelogdb
[08/Jun/2011:12:56:02 +051800] NSMMReplicationPlugin - agmtlist_config_init: found 0 replication agreements in DIT
[08/Jun/2011:12:56:02 +051800] - slapd started.  Listening on All Interfaces port 389 for LDAP requests
[08/Jun/2011:12:56:02 +051800] - Listening on All Interfaces port 636 for LDAPS requests
[08/Jun/2011:16:42:55 +051800] - _csngen_adjust_local_time: gen state before 4def24090000:1307517961:0:0
[08/Jun/2011:16:42:55 +051800] - _csngen_adjust_local_time: gen state after 4def59370000:1307531575:0:0

Using 389-ds-base-1.2.9.9-1.fc15.x86_64

I see the following when backing up the db:
[05/Sep/2011:03:30:11 -0500] ldif2dbm - _get_and_add_parent_rdns: Failed to position at ID 29
[05/Sep/2011:03:30:11 -0500] - ldbm2ldif: Failed to get dn of ID 29
[05/Sep/2011:03:30:11 -0500] - export userRoot: Processed 359 entries (100%).
[05/Sep/2011:03:30:11 -0500] - All database threads now stopped
[05/Sep/2011:03:30:11 -0500] - export NetscapeRoot: Processed 109 entries (100%).
[05/Sep/2011:03:30:11 -0500] - All database threads now stopped
        389-Directory/1.2.9.9 B2011.244.2041


And the following later on:
[05/Sep/2011:14:11:59 -0500] _entry_set_tombstone_rdn - Failed to convert DN uid=aae5b81917538f54cabd7e7d290db106 to RDN
[05/Sep/2011:14:11:59 -0500] id2entry - str2entry returned NULL for id 30, string="rdn"
[05/Sep/2011:22:13:08 -0500] _entry_set_tombstone_rdn - Failed to convert DN uid=aae5b81917538f54cabd7e7d290db106 to RDN
[05/Sep/2011:22:13:08 -0500] id2entry - str2entry returned NULL for id 30, string="rdn"
[05/Sep/2011:22:13:45 -0500] _entry_set_tombstone_rdn - Failed to convert DN uid=aae5b81917538f54cabd7e7d290db106 to RDN
[05/Sep/2011:22:13:45 -0500] id2entry - str2entry returned NULL for id 30, string="rdn"

(In reply to comment #4)
> Using 389-ds-base-1.2.9.9-1.fc15.x86_64
> 
> I see the following when backing up the db:
> [05/Sep/2011:03:30:11 -0500] ldif2dbm - _get_and_add_parent_rdns: Failed to
> position at ID 29
> [05/Sep/2011:03:30:11 -0500] - ldbm2ldif: Failed to get dn of ID 29
> [05/Sep/2011:03:30:11 -0500] - export userRoot: Processed 359 entries (100%).
> [05/Sep/2011:03:30:11 -0500] - All database threads now stopped
> [05/Sep/2011:03:30:11 -0500] - export NetscapeRoot: Processed 109 entries
> (100%).
> [05/Sep/2011:03:30:11 -0500] - All database threads now stopped
>         389-Directory/1.2.9.9 B2011.244.2041
> 
> 
> And the following later on:
> [05/Sep/2011:14:11:59 -0500] _entry_set_tombstone_rdn - Failed to convert DN
> uid=aae5b81917538f54cabd7e7d290db106 to RDN
> [05/Sep/2011:14:11:59 -0500] id2entry - str2entry returned NULL for id 30,
> string="rdn"
> [05/Sep/2011:22:13:08 -0500] _entry_set_tombstone_rdn - Failed to convert DN
> uid=aae5b81917538f54cabd7e7d290db106 to RDN
> [05/Sep/2011:22:13:08 -0500] id2entry - str2entry returned NULL for id 30,
> string="rdn"
> [05/Sep/2011:22:13:45 -0500] _entry_set_tombstone_rdn - Failed to convert DN
> uid=aae5b81917538f54cabd7e7d290db106 to RDN
> [05/Sep/2011:22:13:45 -0500] id2entry - str2entry returned NULL for id 30,
> string="rdn"

Hi Anthony,
Could it be possible to post the output from these command lines?
dbscan -f /path/to/db/userRoot/id2entry.db4 -K 29
dbscan -f /path/to/db/userRoot/id2entry.db4 -K 30
Thanks,
--noriko

Sure, they both come from entries that were deleted.  The first one is gone from the DB.  The second doesn't show up during an ldapsearch, but is avaiable via the command below:

# dbscan -f /var/lib/dirsrv/slapd-ds/db/userRoot/id2entry.db4 -K 29
Can't set cursor to returned item: DB_NOTFOUND: No matching key/data pair found


# dbscan -f /var/lib/dirsrv/slapd-ds/db/userRoot/id2entry.db4 -K 30
id 30
        rdn: nsuniqueid=de6aa638-282011df-a269e3fe-897a001a,uid=aae5b81917538f54cabd7e
         7d290db106
        nsUniqueId: de6aa638-282011df-a269e3fe-897a001a

<entry snipped>

Thanks, Anthony.  I tried to duplicate your problem, but so far no luck.

It looks you have some deleted entries which are turned to tombstone entries once (entry 29 and 30).  Then, some of them are reaped (entry 29).  I wonder if entry 29 could have been a parent of entry 30?  (I don't think a parent can be deleted prior to its child, so I'm not sure how it could happen if it is the case...)  But this could be just my imagination.  I guess we need more detailed data to investigate the problem.

Do you happen to have steps to reproduce the problem?

(In reply to comment #7)
> Thanks, Anthony.  I tried to duplicate your problem, but so far no luck.
> 
> It looks you have some deleted entries which are turned to tombstone entries
> once (entry 29 and 30).  Then, some of them are reaped (entry 29).  I wonder if
> entry 29 could have been a parent of entry 30?  (I don't think a parent can be
> deleted prior to its child, so I'm not sure how it could happen if it is the
> case...)  But this could be just my imagination.  I guess we need more detailed
> data to investigate the problem.
> 
> Do you happen to have steps to reproduce the problem?

I believe you are right when you say that 29 was a parent of 30.  In fact, the 30 entry I have was deleted at the same time as its parent (29) via the 389-console.

It would have had the following structure:
uid=aae5b81917538f54cabd7e7d290db106,cn=user1,ou=personal,ou=contacts,ou=messinet.com,ou=eGW,dc=messinet,dc=com

and cn=user1,ou=personal,ou=contacts,ou=messinet.com,ou=eGW,dc=messinet,dc=com was the entry I deleted via 389-console.

Thanks for the input, Anthony.  I've opened a new bug for this issue.  Let's use this bug for the further discussion.
Bug 736431 - parent tombstone entry could be reaped even if its child tombstone entries still exist