Grouper Users - Open Discussion List

[Julio Macavilca <>]

I ended up turning the log level to debug as some of the debugging lines applied in the patch are set at this level. When I grep for "enableBulkGroupSearching" in grouper_error.log, I see that the config is being read:

2017-08-16 15:12:53,696: [DefaultQuartzScheduler_Worker-8] DEBUG LdapGroupProvisionerConfiguration.readConfiguration(197) -  - Ldap Group Provisioner pspng_ldap - Setting enableBulkGroupSearching to true

2017-08-16 15:12:53,832: [DefaultQuartzScheduler_Worker-8] INFO  LdapSystem.buildLdapConnectionPool(92) -  - Setting up LDAP Connection with properties: {org.ldaptive.ldapUrl=ldaps://devldap:636, org.ldaptive.enableBulkGroupSearching=true, org.ldaptive.searchResultPagingEnabled=false, org.ldaptive.baseDn=ou=zz,o=zzz,o=nyu, org.ldaptive.bindDn=uid=zzzz, org.ldaptive.bindCredential=zzzzz}

Or

2017-08-16 15:59:51,331: [DefaultQuartzScheduler_Worker-9] DEBUG LdapGroupProvisionerConfiguration.readConfiguration(197) -  - Ldap Group Provisioner pspng_ldap - Setting enableBulkGroupSearching to false

The debug lines added in GRP-1588 display when I create a "vanilla" group (without the need for scape chars) then I can see these lines, with or without members in int.

2017-08-16 16:55:57,835: [DefaultQuartzScheduler_Worker-1] DEBUG LdapGroupProvisioner.fetchTargetSystemGroups(451) -  - pspng_ldap: Searching for group test:thisisvanilla with:: [org.ldaptive.SearchFilter@1665898991::filter=(&(objectclass=groupOfNames)(entryDN=cn=thisisvanilla,ou=test,ou=nyu,ou=Groups,o=nyu.edu,o=nyu)), parameters={}]

2017-08-16 16:55:57,863: [DefaultQuartzScheduler_Worker-1] DEBUG LdapGroupProvisioner.fetchTargetSystemGroups(462) -  - pspng_ldap: Group search returned cn=thisisvanilla,ou=test,ou=nyu,ou=groups,o=nyu.edu,o=nyu

Here I create a group with no members in it that requires escape characters and it is successful:

2017-08-16 17:01:51,700: [DefaultQuartzScheduler_Worker-5] DEBUG LdapGroupProvisioner.fetchTargetSystemGroups(451) -  - pspng_ldap: Searching for group test:This_-_is_Not,_Vanilla20 with:: [org.ldaptive.SearchFilter@-1715593699::filter=(&(objectclass=groupOfNames)(entryDN=cn=This_-_is_Not\,_Vanilla20,ou=test,o=nyu.edu,o=nyu)), parameters={}]

But this debug line below did not print out in the logs as is the case above:

DEBUG LdapGroupProvisioner.fetchTargetSystemGroups(462) - .....

So, creating a group with no members requiring escape chars is successful but when I go back  10 minutes later to add a member, that's when it fails as it tries to create the group again, see below before it throws LDAP 68 and changelog consequently stuck.

2017-08-16 15:16:52,161: [DefaultQuartzScheduler_Worker-10] DEBUG Provisioner.shouldGroupBeProvisioned(1318) -  - pspng_ldap: Group test:This_-_is_Not,_Vanilla21 matches group-selection filter.

2017-08-16 15:16:52,162: [DefaultQuartzScheduler_Worker-10] INFO  LdapGroupProvisioner.createGroup(299) -  - Creating LDAP group for GrouperGroup: test:This_-_is_Not,_Vanilla21 

2017-08-16 15:16:52,334: [DefaultQuartzScheduler_Worker-10] DEBUG Provisioner.evaluateJexlExpression(538) -  - Evaluated Jexl _expression_: cn=This_-_is_Not\,_Vanilla21,ou=test FROM ${utils.bushyDn(grouper.name, "cn", "ou")} WITH variables {idIndex=17889, userSearchBaseDn=ou=people,o=nyu.edu,o=nyu, groupAttributes={}, groupCreationBaseDn=ou=test,o=nyu.edu,o=nyu, stemAttributes={}, utils=edu.internet2.middleware.grouper.pspng.PspJexlUtils@40b0c0, groupSearchBaseDn=ou=test,o=nyu.edu,o=nyu, name=test:This_-_is_Not, _Vanilla21, provisionerName=pspng_ldap, group=Group[name=test:This_-_is_Not, _Vanilla21,uuid=5dcad476b1a2461ba3fad017a6393c05], provisionerType=LdapGroupProvisioner}

2017-08-16 15:16:52,336: [DefaultQuartzScheduler_Worker-10] DEBUG Provisioner.evaluateJexlExpression(538) -  - Evaluated Jexl _expression_: boo hoo FROM ${group.description} WITH variables {idIndex=17889, userSearchBaseDn=ou=people,o=nyu.edu,o=nyu, groupAttributes={}, groupCreationBaseDn=ou=test,o=nyu.edu,o=nyu, stemAttributes={}, utils=edu.internet2.middleware.grouper.pspng.PspJexlUtils@40b0c0, groupSearchBaseDn=ou=test,o=nyu.edu,o=nyu, name=test:This_-_is_Not, _Vanilla21, provisionerName=pspng_ldap, group=Group[name=test:This_-_is_Not, _Vanilla21,uuid=5dcad476b1a2461ba3fad017a6393c05], provisionerType=LdapGroupProvisioner}

2017-08-16 15:16:52,349: [DefaultQuartzScheduler_Worker-10] DEBUG LdapGroupProvisioner.createGroup(329) -  - pspng_ldap: LDIF for new group (with partial DN): dn: cn=This_-_is_Not\,_Vanilla21,ou=test||objectclass: groupOfNames||description: boo hoo

2017-08-16 15:16:52,351: [DefaultQuartzScheduler_Worker-10] DEBUG LdapGroupProvisioner.createGroup(338) -  - pspng_ldap: Adding group: [dn=cn=This_-_is_Not\,_Vanilla21,ou=test,o=nyu.edu,o=nyu[[description[boo hoo]], [objectclass[groupOfNames]]]]

2017-08-16 15:16:52,351: [DefaultQuartzScheduler_Worker-10] INFO  LdapProvisioner.performLdapAdd(722) -  - pspng_ldap: Creating LDAP object: cn=This_-_is_Not\,_Vanilla21,ou=test,o=nyu.edu,o=nyu

2017-08-16 15:16:52,354: [DefaultQuartzScheduler_Worker-10] INFO  LdapSystem.performLdapAdd(329) -  - enterpriseldap: Creating LDAP object: cn=This_-_is_Not\,_Vanilla21,ou=test,o=nyu.edu,o=nyu

2017-08-16 15:16:52,416: [DefaultQuartzScheduler_Worker-10] ERROR LdapSystem.performLdapAdd(337) -  - Problem while creating new ldap object: [dn=cn=This_-_is_Not\,_Vanilla21,ou=test,o=nyu.edu,o=nyu[[description[foo foo]], [objectclass[groupOfNames]]]]

[org.ldaptive.LdapException@17704354::resultCode=ENTRY_ALREADY_EXISTS, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, message=javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla21,test,ou=nyu,ou=Groups,o=nyu.edu,o=nyu', providerException=javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla21,test,o=nyu.edu,o=nyu']

thanks,
Julio

On Thu, Aug 10, 2017 at 4:32 PM, Julio Macavilca <> wrote:

I grepped for that string and didn't find it but looking at the last lines in my {grouper_home}/grouperPatchStatus.properties I see the following:

# added by grouper-installer

grouper_v2_3_0_pspng_patch_15.date = 2017/08/10 10:22:01

# added by grouper-installer

grouper_v2_3_0_pspng_patch_15.state = applied

When I create an empty group, everything works fine (no errors, last_sequence_processed are all the same and provisioned to ldap), but for instance for test #4 after I added a member was when I saw those ldap 68's/changelog stuck.  I will keep looking on my end, thanks for all the help.

regards,

Julio

On Thu, Aug 10, 2017 at 4:03 PM, Bee-Lindgren, Bert <> wrote:

Just to make sure Patch 15 is in place... Can you see if "Slower fetching will be attempted" is logged in your Test 4?

Thank you,

  Bert

---

From: <> on behalf of Julio Macavilca <>
Sent: Thursday, August 10, 2017 2:26 PM
To: Bee-Lindgren, Bert
Cc: Grouper Users
Subject: Re: [grouper-users] Re: PSPNG issue

 

Hey Bert,

Thanks so much for that.  I'm all patched up to #15 and was testing this out with the new attribute in the config, please see below as I was not successful in provisioning but perhaps I'm missing something.  I changed my singleGroupSearchFilter to a more resilient attribute (gidNumber) and set the enableBulkGroupSearching. 

regards,
Julio

Test 1:

Single search filter with gid:

changeLog.consumer.pspng_ldap.singleGroupSearchFilter = (gidNumber=${group.idIndex})

changeLog.consumer.pspng_ldap.enableBulkGroupSearching=false

After adding a group and members that requires escape chars, no errors/stacktrace of changelog being stuck in logs but I did see in the logs each of the nonaffected changelog consumers display the following:

[DefaultQuartzScheduler_Worker-4] INFO  PspChangelogConsumerShim.processChangeLogEntries(52) -  - pspng_<consumer-name>: +processChangeLogEntries(6)

But for the affected one (pspng_ldap) I didn't see this appear.  Then, when looking at the grouper_change_log_consumer table the last_sequence_processed number is stuck on the same number it was before while the other ones are all caught up.  In this case, nothing gets provisioned to ldap (group/members).

Test 2: still with gidNumber but this time setting the new attribute to true

changeLog.consumer.pspng_ldap.singleGroupSearchFilter = (gidNumber=${group.idIndex})

changeLog.consumer.pspng_ldap.enableBulkGroupSearching=true

I do see:

Worker-5] INFO  PspChangelogConsumerShim.processChangeLogEntries(52) -  - pspng_ldap: +processChangeLogEntries(1)

