Grouper Users - Open Discussion List

["Redman, Chad" <>]

the calculation is for a log line extrapolating the estimated time left based on how much work has been done in the past interval. Maybe if the work done was very small in the interval, this can lead to such an absurd number? It's ridiculously large, like a floating point rounding error got into a denominator of a fraction.

Unfortunately, there is no config parameter to skip logging it. So it probably needs a patch.

It could also gain some accuracy by looking at the accumulated work done and full elapsed time, rather than always the last interval. That way it would slowly become more accurate over time and not swing wildly. Wouldn't be guaranteed to fix this problem though.

-Chad

---

From: <> on behalf of Dominique Petitpierre <>
Sent: Wednesday, September 16, 2020 11:30 AM
To: <>
Subject: Re: [grouper-users] PSPNG: "ArithmeticException: Multiplication overflows a long" in ProgressMonitor

 

Hello again,

in fact such errors can be frequent, and in that case, because they are repeated for a given group, might slow down significantly the full sync.

During a very long full sync for two provisioners that lasted from 5:30 to 12:23 there were lots of occurrences:

grep -c -a 'FullSyncer(activedirectory_employee): Problem doing full sync' grouper_error.log
930

grep -a -A1 'FullSyncer(activedirectory_employee): Problem doing full sync' grouper_error.log |egrep -c 'Multiplication overflows a long'
930

It happened during the whole syncing period:

grep -a 'Problem doing full sync' grouper_error.log |head -1
2020-09-16 05:46:01,927: [FullSyncer(activedirectory_employee)-Thread] ERROR FullSyncProvisioner.fullSyncGroup(784) -  - FullSyncer(activedirectory_employee): Problem doing full sync. Requeuing group application:wwwit.unige.ch:perso:mobilitydossier:user/#12692(Existing)

grep -a 'Problem doing full sync' grouper_error.log |tail -1
2020-09-16 12:15:37,064: [FullSyncer(activedirectory_employee)-Thread] ERROR FullSyncProvisioner.fullSyncGroup(784) -  - FullSyncer(activedirectory_employee): Problem doing full sync. Requeuing group application:swapp-test.unige.ch:general-swapp:quick-links:offers:mobility/#12710(Existing)

It happens repeatedly for some groups, e.g:

grep -c -a 'FullSyncer(activedirectory_employee): Problem doing full sync.*emploi:offrelecetu:user' grouper_error.log
46

Curiously it did not happen for the other very similar provisioner running at the same time:

grep -a -A1 'FullSyncer(activedirectory_student): Problem doing full sync' grouper_error.log |egrep -c 'Multiplication overflows a long'
0

I suspect it is related to the resource intensive use: it was the first time I tried to run two provisioners at the same time.
May be some time counter overflows because operations are too slow, or because the memory needs doubled there is some memory related problem (although quite unlikely in absence of  any recorded OutOfMemoryError).

- Is it a known bug? (I could not find anything in Jira nor grouper-users)

- Do you have any advice on how to prevent these errors? (besides running the provisioners at different times)

- Have you noticed this problem in relation to intensive resources use?

By the way,

- Do the provisioners share the caches for the Grouper side objects? and for the target directory side (same for both provisioners)?

Thanks in advance for your comments and suggestions!

Regards,
Dominique

On 15.09.20 20:19, Dominique Petitpierre wrote:

Hello,

while testing a provisioner I observed a few errors like this:

2020-09-15 16:14:24,222: [main] WARN  GrouperStartup.printConfigOnce(232) -  - Grouper starting up: version: 2.4.0, build date: null, env: test_2.4.0_grouper-loader
grouperPatchStatus read from: /usr/local/grouper-loader/grouperPatchStatus.properties
api patches installed:        0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96
pspng patches installed:      0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12

...

2020-09-15 16:28:09,696: [FullSyncer(activedirectory_employee)-Thread] ERROR FullSyncProvisioner.fullSyncGroup(784) -  - FullSyncer(activedirectory_employee): Problem doing full sync. Requeuing group application:wwwit.unige.ch:service:emploi:offrelecetu:user/#11137(Existing)
java.lang.ArithmeticException: Multiplication overflows a long: 9223372036854775807 * 1000
        at org.joda.time.field.FieldUtils.safeMultiply(FieldUtils.java:152)
        at org.joda.time.Duration.standardSeconds(Duration.java:154)
        at edu.internet2.middleware.grouper.pspng.ProgressMonitor.logProgressIfNecessary(ProgressMonitor.java:104)
        at edu.internet2.middleware.grouper.pspng.ProgressMonitor.workCompleted(ProgressMonitor.java:68)
        at edu.internet2.middleware.grouper.pspng.Provisioner.prepareUserCache(Provisioner.java:960)
        at edu.internet2.middleware.grouper.pspng.Provisioner.doFullSync(Provisioner.java:1566)
        at edu.internet2.middleware.grouper.pspng.FullSyncProvisioner.fullSyncGroup(FullSyncProvisioner.java:762)
        at edu.internet2.middleware.grouper.pspng.FullSyncProvisioner.processQueueItem(FullSyncProvisioner.java:456)
        at edu.internet2.middleware.grouper.pspng.FullSyncProvisioner.thread_manageFullSyncProcessing(FullSyncProvisioner.java:252)
        at edu.internet2.middleware.grouper.pspng.FullSyncProvisioner$1.run(FullSyncProvisioner.java:147)
        at java.lang.Thread.run(Thread.java:748)
2020-09-15 16:28:09,700: [FullSyncer(activedirectory_employee)-Thread] INFO  FullSyncQueueItem.processingCompleted(324) -  - FullSync Item done (java.lang.ArithmeticException: Multiplication overflows a long: 9223372036854775807 * 1000). Stats: ins=0|del=0|upd=0|tot=0|t=775 secs/ProcTime: 15.759s Timing breakdown: init=0%/ReadGroupFromGrouper=0%/ClearingGroupCache=0%/StartCoordination=0%/StartProvisioning(get group & subject info)=0%/doFullSync=99%/: Action="application:wwwit.unige.ch:service:emploi:offrelecetu:user|qid=132|Trigger=Scheduled" full sync|ExternalRef=null|AsOf=Sep 15, 2020 4:15:13 PM|QTime=12m:40s|Age=12m:55s

It seems to be happening randomly, and infrequently (twice in a provisioning session of about 3.5 hours for 1538 groups).

The group is eventually synchronized after being requeued, so it is not critical, just worrying.

Regards,

-- 
Mr Dominique Petitpierre, user=Dominique.Petitpierre domain=unige.ch
IT Division, University of Geneva, Switzerland