Grouper Users - Open Discussion List

["Bee-Lindgren, Bert" <>]

Jeffrey,

[Outdated paragraph asking for more logs (see below)... but I'm keeping it here as it maybe helpful.]

I appreciate your details, and I'll work on duplicating this. In the meantime, can you tweak your log4j settings as follows and then share an INFO level log the problem.

Add %X{why}%X{who}%X{what}%X{step}  before the '%x - %m' part of your message format. For example,

ConversionPattern  = %d{ISO8601}: %X{pspng.threadid} [%t] %-5p [%c{1}] %X{why}%X{who}%X{what}%X{step} - %x - %m%n

I also have some questions as I try to isolate this problem. Does this rewrite of your description look correct:

Long term, stable:

ucla:app:cmp-vpn:entitlement [Group, provision_to=pspng_entitlement]

Created:

ucla:app:cmp-vpn:group:its:etc [Folder, no pspng settings]

ucla:app:cmp-vpn:group:its:etc:auto [Group, no pspng settings]

Deleted:

ucla:app:cmp-vpn:group:its:etc:auto [Group, never provisioned of course]

Provisioning of ucla:app:cmp-vpn:entitlement is wiped out.

I've re-re-read your report, and, yes, I think the problem has to do with the static attribute-value-format because the quick group-was-deleted check actually finds attributes provisioned for the never-selected-for-provisioning, deleted group, because _all_ groups have the same attribute! I thought group-selection problems were limited to performance and log-noise and, therefore, could wait until pspng was using the new attribute values, but this is too big a problem to wait.

I'm working on this now.

Sincerely,

  Bert

---

From: <> on behalf of Crawford, Jeffrey <>
Sent: Tuesday, August 13, 2019 4:49 PM
To: Grouper Users <>
Subject: Re: [grouper-users] Had a mass attribute delete this morning in production pspng

 

I was just able to reproduce this in test, which is on pspng patch 8

 

I have a group that has provision_to=pspng_entitlement “ucla:app:cmp-vpn:entitlement”

 

I then created a folder and group “ucla:app:cmp-vpn:group:its:etc:auto”

 

I then deleted the “:etc:auto” folder and group which is outside the provision_to folder

 

It triggered the same update we saw in prod and started removing attributes from groups that are still populated. However in test the attribute removed seem more random. Again simply scheduling the FullSyncer on that config, corrects the attribute. There was no change in group memberships in the few minutes between the removal and full sync.

 

Jeffrey C.

 

From: <> on behalf of "Crawford, Jeffrey" <>
Reply-To: "Crawford, Jeffrey" <>
Date: Tuesday, August 13, 2019 at 12:30 PM
To: Grouper Users <>
Subject: [grouper-users] Had a mass attribute delete this morning in production pspng

 

Hello,

 

We just recovered from a pretty strange occurrence and it might be a bug. I was working in an area of grouper we were setting up for a new service, I created a folder and a group, then decided it would fit better somewhere else. I deleted the newly created folder and group and the grouper-loader started getting messages like the following:

 

2019-08-13 07:24:03,319: [DefaultQuartzScheduler_Worker-2] INFO  Provisioner.processIncrementalSyncEvent(1164) -  - pspng_iamucla_entl: Group has been deleted from grouper. Checking to see if it was provisioned to target system

pspng_iamucla_role: Group has been deleted from grouper. Checking to see if it was provisioned to target system

2019-08-13 07:24:03,460: [DefaultQuartzScheduler_Worker-3] INFO  Provisioner.processIncrementalSyncEvent(1164) -  - pspng_cisco_sparkeligible: Group has been deleted from grouper. Checking to see if it was provisioned to target system

…

 

After it had logged those messages I started to see:

2019-08-13 07:24:03,826: [DefaultQuartzScheduler_Worker-8] WARN  PspUtils.hibernateRefresh(305) -  - Unable to refresh object from database, probably because it has been deleted: Group[name=ucla:app:campus-vpn:group:its:etc:auto,uuid=4f2896570b1b40f69c8cb8

4151aa4804]

2019-08-13 07:24:03,830: [DefaultQuartzScheduler_Worker-2] INFO  LdapProvisioner.fetchTargetSystemUsers(141) -  - Read 50 user objects from directory

2019-08-13 07:24:03,831: [DefaultQuartzScheduler_Worker-3] INFO  LdapAttributeProvisioner.purgeAttributeValue(270) -  - pspng_cisco_sparkeligible: There are 373 ldap objects with attribute value=urn:mace:ucla.edu:entitlement:cisco-spark-eigible

2019-08-13 07:24:03,832: [DefaultQuartzScheduler_Worker-3] INFO  LdapAttributeProvisioner.scheduleUserModification(71) -  - Will change LDAP: REMOVE urn:mace:ucla.edu:entitlement:cisco-spark-eigible from eduPersonEntitlement of LdapUser[ldap=LdapObject[id=163533,dn=uclappid=urn:mace:ucla.edu:ppid:person:4d26f82dc42f4311bc8f8f7ed6f92db1,ou=people,dc=ucla,dc=edu,provisioner=LdapAttributeProvisioner[pspng_cisco_sparkeligible],attributesRequested=[dn]]]

2019-08-13 07:24:03,832: [DefaultQuartzScheduler_Worker-3] INFO  LdapProvisioner.scheduleLdapModification(263) -  - pspng_cisco_sparkeligible: Scheduling ldap modification: [org.ldaptive.ModifyRequest@926346189::modifyDn=uclappid=urn:mace:ucla.edu:ppid:person:4d26f82dc42f4311bc8f8f7ed6f92db1,ou=people,dc=ucla,dc=edu, attrMods=[[org.ldaptive.AttributeModification@227410408::attrMod=REMOVE, attribute=[eduPersonEntitlement[urn:mace:ucla.edu:entitlement:cisco-spark-eigible]]]], controls=null, referralHandler=null, intermediateResponseHandlers=null]

2019-08-13 07:24:03,832: [DefaultQuartzScheduler_Worker-3] INFO  LdapAttributeProvisioner.scheduleUserModification(71) -  - Will change LDAP: REMOVE urn:mace:ucla.edu:entitlement:cisco-spark-eigible from eduPersonEntitlement of LdapUser[ldap=LdapObject[id=163534,dn=uclappid=urn:mace:ucla.edu:ppid:person:569d56af316e4b2aa9443f86f1db009a,ou=people,dc=ucla,dc=edu,provisioner=LdapAttributeProvisioner[pspng_cisco_sparkeligible],attributesRequested=[dn]]]

2019-08-13 07:24:03,832: [DefaultQuartzScheduler_Worker-3] INFO  LdapProvisioner.scheduleLdapModification(263) -  - pspng_cisco_sparkeligible: Scheduling ldap modification: [org.ldaptive.ModifyRequest@365004994::modifyDn=uclappid=urn:mace:ucla.edu:ppid:person:569d56af316e4b2aa9443f86f1db009a,ou=people,dc=ucla,dc=edu, attrMods=[[org.ldaptive.AttributeModification@436588274::attrMod=REMOVE, attribute=[eduPersonEntitlement[urn:mace:ucla.edu:entitlement:cisco-spark-eigible]]]], controls=null, referralHandler=null, intermediateResponseHandlers=null]

 

However the above messages were in error since there were members in the group but pspng removed all of them. I later noticed that pspng configs that had variable group names and the provision_to attribute was assigned on a folder were all fine. However configs that were one to one attribute value to group mappings and had the provision_to attribute assigned to a group had the attributes all removed.

 

### The following configs that had variables in the name and are assigned to folders, remained untouched.:

changeLog.consumer.pspng_iamucla_entl.class = edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim

changeLog.consumer.pspng_iamucla_entl.type = edu.internet2.middleware.grouper.pspng.LdapAttributeProvisioner

changeLog.consumer.pspng_iamucla_entl.quartzCron = 0 * * * * ?

changeLog.consumer.pspng_iamucla_entl.retryOnError = true

changeLog.consumer.pspng_iamucla_entl.ldapPoolName = personLdap

changeLog.consumer.pspng_iamucla_entl.provisionedAttributeName = eduPersonEntitlement

changeLog.consumer.pspng_iamucla_entl.provisionedAttributeValueFormat = urn:mace:ucla.edu:${group.name.replaceFirst("ucla:iamucla:", "")}

changeLog.consumer.pspng_iamucla_entl.userSearchBaseDn = ou=people,dc=ucla,dc=edu

changeLog.consumer.pspng_iamucla_entl.userSearchFilter = uclaPPID=${subject.id}

changeLog.consumer.pspng_iamucla_entl.userSearchAttributes = dn,cn,uid,mail,samAccountName,uidNumber,objectClass,uclaPPID

 

### The following configs that have static names and are assigned directly to groups, had all the attributes removed:

changeLog.consumer.pspng_cisco_sparkeligible.class = edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim

changeLog.consumer.pspng_cisco_sparkeligible.type = edu.internet2.middleware.grouper.pspng.LdapAttributeProvisioner

changeLog.consumer.pspng_cisco_sparkeligible.quartzCron = 0 * * * * ?

changeLog.consumer.pspng_cisco_sparkeligible.retryOnError = true

changeLog.consumer.pspng_cisco_sparkeligible.ldapPoolName = personLdap

changeLog.consumer.pspng_cisco_sparkeligible.provisionedAttributeName = eduPersonEntitlement

changeLog.consumer.pspng_cisco_sparkeligible.provisionedAttributeValueFormat = urn:mace:ucla.edu:entitlement:cisco-spark-eigible

changeLog.consumer.pspng_cisco_sparkeligible.userSearchBaseDn = ou=people,dc=ucla,dc=edu

changeLog.consumer.pspng_cisco_sparkeligible.userSearchFilter = uclaPPID=${subject.id}

changeLog.consumer.pspng_cisco_sparkeligible.userSearchAttributes = dn,cn,uid,mail,samAccountName,uidNumber,objectClass,uclaPPID

 

I don’t know if the culprit is the static value in “AttributeValueFormat” or if it’s because those were assigned directly to groups and not folders. However that is the only two difference between them conceptually. I will note that our production is on pspng patch 3, and all of the other environments are on patch 8. We are scheduled to upgrade to patch 8 on Aug 27. So I’m not sure if this had been fixed already, but if not then I wanted to make sure I reported it.

 

I was able to fix the groups by configuring and running the FullSyncer:

#otherJob.<nameOfJob>_full.class = edu.internet2.middleware.grouper.pspng.FullSyncStarter

#otherJob.<nameOfJob>_full.quartzCron = 59 59 23 31 12 ? 2099

 

With the appropriate name and cron entry modified, I didn’t modify any group memberships between the attribute values being removed and running the FullSyncer.

 

Thanks

Jeffrey C.