but same effect on the other tables and not provisioned to ldap.

Test 3: went back to the old singleGroupSearchFilter with the new attribute set to false:

changeLog.consumer.pspng_ldap.singleGroupSearchFilter = (&(objectclass=groupOfNames)(entryDN=${utils.bushyDn(group.name, "cn", "ou")},ou=test,o=nyu.edu,o=nyu))

changeLog.consumer.pspng_ldap.enableBulkGroupSearching=false

I see in the logs:

INFO  PspChangelogConsumerShim.processChangeLogEntries(52) -  - pspng_ldap: +processChangeLogEntries(5)

but shortly followed by the error

[DefaultQuartzScheduler_Worker-1] ERROR LdapSystem.performLdapAdd(337) -  - Problem while creating new ldap object: [dn=cn=This_-_is_Not\,_Vanilla6,ou=ad,ou=pspngtest,ou=test,o=nyu.edu,o=nyu[[description[back again]], [objectclass[groupOfNames]]]]

[org.ldaptive.LdapException@13083363::resultCode=ENTRY_ALREADY_EXISTS, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, message=javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla6,ou=test,o=nyu.edu,o=nyu', providerException=javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla6,ou=test,o=nyu.edu,o=nyu']

As before, the group is provisioned to ldap but no members and changelog is stuck and keeps display the stacktrace.

