Combined test for data export worker (Morning Glory)
IN PROGRESS
Overview
Per PERF-267 - Getting issue details... STATUS the following tests were performed using the data export workflow (eHoldings, bulk edits, and edifacts) to determine what happens to the export workflows when mod-data-export-worker (with one node) fails and to what load can the exports be run successfully.
Infrastructure
PTF -environment
- 10 m6i.2xlarge EC2 instances (changed. In Lotus it was m5.xlarge)
- 2 instances of db.r6.xlarge database instances, one reader and one writer
- MSK
- 4 m5.2xlarge brokers in 2 zones
- auto.create-topics.enable = true
- log.retention.minutes=120
- 2 partitions per DI topics
- okapi (running tasks -3)
- 1024 CPU units, 1360 MB mem
- mod-users (running tasks -2)
- 128 CPU units, 896 MB mem
- mod-data-export (running tasks -1)
- 1024 CPU units, 896 MB mem
- mod-data-export-spring (running tasks -1)
- 256 CPU units, 1844 MB mem
- mod-data-export-worker (running tasks -1)
- 256 CPU units, 1844 MB mem
- mod-notes (running tasks -2)
- 128 CPU units, 896 MB mem
- mod-agreements (running tasks -2)
- 128 CPU units, 1382 MB mem
Software Versions
- mod-data-export-worker: 1.5.0-SNAPSHOT.54
- mod-data-export-spring: 1.4.2
- mod-agreements: 5.2.1
- mod-notes: 3.1.0
- mod-users: 18.3.0
Test Runs (initial assumption of the data sets for combo testing)
Bulk edit files are located in: Performance testing data Google Drive
Test Run | Duration | Edifact | eHoldings | Bulk-edit user barcodes | Bulk edit item barcodes | Bursar (optional) | Circulation logs (optional) | Memory Behavior (Trend) | Comment | Record identifier files name (bulk edit) | Time to process | Results |
#1 | 1-time check | Export 10 orders with 5 order lines each for 1 organization integration. 50 order lines exported to 1 .edi file | Export a "Package" record with small number of "Titles" (<1.000) https://ptf-rmb.int.aws.folio.org/eholdings/packages/228-1126892 (744) | 100 records file name 100-user-barcodes.csv | 100 records file name 100-item-barcodes.csv | |||||||
#2 | 1-time check | Export 10 orders for each account number with 10 order lines each. Each account represents a different organization integration. Meaning 100 order lines exported to 10 different .edi files | Export a "Package" record with close to limit number of "Titles" (between 9.000 and 10.000) without assigned "Notes" records https://ptf-rmb.int.aws.folio.org/eholdings/packages/413-2605025 (9073) | 1 000 records file name 1000-user-barcodes.csv | 1 000 records file name 1000-item-barcodes.csv | |||||||
#3 | 1-time check | Export 100 orders for each account number with 10 order lines each. Each account represents a different organization integration. Meaning 1,000 order lines exported to 10 different .edi files | export "Package" record with "Titles" (about 5k) and assigned 1 large "Note" record https://ptf-rmb.int.aws.folio.org/eholdings/packages/413-2603523 (4,971 titles and one very large note) | 2 500 records file name 2500-user-barcodes.csv | 10 000 records file name 10k-item-barcodes.csv | |||||||
| #4 | 1-time check | Export 100 orders for each account number with 100 order lines each. Each account represents a different organization integration. Meaning 10,000 order lines exported to 10 different .edi files | export "Package" record with "Titles" (between 9.000 and 10.000) and assigned 1 large "Note" record https://ptf-rmb.int.aws.folio.org/eholdings/packages/36-6693? (9,825 titles and one very large note) | 5 000 records file name 5000-user-barcodes.csv | 100 000 records file name 100k-item-barcodes.csv | |||||||
| #5 | 1-time check | ? | ? | ? | ? |
Test resulst
Test Run | Duration | Edifact | eHoldings | Bulk-edit user barcodes | Bulk edit item barcodes | Bursar (optional) | Circulation logs (optional) | Memory Behavior (Trend) | Comment | Time to process | Results |
| #1 | 3x 100 orders with 100 PO lines each (10k) 3[10k files as output | 3x 4472 w/o Note https://ptf-rmb.int.aws.folio.org/eholdings/packages/58-2110695?searchfield=title | 1 user Folio 3 jobs for 1250 records (unique dataset for each file) | 1 user Folio 3 jobs for 5000 records (unique dataset for each file) | - | - | No visible growing of memory usage on mod-data-export-worker and mod-data-export spring see pic#1 | Edifact - success eHoldings - success Bulk users - ok Bulk Items - ok | in total ±16 min | Edifact files being created; Eholdings files being created | |
| Comment | 15-16 sec Status - "success" | ±4 min 10 s Status -"success" | ±15sec -upload (1/3 stuck "IN_PROGRESS")±21sec -for update (2 jobs) | ±3min-upload ±6 min 35 sec- for update (1/3 job failed at the beginning and was restarted) | |||||||
| #2 | 3x 100 orders with 100 PO lines each (10k) 3x 10k files as output | 3x 4472 w/o Note https://ptf-rmb.int.aws.folio.org/eholdings/packages/58-2110695?searchfield=title | 3*1250 | 3*5000 | Java heap space - out of memory exceptions on eHoldings Abstract fatal error executing job - ..-worker | ||||||
14s 1/3 job failed after 4 minutes with Index out of bounds: 347 >= 345 (IndexOutOfBoundsException) | 4 min 30 s (2/3 jobs failed with Java heap space (OutOfMemoryError)) | ±17sec -upload ±31sec -for update Status -"success" | ±3min-upload ±7 min - for update Status -"success" | ||||||||
| #3 | 2x 100 orders with 100 PO lines each (10k) 2x 10k files as output | 2x 4472 w/o Note https://ptf-rmb.int.aws.folio.org/eholdings/packages/58-2110695?searchfield=title | 2*1250 | 2*5000 | |||||||
Failover testing. Behavior of the workflows when 'killing' the module
- mod-data-export-worker
- mod-data-export-spring
| Edifact | eHoldings | Bulk-edit user barcodes | Bulk edit item barcodes | Bursar | Circulation logs | |
| mod-data-export-worker | Jobs resumed successfully | job in status "scheduled " can proceed and be completed successfully after module restart. job in status "in progress" resumed successfully | The job stuck "IN_PROGRESS" for file upload If users were already uploaded, after failover- the edited file upload and the update will successful. The job fails for edited file upload. Status - "Scheduled". Error message "Fail to upload the file" If the edited file was already uploaded, after failover- the update will fail. Error message "Something went wrong" The job stuck "IN_PROGRESS" for the update step. | The job stuck "IN_PROGRESS" for file upload If items were already uploaded, after failover- updating will not start. Job did not resume, but the status changed to "Successful" for the updating process. | Did not test | Did not test On perf bulk edit rancher job resumed successfully |
mod-data-export-spring | Jobs resumed successfully. With OOM some jobs failed | Jobs resumed successfully | Jobs resumed successfully for all of the steps (file upload+ edited file upload +updating) | Jobs resumed successfully for all of the steps (file upload +updating) | Did not test | Did not test on PTF On perf bulk edit rancher job resumed successfully |
Memory Trends of Repeated concurrent eHoldings and Edifact jobs:
Concurrent Edifact exports ( >6)
Concurrent eHolding jobs (6 with 4.2K each)
Memory usage of Repeated concurrent Bulk Edit Items App
- Memory trend: memory usage increases over time for mod-data-export-worker increases from 37% to 46% in 2 steps at the start of the changes commitment process for 10000 and 20000 records. for mod-data-export-spring increases from 24% to 26% and become stable. All other services without changes. Related issue MODEXPW-214 - Getting issue details... STATUS
- 5 parallel jobs for 10k records can be performed simultaneously only if started with the ramp-up of a minimum of 10sec (for both upload and editing processes). If the jobs started with fewer 10s intervals they will have IN_PROGRESS status forever.
Memory usage of Repeated concurrent Bulk Edit Users App
- Memory trend: memory usage is stable.
Parallel jobs can be performed simultaneously only if started with the ramp-up of a minimum of 10sec (for both upload and editing processes). If the jobs started with fewer 10s intervals they will have IN_PROGRESS status forever.
Test #1
pic#1 Memory usage mod-data-export-worker/spring
pic#2 CPU usage
For Bulk-edit user barcodes job stuck "IN_PROGRESS"
Field Value
@ingestionTime 1660122311768
@log 054267740449:lcp2-folio-eis
@logStream lcp2/mod-data-export-spring/f8eefca0df4c4fe8aaa1339b2b020eb8
@message
09:05:07 [950679/bulk-edit] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod-data-export-spring] INFO JobUpdatesService Received Job(id=6a4f73c5-e485-4384-a3b1-a89bd5365cd8, name=null, description=null, source=null, isSystemSource=null, type=BULK_EDIT_IDENTIFIERS, exportTypeSpecificParameters=null, status=null, files=null, fileNames=null, startTime=Wed Aug 10 09:05:07 UTC 2022, endTime=Wed Aug 10 09:05:07 UTC 2022, createdDate=Wed Aug 10 09:05:07 UTC 2022, createdByUserId=null, createdByUsername=null, updatedDate=Wed Aug 10 09:05:07 UTC 2022, updatedByUserId=null, updatedByUsername=null, outputFormat=null, errorDetails=null, batchStatus=STARTED, exitStatus=null, identifierType=null, entityType=USER, progress=class Progress {
@timestamp
1660122307431
Field Value
@ingestionTime 1660122312075
@log 054267740449:lcp2-folio-eis
@logStreamlcp2/mod-data-export-worker/6768ddc692484bd5917f409e9cc10e10
@message
09:05:07 [] [] [] [] INFO SimpleJobLauncher$1 Job: [FlowJob: [name=BULK_EDIT_IDENTIFIERS-USER]]completed with the following parameters: [{jobId=6a4f73c5-e485-4384-a3b1-a89bd5365cd8, tempOutputFilePath=/tmp/mod-data-export-worker/2022-08-10-Matched-Records-1250-user4-barcodes, fileName=/tmp/mod-data-export-worker/1250-user4-barcodes.csv, totalCsvLines=1250, exportType=BULK_EDIT_IDENTIFIERS, identifierType=BARCODE, entityType=USER}] and the following status: [COMPLETED] in 14s649ms
@timestamp
1660122307435
For Bulk-edit item barcodes job "FAILED"
Field Value @ingestionTime 1660122427065 @log 054267740449:lcp2-folio-eis @logStream lcp2/mod-data-export-worker/6768ddc692484bd5917f409e9cc10e10 @message 09:07:06 [] [] [] [] ERROR AbstractStep Encountered an error executing step bulkEditItemStep in job BULK_EDIT_IDENTIFIERS-ITEM @timestamp 1660122426706
Field Value
@ingestionTime 1660122427065
@log 054267740449:lcp2-folio-eis
@logStream lcp2/mod-data-export-worker/6768ddc692484bd5917f409e9cc10e10
@message09:07:07 [] [] [] [] INO SimpleJobLauncher$1 Job: [FlowJob: [name=BULK_EDIT_IDENTIFIERS-ITEM]]completed with the following parameters: [{jobId=f31385ce-a129-4a81-be69-431caf72788f, tempOutputFilePath=/tmp/mod-data-export-worker/2022-08-10-Matched-Records-5000-item-barcodes_version2, fileName=/tmp/mod-data-export-worker/5000-item-barcodes_version2.csv, totalCsvLines=5000, exportType=BULK_EDIT_IDENTIFIERS, identifierType=BARCODE, entityType=ITEM}] and the following status: [FAILED] in 2m41s288ms
@timestamp 1660122427035
Test #2
note: Memory usage doesn't seems to be growing significantly, however 2/3 jobs of eholdings export failed with OOM.
OutOfMemory exception trace (mod-data-export-worker)
09:30:43 [] [] [] [] ERROR AbstractJob Encountered fatal error executing jobjava.lang.OutOfMemoryError: Java heap spaceat java.util.Arrays.copyOf(Arrays.java:3745) ~[?:?]at java.io.ByteArrayOutputStream.toByteArray(ByteArrayOutputStream.java:211) ~[?:?]at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.serializeContext(JdbcExecutionContextDao.java:303) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.updateExecutionContext(JdbcExecutionContextDao.java:146) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.repository.support.SimpleJobRepository.updateExecutionContext(SimpleJobRepository.java:223) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source) ~[?:?]at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) ~[spring-tx-5.3.20.jar!/:5.3.20]at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) ~[spring-tx-5.3.20.jar!/:5.3.20]at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.20.jar!/:5.3.20]at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source) ~[?:?]at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source) ~[?:?]at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:128) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.20.jar!/:5.3.20]at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source) ~[?:?]at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:163) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.job.AbstractJob.handleStep(AbstractJob.java:413) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.job.SimpleJob.doExecute(SimpleJob.java:136) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.job.AbstractJob.execute(AbstractJob.java:320) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.launch.support.SimpleJobLauncher$1.run(SimpleJobLauncher.java:149) ~[spring-batch-core-4.3.6.jar!/:4.3.6]09:30:43 [] [] [] [] INFO NotificationListener Job update JobExecution: id=54, version=1, startTime=Wed Aug 10 09:26:12 UTC 2022, endTime=Wed Aug 10 09:30:43 UTC 2022, lastUpdated=Wed Aug 10 09:26:12 UTC 2022, status=FAILED, exitStatus=exitCode=FAILED;exitDescription=java.lang.OutOfMemoryError: Java heap spaceat java.base/java.util.Arrays.copyOf(Arrays.java:3745)at java.base/java.io.ByteArrayOutputStream.toByteArray(ByteArrayOutputStream.java:211)at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.serializeContext(JdbcExecutionContextDao.java:303)at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.updateExecutionContext(JdbcExecutionContextDao.java:146)at org.springframework.batch.core.repository.support.SimpleJobRepository.updateExecutionContext(SimpleJobRepository.java:223)at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source)at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.base/java.lang.reflect.Method.invoke(Method.java:566)at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123)at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388)at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source)at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source)at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.base/java.lang.reflect.Method.invoke(Method.java:566)at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:128)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source)at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:163)at org.springframework.batch.core.job.AbstractJob.handleStep(AbstractJob.java:413)at org.springframework.batch.core.job.SimpleJob.doExecute(SimpleJob.java:136)at org.springframework.batch.core.job.AbstractJob.execute(AbstractJob.java:320)at org.springframework.batch.core.launch.support.SimpleJobLauncher$1.run(SimpleJobLauncher.java:149), job=[JobInstance: id=54, version=0, Job=[E_HOLDINGS]], jobParameters=[{eHoldingsExportConfig={"recordId":"58-2110695","recordType":"PACKAGE","titleSearchFilters":"searchfield=title","packageFields":["providerName","providerId","packageName","packageId","packageType","packageContentType","packageHoldingsStatus","packageCustomCoverage","packageShowToPatrons","packageAutomaticallySelect","packageProxy","packageAccessStatusType","packageTags","packageAgreements","packageNotes"],"titleFields":["titleName","alternateTitles","titleId","publicationType","titleType","titleHoldingsStatus","titleShowToPatrons","managedCoverage","managedEmbargo","customCoverage","customEmbargo","coverageStatement","titleProxy","url","titleAccessStatusType","titleTags","contributors","edition","publisher","ISSNPrint","ISSNOnline","ISBNPrint","ISBNOnline","subjects","peerReviewed","description","customValue1","customValue2","customValue3","customValue4","customValue5","titleAgreements","titleNotes"]}, jobId=bf697955-8d8e-4bb9-b1ae-af3210298a7e, tempOutputFilePath=/tmp/mod-data-export-worker/2022-08-10_09-26-12_0072_58-2110695_package}].09:30:43 [] [] [] [] INFO KafkaService Sending Job(id=bf697955-8d8e-4bb9-b1ae-af3210298a7e, name=null, description=null, source=null, isSystemSource=null, type=null, exportTypeSpecificParameters=null, status=null, files=null, fileNames=null, startTime=Wed Aug 10 09:26:12 UTC 2022, endTime=Wed Aug 10 09:30:43 UTC 2022, createdDate=Wed Aug 10 09:26:12 UTC 2022, createdByUserId=null, createdByUsername=null, updatedDate=Wed Aug 10 09:26:12 UTC 2022, updatedByUserId=null, updatedByUsername=null, outputFormat=null, errorDetails=Java heap space (OutOfMemoryError), batchStatus=FAILED, exitStatus=exitCode=FAILED;exitDescription=java.lang.OutOfMemoryError: Java heap spaceat java.base/java.util.Arrays.copyOf(Arrays.java:3745)at java.base/java.io.ByteArrayOutputStream.toByteArray(ByteArrayOutputStream.java:211)at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.serializeContext(JdbcExecutionContextDao.java:303)at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.updateExecutionContext(JdbcExecutionContextDao.java:146)at org.springframework.batch.core.repository.support.SimpleJobRepository.updateExecutionContext(SimpleJobRepository.java:223)at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source)at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.base/java.lang.reflect.Method.invoke(Method.java:566)at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123)at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388)at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source)at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source)at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.base/java.lang.reflect.Method.invoke(Method.java:566)at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:128)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source)at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:163)at org.springframework.batch.core.job.AbstractJob.handleStep(AbstractJob.java:413)at org.springframework.batch.core.job.SimpleJob.doExecute(SimpleJob.java:136)at org.springframework.batch.core.job.AbstractJob.execute(AbstractJob.java:320)at org.springframework.batch.core.launch.support.SimpleJobLauncher$1.run(SimpleJobLauncher.java:149), identifierType=null, entityType=null, progress=null).09:30:43 [] [] [] [] INFO KafkaService Sent Job(id=bf697955-8d8e-4bb9-b1ae-af3210298a7e, name=null, description=null, source=null, isSystemSource=null, type=null, exportTypeSpecificParameters=null, status=null, files=null, fileNames=null, startTime=Wed Aug 10 09:26:12 UTC 2022, endTime=Wed Aug 10 09:30:43 UTC 2022, createdDate=Wed Aug 10 09:26:12 UTC 2022, createdByUserId=null, createdByUsername=null, updatedDate=Wed Aug 10 09:26:12 UTC 2022, updatedByUserId=null, updatedByUsername=null, outputFormat=null, errorDetails=Java heap space (OutOfMemoryError), batchStatus=FAILED, exitStatus=exitCode=FAILED;exitDescription=java.lang.OutOfMemoryError: Java heap spaceat java.base/java.util.Arrays.copyOf(Arrays.java:3745)at java.base/java.io.ByteArrayOutputStream.toByteArray(ByteArrayOutputStream.java:211)at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.serializeContext(JdbcExecutionContextDao.java:303)at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.updateExecutionContext(JdbcExecutionContextDao.java:146)at org.springframework.batch.core.repository.support.SimpleJobRepository.updateExecutionContext(SimpleJobRepository.java:223)at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source)at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.base/java.lang.reflect.Method.invoke(Method.java:566)at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123)at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388)at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source)at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source)at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.base/java.lang.reflect.Method.invoke(Method.java:566)at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:128)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source)at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:163)at org.springframework.batch.core.job.AbstractJob.handleStep(AbstractJob.java:413)at org.springframework.batch.core.job.SimpleJob.doExecute(SimpleJob.java:136)at org.springframework.batch.core.job.AbstractJob.execute(AbstractJob.java:320)at org.springframework.batch.core.launch.support.SimpleJobLauncher$1.run(SimpleJobLauncher.java:149), identifierType=null, entityType=null, progress=null).
Index out of bounds: 347 >= 345 (IndexOutOfBoundsException) trace. (mod-data-export-worker)
09:30:52 [] [] [] [] ERROR AbstractJob Encountered fatal error executing joborg.springframework.dao.TransientDataAccessResourceException: PreparedStatementCallback; SQL [UPDATE BATCH_JOB_EXECUTION_CONTEXT SET SHORT_CONTEXT = ?, SERIALIZED_CONTEXT = ? WHERE JOB_EXECUTION_ID = ?]; java.lang.IndexOutOfBoundsException: Index out of bounds: 347 >= 345; nested exception is java.sql.SQLException: java.lang.IndexOutOfBoundsException: Index out of bounds: 347 >= 345at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:110) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:70) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:79) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:79) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1541) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:667) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:960) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1015) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.persistSerializedContext(JdbcExecutionContextDao.java:236) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.repository.dao.JdbcExecutionContextDao.updateExecutionContext(JdbcExecutionContextDao.java:148) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.repository.support.SimpleJobRepository.updateExecutionContext(SimpleJobRepository.java:223) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source) ~[?:?]at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) ~[spring-tx-5.3.20.jar!/:5.3.20]at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) ~[spring-tx-5.3.20.jar!/:5.3.20]at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.20.jar!/:5.3.20]at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source) ~[?:?]at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source) ~[?:?]at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:128) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.20.jar!/:5.3.20]at com.sun.proxy.$Proxy121.updateExecutionContext(Unknown Source) ~[?:?]at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:163) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.job.AbstractJob.handleStep(AbstractJob.java:413) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.job.SimpleJob.doExecute(SimpleJob.java:136) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.job.AbstractJob.execute(AbstractJob.java:320) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.batch.core.launch.support.SimpleJobLauncher$1.run(SimpleJobLauncher.java:149) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.core.task.SyncTaskExecutor.execute(SyncTaskExecutor.java:50) ~[spring-core-5.3.20.jar!/:5.3.20]at org.springframework.batch.core.launch.support.SimpleJobLauncher.run(SimpleJobLauncher.java:140) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at jdk.internal.reflect.GeneratedMethodAccessor651.invoke(Unknown Source) ~[?:?]at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:128) ~[spring-batch-core-4.3.6.jar!/:4.3.6]at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.20.jar!/:5.3.20]at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.20.jar!/:5.3.20]at com.sun.proxy.$Proxy182.run(Unknown Source) ~[?:?]at org.springframework.batch.integration.launch.JobLaunchingMessageHandler.launch(JobLaunchingMessageHandler.java:50) ~[spring-batch-integration-4.3.6.jar!/:4.3.6]at org.folio.dew.batch.ExportJobManager.launchJob(ExportJobManager.java:29) ~[classes!/:1.5.0-SNAPSHOT]at org.folio.dew.service.JobCommandsReceiverService.receiveStartJobCommand(JobCommandsReceiverService.java:139) ~[classes!/:1.5.0-SNAPSHOT]at jdk.internal.reflect.GeneratedMethodAccessor641.invoke(Unknown Source) ~[?:?]at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:169) ~[spring-messaging-5.3.20.jar!/:5.3.20]at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:119) ~[spring-messaging-5.3.20.jar!/:5.3.20]at org.springframework.kafka.listener.adapter.HandlerAdapter.invoke(HandlerAdapter.java:56) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.adapter.MessagingMessageListenerAdapter.invokeHandler(MessagingMessageListenerAdapter.java:347) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.adapter.RecordMessagingMessageListenerAdapter.onMessage(RecordMessagingMessageListenerAdapter.java:92) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.adapter.RecordMessagingMessageListenerAdapter.onMessage(RecordMessagingMessageListenerAdapter.java:53) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeOnMessage(KafkaMessageListenerContainer.java:2645) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeOnMessage(KafkaMessageListenerContainer.java:2625) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeRecordListener(KafkaMessageListenerContainer.java:2552) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeWithRecords(KafkaMessageListenerContainer.java:2433) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeRecordListener(KafkaMessageListenerContainer.java:2311) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeListener(KafkaMessageListenerContainer.java:1982) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeIfHaveRecords(KafkaMessageListenerContainer.java:1366) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.pollAndInvoke(KafkaMessageListenerContainer.java:1357) ~[spring-kafka-2.8.6.jar!/:2.8.6]at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.run(KafkaMessageListenerContainer.java:1252) ~[spring-kafka-2.8.6.jar!/:2.8.6]at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]at java.lang.Thread.run(Thread.java:829) ~[?:?]Caused by: java.sql.SQLException: java.lang.IndexOutOfBoundsException: Index out of bounds: 347 >= 345at org.hsqldb.jdbc.JDBCUtil.sqlException(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCUtil.sqlException(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCPreparedStatement.fetchResult(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCPreparedStatement.executeUpdate(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar!/:?]at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar!/:?]at org.springframework.jdbc.core.JdbcTemplate.lambda$update$2(JdbcTemplate.java:965) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.20.jar!/:5.3.20]... 68 moreCaused by: org.hsqldb.HsqlException: java.lang.IndexOutOfBoundsException: Index out of bounds: 347 >= 345at org.hsqldb.error.Error.error(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.SessionData.allocateLobForResult(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.Session.allocateResultLob(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCPreparedStatement.performPreExecute(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCPreparedStatement.fetchResult(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCPreparedStatement.executeUpdate(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar!/:?]at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar!/:?]at org.springframework.jdbc.core.JdbcTemplate.lambda$update$2(JdbcTemplate.java:965) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.20.jar!/:5.3.20]... 68 moreCaused by: java.lang.IndexOutOfBoundsException: Index out of bounds: 347 >= 345at org.hsqldb.lib.HsqlArrayList.get(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.persist.LobStoreMem.setBlockBytes(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.persist.LobManager.setBytesISNormal(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.persist.LobManager.setBytesIS(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.persist.LobManager.setCharsForNewClob(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.SessionData.allocateLobForResult(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.Session.allocateResultLob(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCPreparedStatement.performPreExecute(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCPreparedStatement.fetchResult(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at org.hsqldb.jdbc.JDBCPreparedStatement.executeUpdate(Unknown Source) ~[hsqldb-2.5.2.jar!/:2.5.2]at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar!/:?]at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar!/:?]at org.springframework.jdbc.core.JdbcTemplate.lambda$update$2(JdbcTemplate.java:965) ~[spring-jdbc-5.3.20.jar!/:5.3.20]at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.20.jar!/:5.3.20]... 68 more