pspng throws errors when folders are deleted

Andy Morgan(opens in new tab) 6 days ago
Running v2.4 container: One of users (okay, my boss!) deleted a folder via the UI and chose the "delete children" option. It was a folder with a handful of groups in it. The delete went okay from the UI perspective. It appears that some background delete jobs were running because the event log entries are spread out over the next 10 minutes. At the end, the folder/stem was deleted. Once the stem was deleted, pspng got stuck and threw this error:
java.lang.IllegalStateException: this should never happen: group has no parent stem: Can't find stem by uuid: 'ad00ff4c31474cdfa674024fca1e498b'

 

 

Andy Morgan(opens in new tab) 6 days ago
Note: these groups aren't actually provisioned via pspng, but it was still processing them as ignored work items. The groups inside this stem were large composites (several with 10s of thousands of members).

 

Chris Hyzer(opens in new tab) 6 days ago
can you skip them in change log consumer table?

 

Chris Hyzer(opens in new tab) 6 days ago
https://spaces.at.internet2.edu/display/Grouper/Change+log+consumers

 

Andy Morgan(opens in new tab) 6 days ago
The errors began at May 7 15:22:03 and the last ERROR was at May 8 02:56:01

 

Andy Morgan(opens in new tab) 6 days ago
I can't figure out how it got unstuck

 

Chris Hyzer(opens in new tab) 6 days ago
full sync?

 

Chris Hyzer(opens in new tab) 6 days ago
do you mind sending the full stack please and let know exactly which version you have (including latest patch numbers)

 

Andy Morgan(opens in new tab) 6 days ago
I don't know. Are those scheduled somewhere?

 

Chris Hyzer(opens in new tab) 6 days ago
otherjob for full sync

 

Andy Morgan(opens in new tab) 6 days ago
Stack trace of the first occurrence:

 

Andy Morgan(opens in new tab) 6 days ago
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-07 15:22:03,728: [DefaultQuartzScheduler_Worker-7] ERROR ChangeLogHelper.processRecords(255) - - Error
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: java.lang.IllegalStateException: this should never happen: group has no parent stem: Can't find stem by uuid: 'ad00ff4c31474cdfa674024fca1e498b',
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: Problem in HibernateSession: HibernateSession (6d689304): new, readonly, NONE, notActiveTransaction, session (null)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.Group.getParentStem(Group.java:3865)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.PspUtils.getStemAttributes(PspUtils.java:137)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.GrouperGroupInfo.getJexlMap(GrouperGroupInfo.java:134)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.Provisioner.getGroupJexlMap(Provisioner.java:1802)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.Provisioner.populateJexlMap(Provisioner.java:837)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.LdapProvisioner.populateJexlMap(LdapProvisioner.java:396)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.LdapProvisioner.populateJexlMap(LdapProvisioner.java:51)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.Provisioner.evaluateJexlExpression(Provisioner.java:733)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.Provisioner.shouldGroupBeProvisioned(Provisioner.java:1818)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.Provisioner.filterWorkItems(Provisioner.java:474)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.Provisioner.provisionBatchOfItems(Provisioner.java:1873)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim.processChangeLogEntries(PspChangelogConsumerShim.java:74)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:245)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$6.runJob(GrouperLoaderType.java:670)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:465)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:345)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: Caused by: edu.internet2.middleware.grouper.exception.StemNotFoundException: Can't find stem by uuid: 'ad00ff4c31474cdfa674024fca1e498b',
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: Problem in HibernateSession: HibernateSession (6d689304): new, readonly, NONE, notActiveTransaction, session (null)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3StemDAO.findByUuid(Hib3StemDAO.java:2233)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3StemDAO.findByUuid(Hib3StemDAO.java:1088)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.Group$11.callback(Group.java:3850)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3TransactionDAO$1.callback(Hib3TransactionDAO.java:66)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:703)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3TransactionDAO.transactionCallback(Hib3TransactionDAO.java:56)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.hibernate.GrouperTransaction.callbackGrouperTransaction(GrouperTransaction.java:87)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.Group.getParentStem(Group.java:3846)
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: #011... 17 more
May 7 15:22:03 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-07 15:22:03,729: [DefaultQuartzScheduler_Worker-7] ERROR ChangeLogHelper.processRecords(286) - - Did not get all the way through the batch! -1 != 38664373

 