Test 4: Set enableBulkGroupSearching to true, result is same ast test3.

On Wed, Aug 9, 2017 at 10:03 AM, Bee-Lindgren, Bert <> wrote:

Hello,

GRP-1588 was created to describe the problem when searching for groups by their DN/EntryDn/DistinguishedName attribute when the DNs contain escaped characters.

This was resolved by PSPNG Patch #15.

While this patch should start working and populating memberships, I would suggest that you consider searching for groups by gidNumber (or cn, if they're unique) so that modified groups (folder change) do not cause deletion of the old group (by an authoritative full sync) and creation of a new one in the new OU.

Sincerely,

  Bert Bee-Lindgren

---

From: Julio Macavilca <>
Sent: Wednesday, August 2, 2017 12:12 PM
To: Bee-Lindgren, Bert
Cc: Grouper Users
Subject: Re: [grouper-users] Re: PSPNG issue

 

Thank you Bert.  I do see improvements and can confirm the group gets created in LDAP with the escape characters but it is shortly followed by an "LDAP: error code 68 - Entry Already Exists" and the members are not added.  I tried creating a group without characters that require escaping and it goes through fine.

2017-08-02 11:15:52,373: [DefaultQuartzScheduler_Worker-9] INFO  EventLog.info(156) -  - [789f520b467b4d648b704674947e6f6b,'GrouperSystem','application'] session: start (3ms)

2017-08-02 11:15:52,378: [DefaultQuartzScheduler_Worker-8] INFO  EventLog.info(156) -  - [7b4ab6d2d4024d7eb2c7eb82d0755a1b,'GrouperSystem','application'] session: start (2ms)

2017-08-02 11:15:52,384: [DefaultQuartzScheduler_Worker-8] INFO  EventLog.info(156) -  - [72c1c4856fdb4cda951a40a2f165213a,'GrouperSystem','application'] session: start (2ms)

2017-08-02 11:15:52,418: [DefaultQuartzScheduler_Worker-2] INFO  LdapGroupProvisioner.createGroup(299) -  - Creating LDAP group for GrouperGroup: test:This_-_is_Not,_Vanilla 

2017-08-02 11:15:52,423: [DefaultQuartzScheduler_Worker-9] INFO  ProvisioningWorkItem.setStatus(143) -  - Work item handled: ProvisioningWorkItem[successful=true,msg=Ignoring work item because group is not provisioned,clog=clog #347647 / ChangeLog type: membership: addMembership,group=test:This_-_is_Not,_Vanilla,subject=tst91@nyuperson]

2017-08-02 11:15:52,424: [DefaultQuartzScheduler_Worker-9] INFO  Provisioner.provisionBatchOfItems(1362) -  - pspng_groupOfNames: 1 work items need to be processed futher

2017-08-02 11:15:52,425: [DefaultQuartzScheduler_Worker-9] INFO  ProvisioningWorkItem.setStatus(143) -  - Work item handled: ProvisioningWorkItem[successful=true,msg=Nothing to do (not a supported change),clog=clog #347646 / ChangeLog type: privilege: addPrivilege]

2017-08-02 11:15:52,426: [DefaultQuartzScheduler_Worker-9] INFO  PspChangelogConsumerShim.processChangeLogEntries(113) -  - Provisioning summary: 

2017-08-02 11:15:52,555: [DefaultQuartzScheduler_Worker-8] INFO  EventLog.info(156) -  - [4bea4d29b507434bbcf01fb52cd5599a,'GrouperSystem','application'] session: start (3ms)

2017-08-02 11:15:52,598: [DefaultQuartzScheduler_Worker-8] INFO  ProvisioningWorkItem.setStatus(143) -  - Work item handled: ProvisioningWorkItem[successful=true,msg=Ignoring work item because group is not provisioned,clog=clog #347647 / ChangeLog type: membership: addMembership,group=test:This_-_is_Not,_Vanilla,subject=tst91@nyuperson]

2017-08-02 11:15:52,600: [DefaultQuartzScheduler_Worker-8] INFO  Provisioner.provisionBatchOfItems(1362) -  - pspng_activedirectory: 2 work items need to be processed futher

2017-08-02 11:15:52,602: [DefaultQuartzScheduler_Worker-8] INFO  ProvisioningWorkItem.setStatus(143) -  - Work item handled: ProvisioningWorkItem[successful=true,msg=Nothing to do (not a supported change),clog=clog #347645 / ChangeLog type: member: addMember,subject=b1135d924da44c47b8158355292d4859@g:gsa]

2017-08-02 11:15:52,604: [DefaultQuartzScheduler_Worker-8] INFO  ProvisioningWorkItem.setStatus(143) -  - Work item handled: ProvisioningWorkItem[successful=true,msg=Nothing to do (not a supported change),clog=clog #347646 / ChangeLog type: privilege: addPrivilege]

2017-08-02 11:15:52,605: [DefaultQuartzScheduler_Worker-8] INFO  PspChangelogConsumerShim.processChangeLogEntries(113) -  - Provisioning summary: 

2017-08-02 11:15:52,641: [DefaultQuartzScheduler_Worker-2] INFO  LdapProvisioner.performLdapAdd(722) -  - pspng_ldap: Creating LDAP object: cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu

2017-08-02 11:15:52,644: [DefaultQuartzScheduler_Worker-2] INFO  LdapSystem.performLdapAdd(329) -  - enterpriseldap: Creating LDAP object: cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu

2017-08-02 11:15:53,112: [DefaultQuartzScheduler_Worker-4] INFO  EventLog.info(156) -  - [c207d011bb0e4e71b3f34bf1b57c7a08,'GrouperSystem','application'] session: start (3ms)

2017-08-02 11:15:53,152: [DefaultQuartzScheduler_Worker-2] INFO  ProvisioningWorkItem.setStatus(143) -  - Work item handled: ProvisioningWorkItem[successful=true,msg=Group test:This_-_is_Not,_Vanilla already exists,clog=clog #347644 / ChangeLog type: group: addGroup,group=test:This_-_is_Not,_Vanilla]

2017-08-02 11:15:53,154: [DefaultQuartzScheduler_Worker-2] INFO  ProvisioningWorkItem.setStatus(143) -  - Work item handled: ProvisioningWorkItem[successful=true,msg=Nothing to do (not a supported change),clog=clog #347645 / ChangeLog type: member: addMember,subject=b1135d924da44c47b8158355292d4859@g:gsa]

2017-08-02 11:15:53,156: [DefaultQuartzScheduler_Worker-2] INFO  ProvisioningWorkItem.setStatus(143) -  - Work item handled: ProvisioningWorkItem[successful=true,msg=Nothing to do (not a supported change),clog=clog #347646 / ChangeLog type: privilege: addPrivilege]

2017-08-02 11:15:53,157: [DefaultQuartzScheduler_Worker-2] INFO  PspChangelogConsumerShim.processChangeLogEntries(113) -  - Provisioning summary: 

2017-08-02 11:15:53,279: [DefaultQuartzScheduler_Worker-1] INFO  EventLog.info(156) -  - [fb95c3dd8b3544b0a95a1dfba7183c1e,'GrouperSystem','application'] session: start (2ms)

2017-08-02 11:15:53,546: [DefaultQuartzScheduler_Worker-7] INFO  EventLog.info(156) -  - [e05ef8d960ce4f9dbba87b0276358203,'GrouperSystem','application'] session: start (3ms)

2017-08-02 11:15:53,624: [DefaultQuartzScheduler_Worker-7] INFO  PspChangelogConsumerShim.processChangeLogEntries(52) -  - pspng_ldap: +processChangeLogEntries(1)

2017-08-02 11:15:53,625: [DefaultQuartzScheduler_Worker-7] INFO  Provisioner.flushCachesIfNecessary(1434) -  - pspng_ldap: Keeping caches in tact for provisioning batch

2017-08-02 11:15:53,633: [DefaultQuartzScheduler_Worker-7] INFO  EventLog.info(156) -  - [c7a187c0748c4701899b42e591ca2e19,'GrouperSystem','application'] session: start (1ms)

2017-08-02 11:15:53,638: [DefaultQuartzScheduler_Worker-7] INFO  EventLog.info(156) -  - [6fe1626a7ebb4dde92fb4ef696c3b3bc,'GrouperSystem','application'] session: start (1ms)

2017-08-02 11:15:53,772: [DefaultQuartzScheduler_Worker-7] INFO  EventLog.info(156) -  - [596605cd18844d3ba9a273c88ac06717,'GrouperSystem','application'] session: start (2ms)

2017-08-02 11:15:53,809: [DefaultQuartzScheduler_Worker-7] INFO  Provisioner.provisionBatchOfItems(1362) -  - pspng_ldap: 1 work items need to be processed futher

2017-08-02 11:15:54,111: [DefaultQuartzScheduler_Worker-6] INFO  EventLog.info(156) -  - [a6931e88591d4d999e38c3ad9ba0cfa4,'GrouperSystem','application'] session: start (3ms)

2017-08-02 11:15:54,278: [DefaultQuartzScheduler_Worker-5] INFO  EventLog.info(156) -  - [a3d5a1680efe401587c447878fcfebd5,'GrouperSystem','application'] session: start (2ms)

2017-08-02 11:15:54,425: [DefaultQuartzScheduler_Worker-7] INFO  LdapGroupProvisioner.createGroup(299) -  - Creating LDAP group for GrouperGroup: test:This_-_is_Not,_Vanilla 

2017-08-02 11:15:54,615: [DefaultQuartzScheduler_Worker-7] INFO  LdapProvisioner.performLdapAdd(722) -  - pspng_ldap: Creating LDAP object: cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu

2017-08-02 11:15:54,617: [DefaultQuartzScheduler_Worker-7] INFO  LdapSystem.performLdapAdd(329) -  - enterpriseldap: Creating LDAP object: cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu

2017-08-02 11:15:54,664: [DefaultQuartzScheduler_Worker-7] ERROR LdapSystem.performLdapAdd(337) -  - Problem while creating new ldap object: [dn=cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu[[description[]], [objectclass[groupOfNames]]]]

[org.ldaptive.LdapException@2414009::resultCode=ENTRY_ALREADY_EXISTS, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, message=javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu', providerException=javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu']

        at org.ldaptive.provider.ProviderUtils.throwOperationException(ProviderUtils.java:55)

        at org.ldaptive.provider.jndi.JndiConnection.processNamingException(JndiConnection.java:619)

        at org.ldaptive.provider.jndi.JndiConnection.add(JndiConnection.java:326)

        at edu.internet2.middleware.grouper.pspng.LdapSystem.performLdapAdd(LdapSystem.java:335)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:725)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:340)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:47)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:749)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:475)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1373)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$5.runJob(GrouperLoaderType.java:717)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:423)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:323)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

Caused by: javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu'

        at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3083)

        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:3034)

        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2841)

        at com.sun.jndi.ldap.LdapCtx.c_createSubcontext(LdapCtx.java:812)

        at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_createSubcontext(ComponentDirContext.java:337)

        at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.createSubcontext(PartialCompositeDirContext.java:266)

        at org.ldaptive.provider.jndi.JndiConnection.add(JndiConnection.java:315)

        ... 14 more

