Grouper Users - Open Discussion List

[Dominique Petitpierre <>]

Hello,

after poring over DEBUG and even TRACE logs I eventually noticed that  LdapSystem.performLdapRead was retrieving members correctly while LdapSystem.performLdapSearchRequest was not. ldaptive DEBUG logs showed that the SearchEntryHandlers were different:

INFO  LdapSystem.performLdapRead(688) -  - Active Directory: Searching with Ldap RangeEntryHandler
DEBUG AbstractOperation.execute(122) -  - execute request=[org.ldaptive.SearchRequest@260620851::baseDn=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, searchFilter=[org.ldaptive.SearchFilter@-253519907::filter=objectclass=*, parameters={}], returnAttributes=[member], searchScope=OBJECT, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=[org.ldaptive.ad.handler.RangeEntryHandler@17257],... 

DEBUG LdapSystem.performLdapSearchRequest(740) -  - Using attribute-value paging
DEBUG LdapSystem.performLdapSearchRequest(751) -  - Using ldap search-result paging
DEBUG AbstractOperation.execute(122) -  - execute request=[org.ldaptive.SearchRequest@-1826196816::baseDn=OU=student,OU=Grouper,OU=Groups,OU=_UNIGE,DC=isis-klif,DC=unige,DC=ch, searchFilter=[org.ldaptive.SearchFilter@948055064::filter=(&(objectclass=group)(gidNumber=5016234)), parameters={}], returnAttributes=[cn, objectclass, sAMAccountName, description, gidNumber, g
roupType, url, displayName, extensionAttribute7, member], searchScope=SUBTREE, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=[edu.interne
t2.middleware.grouper.pspng.LdapSearchProgressHandler@41973d42, edu.internet2.middleware.grouper.pspng.LdapSystem$1@6a6b8efd],...

In that request's result one can see that there is no values for the attribute member, but there is an extra attribute "member;range=0-1499" with the first 1500 values:

DEBUG AbstractOperation.execute(154) -  - execute response=[org.ldaptive.Response@152656682::result=[org.ldaptive.SearchResult@-274902094::entries=[[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[[member;range=0-1499[CN= ... [member[]],

When counting at the next step, only 0 member attribute values are found which causes the problem.

In the  code one can see that the request.SearchEntryHandlers is set to org.ldaptive.ad.handler.RangeEntryHandler , but right after it is set again to something else, cf.

https://github.com/Internet2/grouper/blob/grouper_2_4_0-a95-u57-w11-p12/grouper-misc/grouper-pspng/src/main/java/edu/internet2/middleware/grouper/pspng/LdapSystem.java#L744

SearchRequest.setSearchEntryHandlers does indeed replace the values, cf.

https://code.vt.edu/dfisher/ldaptive/-/blob/master/core/src/main/java/org/ldaptive/SearchRequest.java#L363

This extra setSearchEntryHandlers appeared in PSPNG 2.4.0 patch 8, the last patch to contain LdapSystem, and unfortunately still exists in the latest version:
https://github.com/Internet2/grouper/blob/master/grouper-misc/grouper-pspng/src/main/java/edu/internet2/middleware/grouper/pspng/LdapSystem.java#L744

Although not familiar with the Grouper code and not a Java programmer I believe there is enough evidence to say this is a bug.

What baffles me is that it looks like since that patch was released in June 2019 only one other person reported the problem (cf. https://todos.internet2.edu/browse/GRP-2343):
- Is PSPNG used with Active Directory in "production" environments?
- If so, what is different that prevents that bug to cause problems? Or why people don't notice?

In any case, a fix in a patch for 2.4.0 would be welcome! (I'd like to get this working before upgrading to 2.5).

Regards.

On 19.09.20 00:08, Dominique Petitpierre wrote:

Hello,

thanks for the suggestion!

On 18.09.20 19:32, Jeffrey Williams wrote:

What do you have ldap.groupLdap1.pagedResultsSize set to?

ldap.groupLdap1.pagedResultsSize  was not set, but setting it to 1000 or 100 did not change the symptoms: The LDAP error ENTRY_ALREADY_EXISTS still occurs.

The effective settings and relevant logs are in annexe below.

I am perlexed:

- why is Jira issue GRP-2343 considered minor?  The problem described seems serious: synchronization does not work.
This might be the same problem: the message logs in the description are similar to the ones in Annex.

- Any other ideas or pointers to tackle this issue are welcome!

Regards.

Annex: effective settings and relevant logs




dn: CN=Default Query Policy,CN=Query-Policies,CN=Directory Service,CN=Windows NT,CN=Services,CN=Configuration,DC=isis-klif,DC=unige,DC=ch
lDAPAdminLimits: MaxValRange=1500
lDAPAdminLimits: MaxPageSize=1000





grep -a '^2020-09-18 22:3.*Setting up LDAP Connection with properties:' grouper_error.log|tail -1 |sed -e 's/[:,] /&\n/g' |sed -E -n -e 's/(url|bindDn|ldapUrl|user|pass)=.*,/\1=***,/g' -e /=/p
{org.ldaptive.pass=***,
org.ldaptive.url="***,"
org.ldaptive.bindDn=***,
org.ldaptive.maxPoolSize=6,
org.ldaptive.minPoolSize=2,
org.ldaptive.bindCredential=**masked**,
org.ldaptive.ldapUrl=***,
org.ldaptive.user=***,
org.ldaptive.pagedResultsSize=100,
org.ldaptive.searchResultHandlers=org.ldaptive.handler.DnAttributeEntryHandler,edu.internet2.middleware.grouper.ldap.ldaptive.GrouperRangeEntryHandler}



sed -n -e '/^2020-09-18 22:3.*Provisioner.* - Setting /s///p' grouper_error.log
properties for activedirectory_student consumer/provisioner.
enabled to true
grouperIsAuthoritative to false
dataCacheTime_secs to 43200
sleepTimeAfterError_ms to 1000
grouperGroupCacheSize to 10000
grouperSubjectCacheSize to 10000
targetSystemGroupCacheSize to 10000
targetSystemUserCacheSize to 10000
createMissingUsers to false
needsTargetSystemUsers to true
needsTargetSystemGroups to true
supportsEmptyGroups to true
groupSelectionExpression to ${utils.containedWithin(provisionerName, stemAttributes['etc:pspng:provision_to'], groupAttributes['etc:pspng:provision_to']) && !utils.containedWithin(provisionerName, stemAttributes['etc:pspng:do_not_provision_to'], groupAttributes['etc:pspng:do_not_provision_to'])}
attributesUsedInGroupSelectionExpression to [etc:pspng:provision_to, etc:pspng:do_not_provision_to]
attributesUsedInGroupSelectionExpressionAreComparedToProvisionerName to true
userSearch_batchSize to 50
groupSearch_batchSize to 50
coordinationTimeout_secs to 300
coordinationUpdateInterval_secs to 10
areChangesToInternalGrouperSubjectsIgnored to true
grouperMessagingSystemName to grouperBuiltinMessaging
numberOfDataFetchingWorkers to 1
missingSubjectsWarningThreshold_percentage to 100
areCacheSizeWarningsEnabled to true
cacheFullnessWarningThreshold_percentage to 95
maxNumberOfTimesToRepeatedlyFullSyncGroup to 3
timeToSleepBetweenRepeatedFullSyncs_ms to 1000
properties for activedirectory_student consumer/provisioner.
isActiveDirectory to true
ldapPoolName to groupLdap1
maxValuesToChangePerOperation to 100
userSearchBaseDn to OU=UsersUnige,OU=_UNIGE,DC=isis-klif,DC=unige,DC=ch
userSearchFilter to (cn=${empty(subject.attributes["unigeChStudentUid"])?"0":subject.attributes["unigeChStudentUid"].iterator().next()})
userSearchAttributes to [dn, cn]
userCreationBaseDn to null
userCreationLdifTemplate to null
ouCreationLdifTemplate to dn: ${dn}||ou: ${ou}||objectclass: organizationalunit
attributesNeededingDnEscaping to [dn, distinguishedname, entrydn, uniquemember, member]
properties for activedirectory_student consumer/provisioner.
memberAttributeName to member
memberAttributeValueFormat to ${ldapUser.getDn()}
groupAttributeName to memberof
groupCreationLdifTemplate to dn: ${utils.bushyDn(name, "cn", "ou")}||cn: ${extension}||objectclass: group||objectclass: top||gidNumber: ${idIndex + 5000000}||description: ${org.apache.commons.lang3.StringUtils.abbreviate(org.apache.commons.lang3.StringUtils.replaceAll((description?:""),"[\r\n]+"," "),900)}||groupType: 4||sAMAccountName: student`${org.apache.commons.lang3.StringUtils.replaceChars(name,':','`').replaceAll("[\"\[\];|=+*?<>/\\, ]","_")}||extensionAttribute7: ${name}||url: ${empty(groupAttributes['etc:pspng:entityId'])?"":(org.apache.commons.lang3.StringUtils.replace(org.apache.commons.lang3.StringUtils.removeEnd(org.apache.commons.lang3.StringUtils.removeStart(groupAttributes['etc:pspng:entityId'].toString(),"["),"]"),", ","\u000aurl: "))}||displayName: ${empty(groupAttributes['etc:pspng:is_member_of_value'])?"":groupAttributes['etc:pspng:is_member_of_value']}
groupSearchBaseDn to OU=student,OU=Grouper,OU=Groups,OU=_UNIGE,DC=isis-klif,DC=unige,DC=ch
groupCreationBaseDn to OU=student,OU=Grouper,OU=Groups,OU=_UNIGE,DC=isis-klif,DC=unige,DC=ch
allGroupsSearchFilter to objectclass=group
singleGroupSearchFilter to (&(objectclass=group)(gidNumber=${group.idIndex + 5000000}))
groupSearchAttributes to [cn, objectclass, sAMAccountName, description, gidNumber, groupType, url, displayName, extensionAttribute7]
ldapGroupCacheTime_secs to 600
ldapGroupCacheSize to 10000
memberAttributeIsCaseSensitive to false
enableBulkGroupSearching to true

sed -n -E -e '/^2020-09-18 22:3.*(\b1502\b|EXISTS)/s/.* -  - //p' grouper_error.log
Fetching subjects Completed (Success): 1502 items in 08.980s (10035.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|1502 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 1502. #Values in mod/ADD: 1502
FullSync Item done (Successful: Success). Stats: ins=1502|del=0|upd=0|tot=1502|t=38 secs/ProcTime: 38.330s Timing breakdown: init=0%/ReadGroupFromGrouper=0%/ClearingGroupCache=0%/StartCoordination=0%/StartProvisioning(get group & subject info)=0%/doFullSync=98%/FinishProvisioning=0%/FinishCoordination=0%/: Action="application:bpm-poc:bpm-oracle:workflow1:testgroup|qid=1|Trigger=Scheduled" full sync|ExternalRef=null|AsOf=Sep 18, 2020 10:36:27 PM|QTime=00.001s|Age=38.332s
FullSyncer(activedirectory_student): Full Sync of all groups progress: 1 groups of 1 (100%): ins=1502|del=0|upd=0|tot=1502|t=38 secs
FullSyncer(activedirectory_student): Full Sync of all groups: Finished. Stats: ins=1502|del=0|upd=0|tot=1502|t=0 secs

On Fri, Sep 18, 2020 at 4:21 AM Dominique Petitpierre <> wrote:

Hello,

any advice on how to debug this problem?:

When synchronizing a target group that has more than 1500 members, even if there is nothing to do the PSPNG provisioner tries to replace all the members and fails with a LDAP error ENTRY_ALREADY_EXISTS.
This is with a Microsoft Active Directory target directory. It does not happen with 1500 members or less.
The 1501th member can be added without problem, but a subsequent full sync triggers the problem
This is clearly linked to this Active Directory feature:
3.1.1.3.1.3.3 Range Retrieval of Attribute Values
https://docs.microsoft.com/en-us/openspecs/windows_protocols/ms-adts/e27b48db-6f82-44cd-9038-2e54f790cc1f

dn: CN=Default Query Policy,CN=Query-Policies,CN=Directory Service,CN=Windows NT,CN=Services,CN=Configuration,DC=isis-klif,DC=unige,DC=ch
lDAPAdminLimits: MaxValRange=1500

Adding the searchResultHandler property to the groupLdap1 LDAP connector configuration does not help:

ldap.groupLdap1.searchResultHandlers=org.ldaptive.handler.DnAttributeEntryHandler,edu.internet2.middleware.grouper.ldap.ldaptive.GrouperRangeEntryHandler

cf. vt-ldap to ldaptive migration for LDAP access
https://spaces.at.internet2.edu/display/Grouper/vt-ldap+to+ldaptive+migration+for+LDAP+access#vt-ldaptoldaptivemigrationforLDAPaccess-Configurationoptions

And of course the LdapProvisioner isActiveDirectory property is set:

changeLog.consumer.activedirectory_student.isActiveDirectory = true

A search in grouper-users shows old problems, in particular:

Re: [grouper-users] Active Directory >1500 group members
https://lists.internet2.edu/sympa/arc/grouper-users/2016-11/msg00005.html

Re: [grouper-users] AD Range Attribute support with the PSP
https://lists.internet2.edu/sympa/arc/grouper-users/2017-01/msg00012.html

There is a Jira issue GRP-2343 that shows the same symptom, although it is considered minor and is not fixed:

LdapSystem.performLdapSearchRequest doesn't return any members when group has more than 1500 memberships
https://todos.internet2.edu/browse/GRP-2343

- What could be the problem? Surely PSNG works in other sites with large Active Directory groups!

There must be something obvious I am missing, but I am at loss of ideas.

Thanks in advance for your lights!

Regards.

Annexe: Relevant extract of the logs:

2020-09-18 07:30:06,640: [main] WARN  GrouperStartup.printConfigOnce(232) -  - Grouper starting up: version: 2.4.0, build date: null, env: test_2.4.0_grouper-loader
grouperPatchStatus read from: /usr/local/grouper-loader/grouperPatchStatus.properties
api patches installed:        0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96
pspng patches installed:      0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12
...
2020-09-18 08:23:11,479: [main] DEBUG LdapProvisionerConfiguration.readConfiguration(126) -  - Ldap Provisioner activedirectory_student - Setting isActiveDirectory to true
...
2020-09-18 08:23:21,963: [FullSyncer(activedirectory_student)-Thread] INFO  ProgressMonitor.completelyDone(81) -  - Fetching subjects Completed (Success): 1501 items in 08.833s (10195.9 items/minute)
...
2020-09-18 08:23:21,977: [FullSyncer(activedirectory_student)-Thread] INFO  Provisioner.doFullSync(1591) -  - activedirectory_student-full/application:bpm-poc:bpm-oracle:workflow1:testgroup/#16234(Existing): 1501 correct member subjects. Sample: [''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', ''/'person'/'people-test.unige.ch', '674039@u
nige.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']...
...
2020-09-18 08:23:22,076: [FullSyncer(activedirectory_student)-Thread] INFO  LdapSystem.performLdapRead(688) -  - Active Directory: Searching with Ldap RangeEntryHandler
...
2020-09-18 08:23:51,589: [FullSyncer(activedirectory_student)-Thread] INFO  LdapGroupProvisioner.doFullSync(194) -  - activedirectory_student-full: Full-sync comparison for application:bpm-poc:bpm-oracle:workflow1:testgroup/#16234(Existing): Target-subject count: Correct/Actual: 1501/0
...
2020-09-18 08:23:51,765: [FullSyncer(activedirectory_student)-Thread] WARN  LdapSystem.performLdapModify(450) -  - 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

-- 
Mr Dominique Petitpierre, user=Dominique.Petitpierre domain=unige.ch
IT Division, University of Geneva, Switzerland

-- 
Meilleures salutations,
Dominique Petitpierre
Université de Genève, DSTIC
+41 22 37 97117