Details
-
Bug
-
Resolution: Fixed
-
Minor
-
2.4.0.patch
-
None
Description
Under heavy load the following error occurs for some groups while doing a full sync with a PSPNG provisioner, more or less frequently depending on the load.
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 |
|
This causes the syncing of the group to be retried later (after the end of the main part of the full sync). While the load is still high those retries fail as well and eventually succeed when it abates. This postpones significantly the full sync actual completion.
See more details in this grouper-users thread:
https://lists.internet2.edu/sympa/arc/grouper-users/2020-09/msg00022.html