2017-08-02 11:15:54,681: [DefaultQuartzScheduler_Worker-7] ERROR LdapGroupProvisioner.createGroup(346) -  - Problem while creating new group: dn: cn=This_-_is_Not\,_Vanilla,ou=ad,ou=pspngtest,ou=app

objectclass: groupOfNames

description: 

edu.internet2.middleware.grouper.pspng.PspException: LDAP problem creating object: javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu'

        at edu.internet2.middleware.grouper.pspng.LdapSystem.performLdapAdd(LdapSystem.java:338)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:725)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:340)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:47)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:749)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:475)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1373)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$5.runJob(GrouperLoaderType.java:717)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:423)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:323)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

2017-08-02 11:15:54,684: [DefaultQuartzScheduler_Worker-7] ERROR Provisioner.provisionBatchOfItems(1376) -  - Unable to begin the provisioning batch

edu.internet2.middleware.grouper.pspng.PspException: LDAP problem creating object: javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=test,o=nyu.edu,o=nyu'

        at edu.internet2.middleware.grouper.pspng.LdapSystem.performLdapAdd(LdapSystem.java:338)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:725)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:340)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:47)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:749)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:475)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1373)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$5.runJob(GrouperLoaderType.java:717)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:423)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:323)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

2017-08-02 11:15:54,686: [DefaultQuartzScheduler_Worker-7] ERROR ChangeLogHelper.processRecords(255) -  - Error

