Grouper Users - Open Discussion List

[Ryan Rumbaugh <>]

Well I ran the PITUtils.deleteInactiveObjectsInStem method to clear up the PIT errors I was seeing and now we’re back to this exception when running loaderRunOneJob again. In grouper_loader_log the duration of the job is 66 minutes, so it’s doing something I suppose, but I’m not sure where to being to determine what the issue is. Any help is appreciated. Thanks!

 

"Summary: 991 successes/1 failures.  (991 successful entries will be retried because they follow a failure in the queue.) First error was: FullSync timed out after 300 secondsDid not get all the way through the batch! -1 != 78006962java.lang.RuntimeException: Error in loader job: null, check logs: Summary: 991 successes/1 failures.  (991 successful entries will be retried because they follow a failure in the queue.) First error was: FullSync timed out after 300 secondsDid not get all the way through the batch! -1 != 78006962

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

                at edu.internet2.middleware.grouper.app.loader.GrouperLoader.runOnceByJobName(GrouperLoader.java:1621)

                at edu.internet2.middleware.grouper.app.gsh.loaderRunOneJob.invoke(loaderRunOneJob.java:95)

                at edu.internet2.middleware.grouper.app.gsh.loaderRunOneJob$invoke.call(Unknown Source)

                at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)

                at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)

                at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:133)

                at groovysh_evaluate.loaderRunOneJob(groovysh_evaluate:4)

                at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

                at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

                at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

                at java.lang.reflect.Method.invoke(Method.java:498)

                at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)

                at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)

                at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1224)

                at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1091)

                at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1033)

                at groovy.lang.MetaClassImpl.invokePropertyOrMissing(MetaClassImpl.java:1270)

                at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1226)

                at org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(PogoMetaClassSite.java:69)

                at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:52)

                at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:154)

                at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:166)

                at groovysh_evaluate.run(groovysh_evaluate:3)

                at groovysh_evaluate$run.call(Unknown Source)

                at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)

                at groovysh_evaluate$run.call(Unknown Source)

                at org.codehaus.groovy.tools.shell.Interpreter.evaluate(Interpreter.groovy:78)

                at org.codehaus.groovy.tools.shell.Evaluator$evaluate.call(Unknown Source)

                at org.codehaus.groovy.tools.shell.Groovysh.evaluateWithStoredBoundVars(Groovysh.groovy:258)

                at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

                at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

                at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

                at java.lang.reflect.Method.invoke(Method.java:498)

                at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:210)

                at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:59)

                at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:174)

                at org.codehaus.groovy.tools.shell.Groovysh.execute(Groovysh.groovy:199)

                at org.codehaus.groovy.tools.shell.Shell.leftShift(Shell.groovy:122)

                at org.codehaus.groovy.tools.shell.Shell$leftShift$0.call(Unknown Source)

                at org.codehaus.groovy.tools.shell.ShellRunner.work(ShellRunner.groovy:95)

                at org.codehaus.groovy.tools.shell.InteractiveShellRunner.super$2$work(InteractiveShellRunner.groovy)

                at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

                at sun.reflect.NativeMet"

 

--

Ryan Rumbaugh

Identity Management Specialist

Cybersecurity & Identity |ITS|

501 123.1, 68588-0203

University of Nebraska |nebraska.edu

Kearney|Lincoln|Omaha

402-472-0831 (o)

 

From: Ryan Rumbaugh <>
Date: Tuesday, December 18, 2018 at 4:20 PM
To: "Bee-Lindgren, Bert" <>
Cc: "" <>
Subject: Re: [grouper-users] FullSync Timeout - pspng exception

 

I'm young in my grouper career so I'll answer as best as I can..

 

A) Not sure... I'm not entirely sure how to know

B) The group in question had two issues that I found out after sending the email (of course), it has 26k members and there were spaces in the ID path (I'm told that may be an issue)?

C) The loader in question has been 'stuck' for a quite a while, so yes, it appears to be stuck in so far as the last_sequenced_processed is falling behind the other loaders

 

The timeout value has not been changed. 

 

In any case, I edited the folder path the group is a member of to remove the spaces and ran loaderRunOneJob again and got a different error at least...now it is complaining about now being able to retreive a PIT group:

 

"Error: java.lang.RuntimeException: Problem fetching information on group app:ems:Raikes-School-Room-Request(PIT)

at edu.internet2.middleware.grouper.pspng.Provisioner.fetchTargetSystemGroupsInBatches(Provisioner.java:880)

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

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

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

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:638)

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

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

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

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

Did not get all the way through the batch! -1 != 78006962java.lang.RuntimeException: Error in loader job: null, check logs: Error: java.lang.RuntimeException: Problem fetching information on group app:ems:Raikes-School-Room-Request(PIT)

at edu.internet2.middleware.grouper.pspng.Provisioner.fetchTargetSystemGroupsInBatches(Provisioner.java:880)

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

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

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

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:638)

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

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

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

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

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

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

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

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

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

--

Ryan Rumbaugh

 

 

---

From: Bee-Lindgren, Bert <>
Sent: Tuesday, December 18, 2018 4:06 PM
To: Ryan Rumbaugh
Cc:
Subject: Re: [grouper-users] FullSync Timeout - pspng exception

 

I'll look at this along with adjusting the timeout. 

 

The synchronization process is for Incremental syncs to try to stay out of the way of ongoing FullSyncs (and vice versa), but to CONTINUE with incremental  processing when waiting fails. 

 

So, some questions, 

 

A) Do you think a Full sync was actually happening?

 

B) is the group so big that 5minutes is relatively expected to read all the account objects?

 

C) I presume that this is a persistent problem, meaning that (A) is probably No?

On Dec 18, 2018, at 4:37 PM, Ryan Rumbaugh <> wrote:

Hello,

 

I'm trying to diagnose why pspng is not synching groups with Active Directory. This is what I'm seeing in the grouper_loader_log table. I'm not entirely sure why the timeout is occurring. I have verified connectivity exists between the daemon server and the directory, and it has worked in the past.

 

Running loaderRunOneJob("CHANGE_LOG_consumer_pspng_ad") is causing the exception below.

 

 

"Summary: 993 successes/1 failures.  (993 successful entries will be retried because they follow a failure in the queue.) First error was: FullSync timed out after 300 secondsDid not get all the way through the batch! -1 != 78006962java.lang.RuntimeException: Error in loader job: null, check logs: Summary: 993 successes/1 failures.  (993 successful entries will be retried because they follow a failure in the queue.) First error was: FullSync timed out after 300 secondsDid not get all the way through the batch! -1 != 78006962

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

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

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

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

"

 

Thanks!

 

--

Ryan Rumbaugh