Grouper Users - Open Discussion List

[Philip Harle <>]

Hi Chris,

I've applied the patch and restarted, but unfortunately the issue persists.

2016-10-17 09:49:02,810: [DefaultQuartzScheduler_Worker-2] ERROR 
ChangeLogHelper.processRecords(252) -  - Error
java.lang.IllegalStateException: Stopwatch already started.
        at org.apache.commons.lang.time.StopWatch.start(StopWatch.java:121)
        at 
edu.internet2.middleware.psp.grouper.PspChangeLogConsumer.processChangeLogEntries(PspChangeLogConsumer.java:489)
        at 
edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:242)
        at 
edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:629)
        at 
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:416)
        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)
2016-10-17 09:49:02,812: [DefaultQuartzScheduler_Worker-2] ERROR 
ChangeLogHelper.processRecords(283) -  - Did not get all the way through the 
batch! -1 != 3301924
2016-10-17 09:49:02,812: [DefaultQuartzScheduler_Worker-2] ERROR 
GrouperLoaderJob.runJob(436) -  - Error on job: CHANGE_LOG_consumer_psp
java.lang.RuntimeException: Error in loader job: null, check logs: Error: 
java.lang.IllegalStateException: Stopwatch already started.
        at org.apache.commons.lang.time.StopWatch.start(StopWatch.java:121)
        at 
edu.internet2.middleware.psp.grouper.PspChangeLogConsumer.processChangeLogEntries(PspChangeLogConsumer.java:489)
        at 
edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:242)
        at 
edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:629)
        at 
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:416)
        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)
Did not get all the way through the batch! -1 != 3301924
        at 
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:425)
        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)
2016-10-17 09:49:02,843: [DefaultQuartzScheduler_Worker-2] ERROR 
GrouperLoaderJob.execute(321) -  - Error running up job
java.lang.RuntimeException: Error in loader job: null, check logs: Error: 
java.lang.IllegalStateException: Stopwatch already started.
        at org.apache.commons.lang.time.StopWatch.start(StopWatch.java:121)
        at 
edu.internet2.middleware.psp.grouper.PspChangeLogConsumer.processChangeLogEntries(PspChangeLogConsumer.java:489)
        at 
edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(ChangeLogHelper.java:242)
        at 
edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJob(GrouperLoaderType.java:629)
        at 
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:416)
        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)
Did not get all the way through the batch! -1 != 3301924
        at 
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:425)
        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)
2016-10-17 09:49:04,010: [DefaultQuartzScheduler_Worker-4] INFO  
EventLog.info(156) -  - 
[9a651f49eab44c94a319c212ee00100a,'GrouperSystem','application'] session: 
start (2ms)

Any further ideas?

Thanks,
Phil

> -----Original Message-----
> From: Hyzer, Chris 
> [mailto:]
> Sent: 15 October 2016 16:15
> To: Philip Harle 
> <>;
>  grouper-
> 
> Subject: RE: Grouper 2.3 upgrade - NULL context_id causing PSP issues
> 
> I made a patch for this, can you please try it?
> 
> https://bugs.internet2.edu/jira/browse/GRP-1385
> 
> grouper_v2_3_0_psp_patch_0
> 
> Thanks
> Chris
> 
> -----Original Message-----
> From: 
> 
>  [
> ]
>  On Behalf Of Philip Harle
> Sent: Friday, October 14, 2016 10:22 AM
> To: 
> 
> Subject: [grouper-users] Grouper 2.3 upgrade - NULL context_id causing PSP
> issues
> 
> Hi,
> 
> We're currently upgrading of a clone of our live Grouper 2.2.2 installation 
> to
> 2.3.0 using the grouperInstaller upgrade method.
> We've managed to upgrade the API, UI and WS, and all is looking well. I'm
> now working on upgrading the PSP and have hit an issue.
> 
> The background PSP sync (run as part of our grouperloader service) isn't
> working and we're seeing the following in grouper_error.log:
> 
> 2016-10-14 15:10:00,028: [DefaultQuartzScheduler_Worker-7] ERROR
> ChangeLogHelper.processRecords(252) -  - Error
> java.lang.NullPointerException
>         at
> edu.internet2.middleware.psp.grouper.PspChangeLogConsumer.processCh
> angeLogEntries(PspChangeLogConsumer.java:510)
>         at
> edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRec
> ords(ChangeLogHelper.java:242)
>         at
> edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$4.runJo
> b(GrouperLoaderType.java:629)
>         at
> edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(Gr
> ouperLoaderJob.java:416)
>         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.ja
> va:573)
> 2016-10-14 15:10:00,029: [DefaultQuartzScheduler_Worker-7] ERROR
> ChangeLogHelper.processRecords(283) -  - Did not get all the way through
> the batch! -1 != 3301919
> 
> From what I can tell this is because we had a small number of entries in
> grouper_change_log_entry with a NULL context_id. I cleared these out of
> the table, and the error no longer appeared in the log. However, when
> making any change in grouper it is still creating a new entry in the table 
> with a
> NULL context_id.
> Any ideas why this might be the case?
> 
> 
> Our eventual plan is to move away from PSP in favour of PSPNG, but I feel
> we need to fix the above issue before proceeding.
> Although, as an aside, can PSPNG be installed using the grouperInstaller on
> an installation that has been upgraded from 2.2, or do we need to
> install/configure it manually?
> 
> 
> Thanks,
> Phil
> 
> ---
> Phil Harle
> IT Service
> Newcastle University