java.lang.RuntimeException: No entries provisioned. Batch-Start failed: LDAP problem creating object: javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=ad,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu'

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1378)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$5.runJob(GrouperLoaderType.java:717)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:423)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:323)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

Caused by: edu.internet2.middleware.grouper.pspng.PspException: LDAP problem creating object: javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=ad,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu'

        at edu.internet2.middleware.grouper.pspng.LdapSystem.performLdapAdd(LdapSystem.java:338)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:725)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:340)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:47)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:749)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:475)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1373)

        ... 7 more

2017-08-02 11:15:54,702: [DefaultQuartzScheduler_Worker-7] ERROR ChangeLogHelper.processRecords(286) -  - Did not get all the way through the batch! -1 != 347647

2017-08-02 11:15:54,703: [DefaultQuartzScheduler_Worker-7] ERROR GrouperLoaderJob.runJob(443) -  - Error on job: CHANGE_LOG_consumer_pspng_ldap

java.lang.RuntimeException: Error in loader job: null, check logs: Error: java.lang.RuntimeException: No entries provisioned. Batch-Start failed: LDAP problem creating object: javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=ad,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu'

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1378)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$5.runJob(GrouperLoaderType.java:717)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:423)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:323)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

Caused by: edu.internet2.middleware.grouper.pspng.PspException: LDAP problem creating object: javax.naming.NameAlreadyBoundException: [LDAP: error code 68 - Entry Already Exists]; remaining name 'cn=This_-_is_Not\,_Vanilla,ou=ad,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu'

        at edu.internet2.middleware.grouper.pspng.LdapSystem.performLdapAdd(LdapSystem.java:338)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:725)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:340)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:47)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:749)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:475)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1373)

        ... 7 more

Did not get all the way through the batch! -1 != 347647

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:432)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:323)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

On Tue, Aug 1, 2017 at 9:49 PM, Bee-Lindgren, Bert <> wrote:

Hello,

PSPNG 2.3 Patch 14 addresses a gap in Patch 13's RDN escaping. Please let us know if you see improvements!

Thanks much,

  Bert

---

From: Julio Macavilca <>
Sent: Tuesday, August 1, 2017 12:22 PM
To: Bee-Lindgren, Bert
Cc: Grouper Users
Subject: Re: [grouper-users] Re: PSPNG issue

 

I saw that pspgn 2.3.0 patch 13 (GRP-1533) was recently released (many thanks for this!) so I've patched to:

grouper_v2_3_0_api_patch_71 and grouper_v2_3_0_pspng_patch_13 and tested out but I am still seeing the same behavior.  My config is:

changeLog.consumer.pspng_ldap.allGroupsSearchFilter = objectclass=groupOfNames
changeLog.consumer.pspng_ldap.groupCreationLdifTemplate = dn: ${utils.bushyDn(grouper.name, "cn", "ou")}||objectclass: groupOfNames||description: ${group.description}
changeLog.consumer.pspng_ldap.singleGroupSearchFilter = (&(objectclass=groupOfNames)(entryDN=${utils.bushyDn(group.name, "cn", "ou")},ou=nyu,ou=Groups,o=nyu.edu,o=nyu))

And the output in the log says:

Caused by: edu.internet2.middleware.grouper.pspng.PspException: Unable to find existing OU nor create new one (Problem during LDAP read: javax.naming.InvalidNameException: ou=regular,ou=School_of_Culture,_Education,_Human_Development,ou=test,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name 'ou=regular,ou=School_of_Culture,_Education,_Human_Development,ou=test,o=nyu.edu,o=nyu')

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.ensureLdapOusExist(LdapProvisioner.java:688)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:724)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:340)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:47)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:740)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:475)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1364)

        ... 7 more

Did not get all the way through the batch! -1 != 346592]

thanks,

Julio

On Tue, Jun 27, 2017 at 12:31 PM, Bee-Lindgren, Bert <> wrote:

Hello,

This is my current task, and I should have the DN/RDN part of it patched this week. In other words, cn=${group.name},ou=groups,dc=example,dc=edu will work even for a group with commas/plusses/etc in its name.

