On 10/04/2018 10:20 PM, Kreuzenstein, Luke (OIT) wrote:
Thank you very much Ludwig,

Disabling referential integrity would not be an attractive workaround in this implementation so I'm grateful for any assistance and happy to help all I can.
I understand and we should make it work.

As far as I see we have three potential issues here.
Issue 1) the modrdn operation fails with err=1 and the message indicates that it is the result of a failing plugin, and based on Alberto's findings it is the referential integrity plugin. But we do not know why it is failing. You grepped for modrdn in the errors log, is there more logging which could give a hint ? Otherwise we need to find a pattern which modrdns are failing and which are not, maybe also considering the context when they fail (eg you said some are failing after one day) so that we finally will be able to reproduce this reliably.

The modrdn operation and all the plugin operation triggered by it are processed inside one transaction and if something fails the operation/transaction is aborted and the state of the database should be and should be seen as before the transaction started, but looks like it is not the case, which leads to

Issue 2) after a failed modrdn ldapsearches can return incorrect results. I can somehow reproduce this by enforcing the failure in gdb and have opened this ticket to fix it: https://pagure.io/389-ds-base/issue/49967
The core problem of this issue that we have an entry cache which is not properly cleared after the transaction abort, the cache operations are not transacted. But this is a transient issue and after cache reload (eg triggered by a restart) everything is consistent again.

This seems not to be the case for
Issue 3) "
Restart does not resolve the residual incorrect uniqueMember values in groups."
I did not expect this and it would be great if you could provide some data to show the effect.

Thanks for your patience,
Ludwig

PS I will be on vacation next week, so I hope someone else will look into it as well
Responses are in-line below.

Ludwig Krispenz wrote on 10/4/2018 12:23 AM:
Hi Alberto, Luke,

thanks for reporting the issue and tracking it down to the referential integrity plugin.

I am investigating another issue where after a failing modrdn with err=1 there is an entry cache corruption, but was failing to reproduce locally.
In a quick try with the referential integrity plugin enabled and moving a user to another subtree everything worked for me.

So could you give me some more information.
- did  the failure occur consistently or randomly, did a restart help (ruling out entry cache issues)
The failure is random. Restart resolves some instances of dn-uid mismatch, but not every instance. There are some differences in the logged errors which might be related. Restart does not resolve the residual incorrect uniqueMember values in groups.
- did it fail for all modrdns or only specific users
Only some users, but I have been able to reproduce errors by creating test users and not trying to rename them until the following day or later. This led me to suspect a possible relationship to periodic scripted tasks (such as group membership management) but I have not been able to confirm any such relationship.
- could you provide the referential integrity configuration from the dse.ldif
dn: cn=referential integrity postoperation,cn=plugins,cn=config
objectClass: top
objectClass: nsSlapdPlugin
objectClass: extensibleObject
cn: referential integrity postoperation
nsslapd-pluginPath: libreferint-plugin
nsslapd-pluginInitfunc: referint_postop_init
nsslapd-pluginType: betxnpostoperation
nsslapd-pluginEnabled: on
nsslapd-pluginprecedence: 40
referint-update-delay: 0
referint-logfile: /var/log/dirsrv/slapd-dirmaster/referint
referint-logchanges: 0
referint-membership-attr: member
referint-membership-attr: uniquemember
referint-membership-attr: owner
referint-membership-attr: seeAlso
nsslapd-plugin-depends-on-type: database
nsslapd-pluginId: referint
nsslapd-pluginVersion: 1.3.7.5
nsslapd-pluginVendor: 389 Project
nsslapd-pluginDescription: referential integrity plugin
modifiersName: cn=directory manager
modifyTimestamp: 20180321162105Z


- and some information on the user group structure of the failing users/groups
Our DIT is fairly flat, as is evident from the DNs in the excerpts below. The specific group in this example is our largest at about 11000 members, but not all of the affected entries have been members of this group.

Audit log excerpts:

time: 20180925100009
dn: uid=lktestA,ou=People,o=state.ak.us
result: 0
changetype: add
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: inetOrgPerson
objectClass: soaOrgPerson
objectClass: inetLocalMailRecipient
stellentusertype: Internal
sn: lktestA
cn: lktestA
ou: Administration
l: Anchorage
uid: lktestA
creatorsName: uid=lk*****,ou=people,o=state.ak.us
modifiersName: uid=lk*****,ou=people,o=state.ak.us
createTimestamp: 20180925180009Z
modifyTimestamp: 20180925180009Z

...

time: 20180926070140
dn: cn=Statewide - Non Employees, ou=Groups, o=state.ak.us
result: 0
changetype: modify
add: uniqueMember
uniqueMember: uid=20180925mwmeienberg,ou=People,o=state.ak.us
uniqueMember: uid=dlnorthburg,ou=People,o=state.ak.us
uniqueMember: uid=dot.issd.cab,ou=People,o=state.ak.us
uniqueMember: uid=dot.issd.systems.eng,ou=People,o=state.ak.us
uniqueMember: uid=lktestA,ou=People,o=state.ak.us
uniqueMember: uid=lktestB,ou=People,o=state.ak.us
uniqueMember: uid=lktestCorup010,ou=People,o=state.ak.us
uniqueMember: uid=lktestcorup0200,ou=People,o=state.ak.us
uniqueMember: uid=lktestC,ou=People,o=state.ak.us
uniqueMember: uid=lktestD,ou=People,o=state.ak.us
uniqueMember: uid=lktestE,ou=People,o=state.ak.us
uniqueMember: uid=lktestF,ou=People,o=state.ak.us
uniqueMember: uid=lorussell,ou=People,o=state.ak.us
uniqueMember: uid=mplachinski,ou=People,o=state.ak.us
uniqueMember: uid=Rkitiona,ou=People,o=state.ak.us
uniqueMember: uid=ssaarsetharc,ou=People,o=state.ak.us
-
replace: modifiersname
modifiersname: uid=ak*****,ou=people,o=state.ak.us
-
replace: modifytimestamp
modifytimestamp: 20180926150140Z
-
  

Access log excerpt:

[27/Sep/2018:11:29:23.099860407 -0800] conn=175 fd=173 slot=173 connection from 10.*.*.2 to 10.*.*.3
[27/Sep/2018:11:29:23.100058246 -0800] conn=175 op=0 BIND dn="uid=lk*****,ou=People,o=state.ak.us" method=128 version=3
[27/Sep/2018:11:29:23.100419707 -0800] conn=175 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0000498496 dn="uid=lk*****,ou=people,o=state.ak.us"
[27/Sep/2018:11:29:23.100883691 -0800] conn=175 op=1 MODRDN dn="uid=lktestA,ou=People,o=state.ak.us" newrdn="uid=lktestA1" newsuperior="(null)"
[27/Sep/2018:11:29:32.010951183 -0800] conn=175 op=1 RESULT err=1 tag=109 nentries=0 etime=8.1089839667 csn=5bad2f93000000010000
[27/Sep/2018:11:29:32.011655447 -0800] conn=175 op=2 UNBIND
[27/Sep/2018:11:29:32.011669501 -0800] conn=175 op=2 fd=173 closed - U1


Error log excerpts:  (since starting production use on 9 September, converted from ds7)

