Grouper Users - Open Discussion List

["Coleman, Erik C" <>]

Dominique,

 

I can confirm this behavior in our environment, running Grouper 2.5.33.  Looks like about 35 of these events last Saturday, the day we run a full sync.  Group membership successfully propagated to AD without any performance impact or missing entries, so we never really “paid attention” to these log entries.  Honestly, there are dozens of WARN level logs that appear to be benign, have always put off combing the logs for a rainy weekend project!

 

Have you provided this information as a comment to the JIRA entry?  I suspect that they aren’t prioritizing this with the work on the PSPNG replacement, which will completely change the architecture of group provisioning to targets.

 

--

Erik Coleman

University of Illinois at Urbana-Champaign

 

 

 

 

From: <> On Behalf Of Dominique Petitpierre
Sent: Monday, September 21, 2020 7:52 PM
To: Grouper-Users <>
Cc: Jeffrey Williams <>
Subject: Re: [grouper-users] PSPNG: syncing fails with ENTRY_ALREADY_EXISTS when group has more than 1500 members

 

Hello,

 

here is a example showing that PSPNG full sync does not work in the case I was describing:

 

On 21.09.20 19:41, Dominique Petitpierre wrote:

So when the full sync has nothing to do there is no bad consequences.
But if you stop the loader process, remove a member from the group in Grouper, and start "manually" a full sync, then, because of the bug that member will not be removed from the target directory group.

0) the Grouper group and target directory group are synchronized and have 1502 members, and user bello6 is not one of them.

ldapsearch ... gidnumber=5016234 'member'|grep -c bello6

0

ldapsearch ...  gidnumber=5016234 'member;range=1500-2999'|grep -c ^member

2

1) add a new member bello6 in the target directory group with

ldapmodify ...  <<EOF

dn: CN=testgroup,OU=workflow1,OU=bpm-oracle,OU=bpm-poc,OU=application,OU=student,OU=Grouper,OU=Groups,OU=_UNIGE,DC=isis-klif,DC=unige,DC=ch

changetype: modify

add: member

member: CN=bello6,OU=LETTRES,OU=ETU,OU=UsersUnige,OU=_UNIGE,DC=isis-klif,DC=unige,DC=ch

EOF

2) check the new member and the new number of members (1503) in the target directory group:

ldapsearch ... gidnumber=5016234 'member'|grep bello6

member;range=0-1499: CN=bello6,OU=LETTRES,OU=ETU,OU=UsersUnige,OU=_UNIGE,DC=isis-klif,DC=unige,DC=ch

ldapsearch ...  gidnumber=5016234 'member;range=1500-2999'|grep -c ^member

3