I'm keeping the Jira updated as I go.

Thanks,

  Bert

---

From: <> on behalf of Julio Macavilca <>
Sent: Wednesday, June 21, 2017 12:11 PM
To: Grouper Users
Subject: [grouper-users] Re: PSPNG issue

 

Hi folks,

Just resurfacing this issue, I'm aware that the Jira was created (https://bugs.internet2.edu/jira/browse/GRP-1533) back in April and wanted to see if there was an update.  We'd like to run the PSPNG in prod but this is preventing us from going forward with it.

many thanks,

Julio

On Mon, Apr 17, 2017 at 3:17 PM, Julio Macavilca <> wrote:

Hi, 

Bumping this up.  We came across this bug because while running a loader job coming from a system of records, the PSPNG became "stuck".  The name of the groups that would trigger this behavior all had commas there and I was then able to reproduce this by creating them manually.

thanks,

Julio

On Thu, Feb 23, 2017 at 1:30 PM, Julio Macavilca <> wrote:

Hi folks,

I am testing the PSPNG in dev environment running pspng patch 7.  When creating a group or stem with a name that includes a comma I am seeing that the changelog consumer becomes stuck when provisioning to LDAP.  After looking at the logs the dn looks malformed whereas using the PSP we have similar ones but it includes the escape character in the dn so it doesn't cause an LDAP error 34.

thanks,

Julio

Name:	This_-_is_My,_Test
Path:	app:pspngtest:This_-_is_My,_Test
ID path:	app:pspngtest:This_-_is_My,_Test
Alternate ID path:
ID:	This_-_is_My,_Test
Created:	Thu Feb 23 1:09:24 PM EST 2017

2017-02-23 13:09:51,375: [DefaultQuartzScheduler_Worker-1] INFO  PspChangelogConsumerShim.processChangeLogEntries(52) -  - pspng_activedirectory: +processChangeLogEntries(2)

2017-02-23 13:09:51,376: [DefaultQuartzScheduler_Worker-1] INFO  ProvisionerFactory.createProvisionerWithName(80) -  - Constructing provisioner: pspng_activedirectory

2017-02-23 13:09:51,416: [DefaultQuartzScheduler_Worker-2] INFO  EventLog.info(156) -  - [dbd228ec52b04b1dbb98aaedef378dfb,'GrouperSystem','application'] session: start (1ms)

2017-02-23 13:09:51,437: [DefaultQuartzScheduler_Worker-1] INFO  EventLog.info(156) -  - [9f5124c4b49d4247bc0d8aacbf2105dc,'GrouperSystem','application'] session: start (1ms)

2017-02-23 13:09:51,466: [DefaultQuartzScheduler_Worker-2] INFO  EventLog.info(156) -  - [3157a17bd1c0433c8fb6cefb4a191ee8,'GrouperSystem','application'] session: start (1ms)

2017-02-23 13:09:51,557: [DefaultQuartzScheduler_Worker-2] INFO  EventLog.info(156) -  - [7db294383c8340c58b14b5d02ec19576,'GrouperSystem','application'] session: start (2ms)

2017-02-23 13:09:51,570: [DefaultQuartzScheduler_Worker-1] INFO  EhcacheController.getCache(200) -  - cache not configured explicitly: PSP-pspng_activedirectory-GrouperGroupInfoCache, to override default values, configure in the resource /grouper.cache.base.properties and /grouper.cache.properties.  Default values are:maxElementsInMemory: 10000, eternal: false, timeToIdleSeconds: 600, timeToLiveSeconds: 600, overFlowToDisk: false

2017-02-23 13:09:51,572: [DefaultQuartzScheduler_Worker-1] INFO  EhcacheController.getCache(200) -  - cache not configured explicitly: PSP-pspng_activedirectory-GrouperSubjectCache, to override default values, configure in the resource /grouper.cache.base.properties and /grouper.cache.properties.  Default values are:maxElementsInMemory: 10000, eternal: false, timeToIdleSeconds: 600, timeToLiveSeconds: 600, overFlowToDisk: false

2017-02-23 13:09:51,573: [DefaultQuartzScheduler_Worker-1] INFO  EhcacheController.getCache(200) -  - cache not configured explicitly: PSP-pspng_activedirectory-TargetSystemUserCache, to override default values, configure in the resource /grouper.cache.base.properties and /grouper.cache.properties.  Default values are:maxElementsInMemory: 10000, eternal: false, timeToIdleSeconds: 600, timeToLiveSeconds: 600, overFlowToDisk: false

2017-02-23 13:09:51,575: [DefaultQuartzScheduler_Worker-1] INFO  EhcacheController.getCache(200) -  - cache not configured explicitly: PSP-pspng_activedirectory-TargetSystemGroupCache, to override default values, configure in the resource /grouper.cache.base.properties and /grouper.cache.properties.  Default values are:maxElementsInMemory: 10000, eternal: false, timeToIdleSeconds: 600, timeToLiveSeconds: 600, overFlowToDisk: false

2017-02-23 13:09:51,576: [DefaultQuartzScheduler_Worker-1] INFO  EhcacheController.getCache(200) -  - cache not configured explicitly: PSP-pspng_activedirectory-LdapUserCache, to override default values, configure in the resource /grouper.cache.base.properties and /grouper.cache.properties.  Default values are:maxElementsInMemory: 10000, eternal: false, timeToIdleSeconds: 600, timeToLiveSeconds: 600, overFlowToDisk: false

2017-02-23 13:09:51,578: [DefaultQuartzScheduler_Worker-1] INFO  ProvisionerFactory.createProvisionerWithName(80) -  - Constructing provisioner: pspng_activedirectory

