Grouper Users - Open Discussion List

[Dominique Petitpierre <>]

Hello,

Thanks for your answer!

On 17.09.20 19:49, Redman, Chad wrote:

        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.

Curiously the error occurs on the provider that runs the fastest (1h30, activedirectory_employee) and not at all on the slowest (7h, activedirectory_student).

(note: In the case described in my message, the retries occurred after the end of the  activedirectory_employee full sync, so the groups were eventually synchronized only after activedirectory_student finished.)

Since they were running simultaneously they experienced the same load, so it has to do with the content of the groups. But I don't have time to investigates this. Sorry.

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

- Can the delay between the progress messages be configured?

In any case it is not critical: running the two provisioners separately lowers the frequency of the issue.

        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.

Well, it is always reassuring to see that something is happening and has a predicted end!

Thanks again for your explanations.

Dominique

        -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
 

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