memberOf overlay issues with 2.4.44 + ITS 8432 patch

["Paul B. Henson" <henson@acm.org>]

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 yes,
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...