3) start a full sync for that group (or wait for the next global full sync launched by the daemon "loader" process).
Here is a relevant extract of the log (log level INFO, to compare to the one in https://lists.internet2.edu/sympa/arc/grouper-users/2020-09/msg00039.html):

sed -n -e '/^2020-09-21 23:50/p' grouper_error.log.2020-09-21| egrep -a 'EXIST|\b(1502|1503)\b'|sed -e 's/.* -  - //'

Fetching subjects Completed (Success): 1502 items in 09.869s (9131.6 items/minute)

activedirectory_student-full/application:bpm-poc:bpm-oracle:workflow1:testgroup/#16234(Existing): 1502 correct member subjects. Sample: [''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch']...

activedirectory_student-full: Full-sync comparison for application:bpm-poc:bpm-oracle:workflow1:testgroup/#16234(Existing): Target-subject count: Correct/Actual: 1502/0

activedirectory_student-full: Group application:bpm-poc:bpm-oracle:workflow1:testgroup/#16234(Existing) has 1502 missing values

groupLdap1: Performing ldap mod (with retry) Mod Summary: dn=cn=testgroup,ou=workflow1,ou=bpm-oracle,ou=bpm-poc,ou=application,ou=student,ou=grouper,ou=groups,ou=_unige,dc=isis-klif,dc=unige,dc=ch|ADD 1502 member values|

groupLdap1: Problem while modifying ldap system based on grouper expectations. Starting to perform adaptive modifications based on data already on server: cn=testgroup,ou=workflow1,ou=bpm-oracle,ou=bpm-poc,ou=application,ou=student,ou=grouper,ou=groups,ou=_unige,dc=isis-klif,dc=unige,dc=ch: ENTRY_ALREADY_EXISTS

groupLdap1: Data already on ldap server Entry Summary: dn=cn=testgroup,ou=workflow1,ou=bpm-oracle,ou=bpm-poc,ou=application,ou=student,ou=grouper,ou=groups,ou=_unige,dc=isis-klif,dc=unige,dc=ch|1503 member values|

groupLdap1: Summary: Comparing modification of member to what is already in LDAP: ADD/1502 Values

groupLdap1: Comparing Attribute member. #Values on server already 1503. #Values in mod/ADD: 1502

FullSync Item done (Successful: Success). Stats: ins=1502|del=0|upd=0|tot=1502|t=41 secs/ProcTime: 41.384s Timing breakdown: init=0%/ReadGroupFromGrouper=0%/ClearingGroupCache=0%/StartCoordination=0%/StartProvisioning(get group & subject info)=1%/doFullSync=98%/FinishProvisioning=0%/FinishCoordination=0%/: Action="application:bpm-poc:bpm-oracle:workflow1:testgroup|qid=1|Trigger=Scheduled" full sync|ExternalRef=null|AsOf=21 sept. 2020 23:50:02|QTime=00s|Age=41.384s

FullSyncer(activedirectory_student): Full Sync of all groups progress: 1 groups of 1 (100%): ins=1502|del=0|upd=0|tot=1502|t=41 secs

FullSyncer(activedirectory_student): Full Sync of all groups: Finished. Stats: ins=1502|del=0|upd=0|tot=1502|t=0 secs

The first log lines are the same: because of the bug, the provisioner deduces that  the group is empty (Correct/Actual: 1502/0) and tries to add all the members again (ADD 1502 member values) and that operation fails (ENTRY_ALREADY_EXISTS). Since that failure is not fatal it continues and checks the content of the group again, with another method that is not bugged, and finds that there are 1503 members (Values on server already 1503) and eventually concludes that the supposedly missing members have been inserted (Stats: ins=1502), but no deletion occurred (del=0) and syncing is finished with 1502 members in the group.

4) check that the extra member in the target directory is still there and there are still 1503 members in the target group:

ldapsearch ... gidnumber=5016234 'member'|grep bello6

member;range=0-1499: CN=bello6,OU=LETTRES,OU=ETU,OU=UsersUnige,OU=_UNIGE,DC=isis-klif,DC=unige,DC=ch

ldapsearch ...  gidnumber=5016234 'member;range=1500-2999'|grep -c ^member

3

5) Conclusion: full sync does not work in that case, at least in my context (cf. Grouper version, PSPNG patches and settings in https://lists.internet2.edu/sympa/arc/grouper-users/2020-09/msg00039.html).

 

If you have Grouper 2.4.0 or greater with PSPNG patch 8 or greater, syncing to a target Active Directory, could you please try something similar for a group with at least 1501 members (more than AD lDAPAdminLimits: MaxValRange=1500), with the following log level in conf/log4j.properties:

log4j.logger.edu.internet2.middleware.grouper.pspng=INFO

or, if you want to see if there is a bad searchEntryHandlers and the resulting empty list of values for the member attribute (cf. https://lists.internet2.edu/sympa/arc/grouper-users/2020-09/msg00042.html):

log4j.logger.edu.internet2.middleware.grouper.pspng=DEBUG

log4j.logger.org.ldaptive=DEBUG

 

I am curious of your findings.
Thanks in advance!

 

Regards.

-- 

Mr Dominique Petitpierre, user=Dominique.Petitpierre domain=unige.ch

IT Division, University of Geneva, Switzerland