2017-02-23 13:09:51,587: [DefaultQuartzScheduler_Worker-2] INFO  ProvisioningWorkItem.getSubjectId(201) -  - Not a supported change for finding subject (not MEMBERSHIP_ADD nor MEMBERSHIP_DELETE): ChangeLog type: group: addGroup

2017-02-23 13:09:51,591: [DefaultQuartzScheduler_Worker-2] INFO  ProvisioningWorkItem.getSubjectSourceId(225) -  - Not a supported change for finding subject (not MEMBERSHIP_ADD nor MEMBERSHIP_DELETE): ChangeLog type: group: addGroup

2017-02-23 13:09:51,674: [pspng_activedirectory-FullSync] INFO  EventLog.info(156) -  - [4e69be2f9f1d4f18a9855299ed4efd9b,'GrouperSystem','application'] session: start (3ms)

2017-02-23 13:09:51,692: [DefaultQuartzScheduler_Worker-1] INFO  EventLog.info(156) -  - [5d3ed92061e44293bea0c15cc3b82467,'GrouperSystem','application'] session: start (1ms)

2017-02-23 13:09:51,781: [DefaultQuartzScheduler_Worker-1] INFO  EventLog.info(156) -  - [24d06f83d7684a6090fd342b3025dc62,'GrouperSystem','application'] session: start (2ms)

2017-02-23 13:09:51,849: [DefaultQuartzScheduler_Worker-1] INFO  Provisioner.getAllGroupsForProvisioner(1163) -  - pspng_activedirectory: There are 0 folders that match etc:pspng:provision_to attribute

2017-02-23 13:09:51,850: [DefaultQuartzScheduler_Worker-1] INFO  Provisioner.getAllGroupsForProvisioner(1164) -  - pspng_activedirectory: There are 0 groups that match etc:pspng:provision_to attribute

2017-02-23 13:09:51,969: [DefaultQuartzScheduler_Worker-1] INFO  Provisioner.getAllGroupsForProvisioner(1163) -  - pspng_activedirectory: There are 0 folders that match etc:pspng:do_not_provision_to attribute

2017-02-23 13:09:51,970: [DefaultQuartzScheduler_Worker-1] INFO  Provisioner.getAllGroupsForProvisioner(1164) -  - pspng_activedirectory: There are 0 groups that match etc:pspng:do_not_provision_to attribute

2017-02-23 13:09:51,971: [DefaultQuartzScheduler_Worker-1] INFO  Provisioner.flushCachesIfNecessary(1346) -  - pspng_activedirectory: Keeping caches in tact for provisioning batch

2017-02-23 13:09:51,981: [DefaultQuartzScheduler_Worker-2] INFO  LdapGroupProvisioner.createGroup(251) -  - Creating LDAP group for GrouperGroup: app:pspngtest:This_-_is_My,_Test  

2017-02-23 13:09:52,060: [DefaultQuartzScheduler_Worker-1] INFO  EventLog.info(156) -  - [16d7c162c83549cf89a7537c6ef2ae72,'GrouperSystem','application'] session: start (2ms)

2017-02-23 13:09:52,098: [DefaultQuartzScheduler_Worker-1] INFO  ProvisioningWorkItem.getSubjectId(201) -  - Not a supported change for finding subject (not MEMBERSHIP_ADD nor MEMBERSHIP_DELETE): ChangeLog type: group: addGroup

2017-02-23 13:09:52,099: [DefaultQuartzScheduler_Worker-1] INFO  ProvisioningWorkItem.setStatus(125) -  - Not a supported change for finding subject (not MEMBERSHIP_ADD nor MEMBERSHIP_DELETE): ChangeLog type: group: addGroup

2017-02-23 13:09:52,100: [DefaultQuartzScheduler_Worker-1] INFO  ProvisioningWorkItem.setStatus(125) -  - Work item done: ProvisioningWorkItem[successful=true,msg=Ignoring work item ProvisioningWorkItem[successful=true,clog=clog #285000 / ChangeLog type: group: addGroup,group=app:pspngtest:This_-_is_My,_Test ] because group app:pspngtest:This_-_is_My,_Test  is not provisioned,clog=clog #285000 / ChangeLog type: group: addGroup,group=app:pspngtest:This_-_is_My,_Test ]

2017-02-23 13:09:52,101: [DefaultQuartzScheduler_Worker-1] INFO  ProvisioningWorkItem.getSubjectId(201) -  - Not a supported change for finding subject (not MEMBERSHIP_ADD nor MEMBERSHIP_DELETE): ChangeLog type: group: addGroup

2017-02-23 13:09:52,102: [DefaultQuartzScheduler_Worker-1] INFO  ProvisioningWorkItem.getSubjectSourceId(225) -  - Not a supported change for finding subject (not MEMBERSHIP_ADD nor MEMBERSHIP_DELETE): ChangeLog type: group: addGroup

2017-02-23 13:09:52,109: [DefaultQuartzScheduler_Worker-2] INFO  LdapProvisioner.performLdapAdd(628) -  - pspng_groupOfNames: Creating LDAP object: cn=This_-_is_My,_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu

2017-02-23 13:09:52,136: [DefaultQuartzScheduler_Worker-2] ERROR LdapSystem.performLdapRead(387) -  - Problem during ldap read _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu

[org.ldaptive.LdapException@27941234::resultCode=INVALID_DN_SYNTAX, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, message=javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu', providerException=javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu']

        at org.ldaptive.provider.ProviderUtils.throwOperationException(ProviderUtils.java:55)

        at org.ldaptive.provider.jndi.JndiConnection.processNamingException(JndiConnection.java:619)

        at org.ldaptive.provider.jndi.JndiConnection$JndiSearchIterator.initialize(JndiConnection.java:741)

        at org.ldaptive.provider.jndi.JndiConnection.search(JndiConnection.java:463)

        at org.ldaptive.SearchOperation.executeSearch(SearchOperation.java:103)

        at org.ldaptive.SearchOperation.invoke(SearchOperation.java:85)

        at org.ldaptive.SearchOperation.invoke(SearchOperation.java:15)

        at org.ldaptive.AbstractOperation.execute(AbstractOperation.java:126)

        at edu.internet2.middleware.grouper.pspng.LdapSystem.performLdapRead(LdapSystem.java:372)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.ensureLdapOusExist(LdapProvisioner.java:585)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:630)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:269)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:54)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:715)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:468)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1285)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:652)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:418)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:318)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