Andy Morgan(opens in new tab) 6 days ago
Version is tier/grouper:2.4.0-a93-u56-w11-p12-20200310

 

Andy Morgan(opens in new tab) 6 days ago
This continues until this final error for that stem:
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-08 02:42:00,159: [DefaultQuartzScheduler_Worker-10] INFO PspChangelogConsumerShim.processChangeLogEntries(55) - - pspng_activedirectory: +processChangeLogEntries(1000)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-08 02:42:00,184: [DefaultQuartzScheduler_Worker-10] ERROR ChangeLogHelper.processRecords(255) - - Error
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: java.lang.NullPointerException
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-08 02:42:00,184: [DefaultQuartzScheduler_Worker-10] ERROR ChangeLogHelper.processRecords(286) - - Did not get all the way through the batch! -1 != 38664373
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-08 02:42:00,184: [DefaultQuartzScheduler_Worker-10] ERROR GrouperLoaderJob.runJob(485) - - Error on job: CHANGE_LOG_consumer_pspng_activedirectory
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: java.lang.RuntimeException: Error in loader job: null, check logs: Error: java.lang.NullPointerException
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: Did not get all the way through the batch! -1 != 38664373
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:474)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:345)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: #011at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: #011at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-08 02:42:00,187: [DefaultQuartzScheduler_Worker-10] ERROR GrouperLoaderJob.execute(348) - - Error running up job
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: java.lang.RuntimeException: Error in loader job: null, check logs: Error: java.lang.NullPointerException
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: Did not get all the way through the batch! -1 != 38664373
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:474)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: #011at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:345)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: #011at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: #011at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-08 02:42:00,206: [DefaultQuartzScheduler_Worker-6] INFO PspChangelogConsumerShim.processChangeLogEntries(55) - - pspng_ldap: +processChangeLogEntries(1000)
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-08 02:42:00,259: [DefaultQuartzScheduler_Worker-6] WARN Provisioner.getGroupInfo(1700) - - Could not find PIT group: osu:org:is:app:duo:duo-mandatory:stuman-reports:Enrolled student totals:0129-enrolled
May 8 02:42:00 grouper-be1 31aa7a6d66fc[570]: grouper-api;grouper_error.log;prod;prod;2020-05-08 02:42:00,269: [DefaultQuartzScheduler_Worker-6] WARN Provisioner.getGroupInfo(1700) - - Could not find PIT group: osu:org:is:app:duo:duo-mandatory:stuman-reports:Enrolled student totals:0129-enrolled

 

Andy Morgan(opens in new tab) 6 days ago
Followed by thousands of that "Could not find PIT group" warning

 

Andy Morgan(opens in new tab) 6 days ago
I have not configured a fullsync job for pspng.

 

Chris Hyzer(opens in new tab) 6 days ago
the obliterate call in UI had the checkbox for PIT delete checked right?

 

Andy Morgan(opens in new tab) 5 days ago
Good question... I'll see if I can query PIT to find this deleted stem

 

Andy Morgan(opens in new tab) 5 days ago
I can't find the group in PIT, so it is likely she chose to delete PIT records.

 

Andy Morgan(opens in new tab) 5 days ago
Is there some more elegant way the PSPNG can handle this condition?

 

Andy Morgan(opens in new tab) 5 days ago
Still, how did it get unstuck?

 

Andy Morgan(opens in new tab) 4 hours ago
Any thoughts about PSPNG handling missing PIT data? Can/should I file a bug for this? I don't know if that's something the project wants outsiders doing.