I sent this to the mailing list and was advised to add it to ITS 8444, so here it is:

I recently updated to openldap 2.4.44 with the patch for ITS 8432. I'd been holding off in hopes of a new release with that patch included and for some update on ITS 8444, but decided to go ahead and push it through during the holiday break.

I installed it on my dev environment and was unable to replicate the issues reported in ITS 8444 so went ahead and rolled into production. However, now that I'm in production, I'm seeing different issues with the memberOf overlay. It seems for some reason group membership deletions are getting replicated multiple times? In the logs, I will see something like the following:

Dec 21 04:16:59 themis slapd[2607]: conn=364875 op=227806 MOD dn="uid=members,ou=group,dc=cpp,dc=edu" Dec 21 04:16:59 themis slapd[2607]: conn=364875 op=227806 MOD attr=member

My identity management system connected and removed some members from this group. Next, there will be a number of lines like this:

Dec 21 04:17:15 themis slapd[2607]: conn=-1 op=0: memberof_value_modify DN="uid=prsloan,ou=user,dc=cpp,dc=edu" delete memberOf="uid=members,ou=group,dc=cpp,dc=edu" failed err=16 Dec 21 04:17:16 themis slapd[2607]: conn=-1 op=0: memberof_value_modify DN="uid=prsloan,ou=user,dc=cpp,dc=edu" delete memberOf="uid=members,ou=group,dc=cpp,dc=edu" failed err=16 Dec 21 04:17:17 themis slapd[2607]: conn=-1 op=0: memberof_value_modify DN="uid=prsloan,ou=user,dc=cpp,dc=edu" delete memberOf="uid=members,ou=group,dc=cpp,dc=edu" failed err=16 Dec 21 04:17:18 themis slapd[2607]: conn=-1 op=0: memberof_value_modify DN="uid=prsloan,ou=user,dc=cpp,dc=edu" delete memberOf="uid=members,ou=group,dc=cpp,dc=edu" failed err=16 Dec 21 04:17:18 themis slapd[2607]: conn=-1 op=0: memberof_value_modify DN="uid=prsloan,ou=user,dc=cpp,dc=edu" delete memberOf="uid=members,ou=group,dc=cpp,dc=edu" failed err=16 Dec 21 04:17:18 themis slapd[2607]: conn=-1 op=0: memberof_value_modify DN="uid=prsloan,ou=user,dc=c

Where the memberOf overlay is complaining that it can't remove the corresponding memberOf attribute from the user. Reviewing the accesslog, we see:

dn: reqStart=20161221121659.000002Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121659.000002Z reqEnd: 20161221121706.000000Z reqType: modify reqSession: 364875 reqAuthzID: cn=idmgmt,ou=user,ou=service,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

The initial tranaction from my client, authenticated as cn=idmgmt. This one is successful and the overlay deletes the memberOf attribute. However, there are then *six* more instances of the same transaction:

dn: reqStart=20161221121714.000001Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121714.000001Z reqEnd: 20161221121715.000000Z reqType: modify reqSession: 3 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

dn: reqStart=20161221121716.000001Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121716.000001Z reqEnd: 20161221121716.000002Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

dn: reqStart=20161221121716.000004Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121716.000004Z reqEnd: 20161221121717.000002Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

dn: reqStart=20161221121717.000001Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121717.000001Z reqEnd: 20161221121718.000000Z reqType: modify reqSession: 2 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

dn: reqStart=20161221121718.000001Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121718.000001Z reqEnd: 20161221121718.000002Z reqType: modify reqSession: 2 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

dn: reqStart=20161221121718.000003Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121718.000003Z reqEnd: 20161221121718.000004Z reqType: modify reqSession: 2 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

These are are performed by cn=ldaproot, and correspond to the six error messages from the overlay about failing to remove the attribute (which was already removed).

Similarly, on a replica:

Dec 21 04:17:16 coeus slapd[2841]: conn=-1 op=0: memberof_value_modify DN="uid=prsloan,ou=user,dc=cpp,dc=edu" delete memberOf="uid=members,ou=group,dc=cpp,dc=edu" failed err=16

There is one error, because there are two copies of the transaction:

dn: reqStart=20161221121706.000001Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121706.000001Z reqEnd: 20161221121716.000000Z reqType: modify reqSession: 1 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

dn: reqStart=20161221121714.000002Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20161221121714.000002Z reqEnd: 20161221121716.000001Z reqType: modify reqSession: 3 reqAuthzID: cn=ldaproot,dc=cpp,dc=edu reqDN: uid=members,ou=group,dc=cpp,dc=edu reqResult: 0 reqMod: member:- uid=jjtringali,ou=user,dc=cpp,dc=edu reqMod: member:- uid=kaijulee,ou=user,dc=cpp,dc=edu reqMod: member:- uid=srknight,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ppimentel,ou=user,dc=cpp,dc=edu reqMod: member:- uid=epdetering,ou=user,dc=cpp,dc=edu reqMod: member:- uid=ktran,ou=user,dc=cpp,dc=edu [...] reqMod: member:- uid=prsloan,ou=user,dc=cpp,dc=edu

So far, I've only seem this behavior for group membership removals. Adds don't seem to cause a problem, nor do create/delete of groups or users as far as I can tell.

Any thoughts on what's going on here? It's not causing any failures yet, as removing members multiple times results in the same end state and the multiple replication seems to have a fairly low upper bound. But it would be nice to fix it :).

Thanks...