Grouper Users - Open Discussion List

[Jeffrey Crawford <>]

okay just found this at the end of the process, was very long so missed it, am I missing something simple? I have the following configs in the grouper-loader.properties file:

# Omit diff responses from bulk response to conserve memory.
changeLog.psp.fullSync.omitDiffResponses = true

# Omit sync responses from bulk response to conserve memory.
changeLog.psp.fullSync.omitSyncResponses = true


===========================================================
2015-09-20 01:06:36,084: [DefaultQuartzScheduler_Worker-2] ERROR Psp.execute(811) -  - Psp 'psp' - BulkSync BulkSyncResponse[id=<nul
l>,status=failure,error=<null>,errorMessages={},requestID=2015/09/20-01:00:00.032,responses=26044]
2015-09-20 01:06:46,200: [DefaultQuartzScheduler_Worker-2] ERROR GrouperLoaderJob.runJob(433) -  - Error on job: PSP_FULL_SYNC
java.lang.RuntimeException: Cant execute reflection method: fullSync, on: edu.internet2.middleware.psp.grouper.PspChangeLogConsumer,
 with args: null,
Problem calling method fullSync on edu.internet2.middleware.psp.grouper.PspChangeLogConsumer
        at edu.internet2.middleware.grouper.util.GrouperUtil.invokeMethod(GrouperUtil.java:4016)
        at edu.internet2.middleware.grouper.util.GrouperUtil.callMethod(GrouperUtil.java:3953)
        at edu.internet2.middleware.grouper.util.GrouperUtil.callMethod(GrouperUtil.java:4137)
        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$9.runJob(GrouperLoaderType.java:1063)
        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:413)
        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:315)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:529)
Caused by: java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at edu.internet2.middleware.grouper.util.GrouperUtil.invokeMethod(GrouperUtil.java:4002)
        ... 7 more
Caused by: java.lang.OutOfMemoryError: Java heap space
        at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:133)
        at java.io.OutputStreamWriter.write(OutputStreamWriter.java:220)
        at java.io.Writer.write(Writer.java:157)
        at org.apache.log4j.helpers.QuietWriter.write(QuietWriter.java:48)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:302)
        at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:359)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
        at org.apache.log4j.Category.callAppenders(Category.java:206)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.log(Category.java:856)
        at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:541)
        at edu.internet2.middleware.psp.Psp.execute(Psp.java:813)
        at edu.internet2.middleware.psp.grouper.PspChangeLogConsumer.fullSync(PspChangeLogConsumer.java:335)
        ... 12 more

Currently the loader process is set to 1024m so I've upped it to 2048m but I'm not sure that will fix it.

Jeffrey

Both pilots and IT professionals require training and currency before charging into clouds!

---------------------------------------

On Mon, Sep 21, 2015 at 12:04 PM, Jeffrey Crawford <> wrote:

We are starting to put grouper into production and I've noticed something strange.

We perform a full sync early Sunday morning, but when Monday rolls around and people start trying to provision new group members I get the following error type in the logs:

============================================================
2015-09-21 11:22:00,035: [DefaultQuartzScheduler_Worker-4] INFO  PspChangeLogConsumer.processChangeLogEntries(481) -  - PSP Consumer 'psp' - Full sync is running, returning sequence number '149686'
2015-09-21 11:22:00,057: [DefaultQuartzScheduler_Worker-4] ERROR ChangeLogHelper.processRecords(281) -  - Did not get all the way through the batch! 149686 != 149690
2015-09-21 11:22:00,057: [DefaultQuartzScheduler_Worker-4] ERROR GrouperLoaderJob.runJob(433) -  - Error on job: CHANGE_LOG_consumer_psp
java.lang.RuntimeException: Error in loader job: null, check logs: Did not get all the way through the batch! 149686 != 149690
        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:422)
        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:315)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:529)
2015-09-21 11:22:00,070: [DefaultQuartzScheduler_Worker-4] ERROR GrouperLoaderJob.execute(318) -  - Error running up job
java.lang.RuntimeException: Error in loader job: null, check logs: Did not get all the way through the batch! 149686 != 149690
        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:422)
        at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:315)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:529)
============================================================

Its as if the Full Sync isn't being notified that it's finished. The only error I see during the full sync is:

============================================================
2015-09-20 01:06:28,211: [DefaultQuartzScheduler_Worker-2] ERROR Psp.execute(1187) -  - Psp 'psp' - Diff DiffResponse[id=G046553637,
status=failure,error=noSuchIdentifier,errorMessages={Unable to calculate provisioned object.},requestID=2015/09/20-01:06:28.208]
2015-09-20 01:06:28,211: [DefaultQuartzScheduler_Worker-2] ERROR Psp.execute(1189) -  - Psp 'psp' - Diff XML:
<psp:diffResponse xmlns:psp='http://grouper.internet2.edu/psp' status='failure' requestID='2015/09/20-01:06:28.208' error='noSuchIde
ntifier'>
  <errorMessage>Unable to calculate provisioned object.</errorMessage>
  <psp:id ID='G046553637'/>
</psp:diffResponse>

2015-09-20 01:06:28,211: [DefaultQuartzScheduler_Worker-2] ERROR Psp.execute(1452) -  - Psp 'psp' - Sync SyncResponse[id=G046553637,status=failure,error=noSuchIdentifier,errorMessages={Unable to calculate provisioned object.},requestID=2015/09/20-01:06:28.208]
2015-09-20 01:06:28,212: [DefaultQuartzScheduler_Worker-2] ERROR Psp.execute(1454) -  - Psp 'psp' - Sync SPML:
<psp:syncResponse xmlns:psp='http://grouper.internet2.edu/psp' status='failure' requestID='2015/09/20-01:06:28.208' error='noSuchIdentifier'>
  <errorMessage>Unable to calculate provisioned object.</errorMessage>
  <psp:id ID='G046553637'/>
</psp:syncResponse>
============================================================

Not sure if the above can be causing the issue at the top of the message.

Jeffrey

Both pilots and IT professionals require training and currency before charging into clouds!

---------------------------------------