> grep -i modrdn errors*
errors.20180907-002004:[10/Sep/2018:15:05:34.658791117 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180907-002004:[11/Sep/2018:11:28:21.168151469 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180907-002004:[12/Sep/2018:12:02:30.359474198 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180907-002004:[12/Sep/2018:12:38:32.159185135 -0800] - ERR - ldbm_back_modrdn - entryrdn_rename_subtree failed (-30988); dn: uid=bfishie00,ou=People,o=state.ak.us, newsrdn: (null), dn_newsuperiordn: (null)
errors.20180914-115839:[17/Sep/2018:08:02:08.997495533 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180914-115839:[17/Sep/2018:11:22:48.235465642 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180914-115839:[17/Sep/2018:11:58:34.809217081 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180914-115839:[19/Sep/2018:15:16:15.960581907 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[24/Sep/2018:08:01:42.846771929 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[25/Sep/2018:09:00:47.780203196 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[26/Sep/2018:15:50:46.671324556 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[27/Sep/2018:10:36:35.122441609 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[27/Sep/2018:11:29:31.994645991 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[27/Sep/2018:11:42:14.074905249 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[28/Sep/2018:07:56:01.431044649 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[28/Sep/2018:07:56:40.192324627 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[28/Sep/2018:07:57:13.827975215 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors.20180924-080142:[28/Sep/2018:12:29:11.860652579 -0800] - ERR - ldbm_back_modrdn - entryrdn_rename_subtree failed (-30988); dn: uid=jlsmith5,ou=People,o=state.ak.us, newsrdn: (null), dn_newsuperiordn: (null)
errors.20180924-080142:[28/Sep/2018:12:31:03.854724118 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors:[02/Oct/2018:13:24:59.342201280 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors:[02/Oct/2018:16:29:11.282793381 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
errors:[04/Oct/2018:10:03:34.536504456 -0800] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE


I have noticed that many of our DNs contain ou=people (lower case p instead of upper case P) and I have speculated about whether that could cause problems somewhere.
Thanks,
Ludwig

On 10/02/2018 03:41 PM, Alberto Viana wrote:
I had to disable this plugin to solve the problem (workaround) in my master.

My first guess to solve the problem is:

Delete my agreements, my replication DB, and re-create everything, and after that try to enable the plugin again. But I couldn't do it so far...I will later in this month.

On Fri, Sep 28, 2018 at 4:00 PM Kreuzenstein, Luke (OIT) <luke.kreuzenstein@alaska.gov> wrote:
 >>> From: "Alberto Viana" <albertocrj@gmail.com>
 >>> To: "General discussion list for the 389 Directory server project."
<389-users@lists.fedoraproject.org>
 >>> Sent: Tuesday, March 20, 2018 6:15:46 PM
 >>> Subject: [389-users] error moving an user
 >>>
 >>> Hey Guys,
 >>>
 >>> 389 version: 389-Directory/1.3.7.4.20170912git26a9426 B2017.255.1330
 >>>
 >>> I'm trying to move one of my users to another OU and I see this kind of
 >>> error:
 >>>
 >>> Error while moving entry
 >>> - [LDAP: error code 1 - Operations Error]
 >>> java.lang.Exception: [LDAP: error code 1 - Operations Error]
 >>> at
 >>>
 >>>
 >>> In the log I see:
 >>>
 >>> [20/Mar/2018:14:12:27.172553808 -0300] - ERR - ldbm_back_modrdn -
 >>> SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did
not set
 >>> SLAPI_RESULT_CODE
 >>>
 >>> I thought that was related to my windows replication, but I
disabled it and
 >>> I'm still getting the error.
 >>>
 >>> Any clues?
 >>>
 >>> _______________________________________________
 >>> 389-users mailing list -- 389-users@lists.fedoraproject.org
 >>> To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org
 >>>

On Wed, Mar 21, 2018 at 12:00 PM, Simon Pichugin <spichugi@redhat.com>
wrote:

 >>    Hi,
 >>    could you please enable 16385 errorlog-level (16384 defaults and
1 trace) just before the operation and send us the
/var/log/dirsrv/slapd-INSTNAME/errors:
 >>
 >>    ldapmodify -h localhost -p 389 -D "cn=Directory manager" -w
password << EOF
 >>    dn: cn=config
 >>    changetype: modify
 >>    replace: nsslapd-errorlog-level
 >>    nsslapd-errorlog-level: 16385
 >>    EOF
 >>
 >>    Thanks,
 >>    Simon

Alberto Viana wrote on 3/23/2018 8:08 AM:
 > Simon,
 >
 > I was able to reproduce the problem in a new fresh install (I just
imported my database), and It's related to "Referential Integrity
Postoperation Plugin" that I use in my environment. When I disable it,
the moving works just fine.
 >
 > I have a single master, replication to one AD.
 >
 > I changed the log level, but it's really hard to find the root cause.
 >
 > Do you want to take a look on it?
 >
 >
 > Once it has some info about my tree, I'd prefer to send the link to
download the file directly to you.
 >
 > Thanks.

Was this issue ever resolved?  I'm experiencing the same symptom
intermittently in a production environment but haven't managed to
reproduce it in my test environment. The DN gets updated but the uid
(naming attribute) does not. Restarting slapd has helped in one instance
(to apparently fix a corrupted entry) but not every instance.

[27/Sep/2018:11:29:31.994645991 -0800] - ERR - ldbm_back_modrdn -
SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set
SLAPI_RESULT_CODE

It's a single master configuration with two consumer replicas and about
37000 entries.
The Referential Integrity Postoperation Plugin is enabled on the master
only.

using:
 > rpm -qa | grep 389-ds-base
389-ds-base-1.3.7.5-25.el7_5.x86_64
389-ds-base-libs-1.3.7.5-25.el7_5.x86_64
 > uname -a
Linux         3.10.0-862.11.6.el7.x86_64 #1 SMP Tue Aug 14 21:49:04 UTC
2018 x86_64 x86_64 x86_64 GNU/Linux

_______________________________________________
389-users mailing list -- 389-users@lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org
Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject.org


_______________________________________________
389-users mailing list -- 389-users@lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org
Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject.org

-- 
Red Hat GmbH, http://www.de.redhat.com/, Registered seat: Grasbrunn, 
Commercial register: Amtsgericht Muenchen, HRB 153243,
Managing Directors: Charles Cachera, Michael Cunningham, Michael O'Neill, Eric Shander


_______________________________________________
389-users mailing list -- 389-users@lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org
Fedora Code of Conduct: https://urldefense.proofpoint.com/v2/url?u=https-3A__getfedora.org_code-2Dof-2Dconduct.html&d=DwIGaQ&c=teXCf5DW4bHgLDM-H5_GmQ&r=WWEVWbdVNAL5YoAZkgTvaRklGnnzP8rchpW5qJbXYMA&m=Lg8kZkysOB62VQGorlqaP5_bgVXBeKE_enfOvtqIdBA&s=OE5hrHN0-hKRFO6zM-ZTV1rv27PbJwDnQnF3CQnCHzs&e=
List Guidelines: https://urldefense.proofpoint.com/v2/url?u=https-3A__fedoraproject.org_wiki_Mailing-5Flist-5Fguidelines&d=DwIGaQ&c=teXCf5DW4bHgLDM-H5_GmQ&r=WWEVWbdVNAL5YoAZkgTvaRklGnnzP8rchpW5qJbXYMA&m=Lg8kZkysOB62VQGorlqaP5_bgVXBeKE_enfOvtqIdBA&s=smvquVz2uWYD_E7Z2bSnwlG9yw8WWqQcIfBXAo4U0eg&e=
List Archives: https://urldefense.proofpoint.com/v2/url?u=https-3A__lists.fedoraproject.org_archives_list_389-2Dusers-40lists.fedoraproject.org&d=DwIGaQ&c=teXCf5DW4bHgLDM-H5_GmQ&r=WWEVWbdVNAL5YoAZkgTvaRklGnnzP8rchpW5qJbXYMA&m=Lg8kZkysOB62VQGorlqaP5_bgVXBeKE_enfOvtqIdBA&s=W5hdmvkP4UqmNcV7Ab6ILo6taeLxiqKhPbH_EnaNvog&e=



_______________________________________________
389-users mailing list -- 389-users@lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org
Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject.org

-- 
Red Hat GmbH, http://www.de.redhat.com/, Registered seat: Grasbrunn, 
Commercial register: Amtsgericht Muenchen, HRB 153243,
Managing Directors: Charles Cachera, Michael Cunningham, Michael O'Neill, Eric Shander