Caused by: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu'

        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:3026)

        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2841)

        at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1850)

        at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1773)

        at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:386)

        at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:356)

        at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:339)

        at org.ldaptive.provider.jndi.JndiConnection$JndiSearchIterator.search(JndiConnection.java:806)

        at org.ldaptive.provider.jndi.JndiConnection$JndiSearchIterator.initialize(JndiConnection.java:735)

        ... 20 more

2017-02-23 13:09:52,146: [DefaultQuartzScheduler_Worker-2] ERROR LdapProvisioner.ensureLdapOusExist(593) -  - pspng_groupOfNames: Unable to find existing OU (_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu)

edu.internet2.middleware.grouper.pspng.PspException: Problem during LDAP read: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu'

        at edu.internet2.middleware.grouper.pspng.LdapSystem.performLdapRead(LdapSystem.java:388)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.ensureLdapOusExist(LdapProvisioner.java:585)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:630)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:269)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:54)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:715)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:468)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1285)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:652)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:418)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:318)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

2017-02-23 13:09:52,149: [DefaultQuartzScheduler_Worker-2] ERROR LdapGroupProvisioner.createGroup(275) -  - Problem while creating new group: dn: cn=This_-_is_My,_Test ,ou=pspngtest,ou=app

objectclass: groupOfNames

description: 

gidNumber: 15066

objectclass: posixGroup

edu.internet2.middleware.grouper.pspng.PspException: Unable to find existing OU nor create new one (Problem during LDAP read: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu')

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.ensureLdapOusExist(LdapProvisioner.java:594)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:630)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:269)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:54)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:715)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:468)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1285)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:652)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:418)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:318)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

2017-02-23 13:09:52,152: [DefaultQuartzScheduler_Worker-2] ERROR Provisioner.provisionBatchOfItems(1288) -  - Unable to begin the provisioning batch

edu.internet2.middleware.grouper.pspng.PspException: Unable to find existing OU nor create new one (Problem during LDAP read: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu')

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.ensureLdapOusExist(LdapProvisioner.java:594)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:630)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:269)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:54)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:715)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:468)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1285)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:652)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:418)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:318)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

2017-02-23 13:09:52,155: [DefaultQuartzScheduler_Worker-2] ERROR ChangeLogHelper.processRecords(255) -  - Error

java.lang.RuntimeException: No entries provisioned. Batch-Start failed: Unable to find existing OU nor create new one (Problem during LDAP read: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu')

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1290)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:652)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:418)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:318)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

Caused by: edu.internet2.middleware.grouper.pspng.PspException: Unable to find existing OU nor create new one (Problem during LDAP read: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu')

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.ensureLdapOusExist(LdapProvisioner.java:594)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:630)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:269)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:54)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:715)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:468)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1285)

        ... 7 more

2017-02-23 13:09:52,160: [DefaultQuartzScheduler_Worker-2] ERROR ChangeLogHelper.processRecords(286) -  - Did not get all the way through the batch! -1 != 285001

2017-02-23 13:09:52,161: [DefaultQuartzScheduler_Worker-2] ERROR GrouperLoaderJob.runJob(438) -  - Error on job: CHANGE_LOG_consumer_pspng_groupOfNames

java.lang.RuntimeException: Error in loader job: null, check logs: Error: java.lang.RuntimeException: No entries provisioned. Batch-Start failed: Unable to find existing OU nor create new one (Problem during LDAP read: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu')

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1290)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:652)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:418)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:318)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

Caused by: edu.internet2.middleware.grouper.pspng.PspException: Unable to find existing OU nor create new one (Problem during LDAP read: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu')

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.ensureLdapOusExist(LdapProvisioner.java:594)

        at edu.internet2.middleware.grouper.pspng.LdapProvisioner.performLdapAdd(LdapProvisioner.java:630)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:269)

        at edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner.createGroup(LdapGroupProvisioner.java:54)

        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareGroupCache(Provisioner.java:715)

        at edu.internet2.middleware.grouper.pspng.Provisioner.startProvisioningBatch(Provisioner.java:468)

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1285)

        ... 7 more

Did not get all the way through the batch! -1 != 285001

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:427)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:318)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

2017-02-23 13:09:52,189: [DefaultQuartzScheduler_Worker-2] ERROR GrouperLoaderJob.execute(321) -  - Error running up job

java.lang.RuntimeException: Error in loader job: null, check logs: Error: java.lang.RuntimeException: No entries provisioned. Batch-Start failed: Unable to find existing OU nor create new one (Problem during LDAP read: javax.naming.InvalidNameException: _Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu: [LDAP: error code 34 - Invalid DN]; remaining name '_Test ,ou=pspngtest,ou=app,ou=nyu,ou=Groups,o=nyu.edu,o=nyu')

        at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1290)

        at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:71)

        at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:652)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:418)

        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:318)

        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)

        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)