Grouper Users - Open Discussion List

[BROWN Hugh <>]

We are currently testing Grouper 2.3.0 on our Test environment. 
All seems well except for the psp which on startup returned the "StopWatch 
already running" message referenced in this thread. 

As per the related thread at 
https://lists.internet2.edu/sympa/arc/grouper-users/2016-05/msg00090.html  we 
ran a bulk sync and increased the psp GROUPER_CHANGE_LOG_CONSUMER 
LAST_SEQUENCE_PROCESSED value to the most recent  GROUPER_CHANGE_LOG_ENTRY 
value.

This cleared the StopWatch issue, but under ongoing running we encountered 
further psp failures. These again related to NULL CONTEXT_ID value, but  now 
do not include the StopWatch reference and simply report a 
NullPointerException  as below:

**********************************************************************************************
2018-01-22 15:10:00,031: [DefaultQuartzScheduler_Worker-4] ERROR
GrouperLoaderJob.execute(348) - - Error running up job
java.lang.RuntimeException: Error in loader job: null, check logs: Error:
java.lang.NullPointerException
at
edu.internet2.middleware.psp.grouper.PspChangeLogConsumer.processChangeLogEntr
ies(PspChangeLogConsumer.java:510)
at
edu.internet2.middleware.grouper.changeLog.ChangeLogHelper.processRecords(Chan
geLogHelper.java:245)
at
edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$5.runJob(Grouper
LoaderType.java:732)
at
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoa
derJob.java:465)
at
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLo
aderJob.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 != 6489359
at
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoa
derJob.java:474)
at
edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLo
aderJob.java:345)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)

**********************************************************************************************

As detailed in the Grouper 2.3.0 release notes at 
https://spaces.internet2.edu/display/Grouper/v2.3+Release+Notes we have 
applied patches grouper_v2_3_0_psp_patch_0 and grouper_v2_3_0_psp_patch_1. 
(As these are binaries, had to merge into the existing jar, so we assume this 
is correct?)

On running the psp we obtained the same NullPointerException.  On checking 
the GitHub entry at 
https://github.com/Internet2/grouper-psp/commit/b83876f0bca4e25b8a2e256dc7668963f697efa4
 line 510 shows the modification does indeed check for nulls.  
Furthermore, while the patch seems to be intended to catch GROUPER 
_CHANGE_LOG_ENTRY  entries with null CONTEXT_ID values, it is not clear why 
they are now being created by version 2.3.0 when they did not occur under 
version 2.2.2.

 Can anyone please assist?

Thank you,

Hugh Brown
University of Edinburgh
IS Applications 
Production Management










-- 
The University of Edinburgh is a charitable body, registered in
Scotland, with registration number SC005336.


-----Original Message-----
From: 

 
[mailto:]
 On Behalf Of Hyzer, Chris
Sent: 18 October 2016 17:32
To: Philip Harle 
<>;
 

Subject: [grouper-users] RE: Grouper 2.3 upgrade - NULL context_id causing 
PSP issues

Hmmm, I made another patch can you please try it?

Thanks
Chris

-----Original Message-----
From: Philip Harle 
[mailto:]
Sent: Monday, October 17, 2016 4:54 AM
To: Hyzer, Chris 
<>;
 

Subject: RE: Grouper 2.3 upgrade - NULL context_id causing PSP issues

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