Uploaded image for project: 'mod-source-record-manager'
  1. mod-source-record-manager
  2. MODSOURMAN-706

Error loading MappingParametersSnapshot (Kiwi HF2)

    XMLWordPrintable

Details

    • 3
    • Folijet Support
    • Kiwi (R3 2021) Hot Fix #2
    • Yes
    • Approved by CPT on the Slack release-bug-triage channel 15 Feb 2022
    • Third party component integration

    Description

      Overview:

      When doing a CREATE import, the following error was encountered intermittently in mod-srs.  As a result the import was not completed successfully and mod-srs created 50 records less than desired (50,000).  However, this error was not consistently reproducible at all times, but the PTF has seen many occasions of it to warrant a deeper investigation.

       

      2021-11-22T16:19:59.891-05:00 WARNING: Exception thrown during asynchronous load 2021-11-22T16:19:59.891-05:00 WARNING: Exception thrown during asynchronous load 2021-11-22T16:19:59.891-05:00 java.util.concurrent.CompletionException: org.folio.services.exceptions.CacheLoadingException: Error loading MappingParametersSnapshot by jobExecutionId: '4a13fa36-ce19-48ed-a66b-f9d2bd5ce1fd', status code: 500, response message: Internal Server Error, Please contact System Administrator or try again021-11-22T16:19:59.891-05:00 at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:367)2021-11-22T16:19:59.891-05:00 at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:376)2021-11-22T16:19:59.891-05:00 at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1074)2021-11-22T16:19:59.891-05:00 at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)2021-11-22T16:19:59.891-05:00 at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)2021-11-22T16:19:59.891-05:00 at io.vertx.core.Future.lambda$toCompletionStage$2(Future.java:360)2021-11-22T16:19:59.891-05:00 at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:124)2021-11-22T16:19:59.891-05:00 at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:62)2021-11-22T16:19:59.891-05:00 at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:179)2021-11-22T16:19:59.891-05:00 at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23)2021-11-22T16:19:59.891-05:00 at io.vertx.core.Promise.complete(Promise.java:66)2021-11-22T16:19:59.891-05:00 at org.folio.dataimport.util.RestUtil.lambda$handleResponse$0(RestUtil.java:182)2021-11-22T16:19:59.891-05:00 at io.vertx.ext.web.client.impl.HttpContext.handleDispatchResponse(HttpContext.java:371)2021-11-22T16:19:59.891-05:00 at io.vertx.ext.web.client.impl.HttpContext.execute(HttpContext.java:358)2021-11-22T16:19:59.891-05:00 at io.vertx.ext.web.client.impl.HttpContext.next(HttpContext.java:336)2021-11-22T16:19:59.891-05:00 at io.vertx.ext.web.client.impl.HttpContext.fire(HttpContext.java:303)2021-11-22T16:19:59.891-05:00 at io.vertx.ext.web.client.impl.HttpContext.dispatchResponse(HttpContext.java:265)2021-11-22T16:19:59.891-05:00 at io.vertx.ext.web.client.impl.HttpContext.lambda$null$8(HttpContext.java:528)2021-11-22T16:19:59.891-05:00 at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:96)2021-11-22T16:19:59.891-05:00 at io.vertx.core.impl.WorkerContext.lambda$run$1(WorkerContext.java:82)2021-11-22T16:19:59.891-05:00 at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)2021-11-22T16:19:59.891-05:00 at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)2021-11-22T16:19:59.891-05:00 at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)2021-11-22T16:19:59.891-05:00 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)2021-11-22T16:19:59.891-05:00 at java.base/java.lang.Thread.run(Thread.java:829)2021-11-22T16:19:59.891-05:00 Caused by: org.folio.services.exceptions.CacheLoadingException: Error loading MappingParametersSnapshot by jobExecutionId: '4a13fa36-ce19-48ed-a66b-f9d2bd5ce1fd', status code: 500, response message: Internal Server Error, Please contact System Administrator or try again2021-11-22T16:19:59.891-05:00 at org.folio.services.caches.MappingParametersSnapshotCache.lambda$3(MappingParametersSnapshotCache.java:66)2021-11-22T16:19:59.891-05:00 at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072)2021-11-22T16:19:59.891-05:00 ... 22 more2021-11-22T16:19:59.892-05:00 21:19:59.892 [vert.x-worker-thread-17] ERROR ocessingEventHandler [1044351405eqId] Failed to handle event DI_INVENTORY_INSTANCE_CREATED_READY_FOR_POST_PROCESSING2021-11-22T16:19:59.892-05:00 java.util.concurrent.CompletionException: org.folio.services.exceptions.CacheLoadingException: Error loading MappingParametersSnapshot by jobExecutionId: '4a13fa36-ce19-48ed-a66b-f9d2bd5ce1fd', status code: 500, response message: Internal Server Error, Please contact System Administrator or try again2021-11-22T16:19:59.892-05:00 at java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:367) ~[?:?]2021-11-22T16:19:59.892-05:00 at java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:376) ~[?:?]2021-11-22T16:19:59.892-05:00 at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1074) ~[?:?]2021-11-22T16:19:59.892-05:00 at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]2021-11-22T16:19:59.892-05:00 at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.Future.lambda$toCompletionStage$2(Future.java:360) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:124) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:62) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:179) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.Promise.complete(Promise.java:66) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at org.folio.dataimport.util.RestUtil.lambda$handleResponse$0(RestUtil.java:182) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.ext.web.client.impl.HttpContext.handleDispatchResponse(HttpContext.java:371) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.ext.web.client.impl.HttpContext.execute(HttpContext.java:358) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.ext.web.client.impl.HttpContext.next(HttpContext.java:336) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.ext.web.client.impl.HttpContext.fire(HttpContext.java:303) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.ext.web.client.impl.HttpContext.dispatchResponse(HttpContext.java:265) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.ext.web.client.impl.HttpContext.lambda$null$8(HttpContext.java:528) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:96) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.impl.WorkerContext.lambda$run$1(WorkerContext.java:82) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]2021-11-22T16:19:59.892-05:00 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]2021-11-22T16:19:59.892-05:00 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [ms.jar:?]2021-11-22T16:19:59.892-05:00 at java.lang.Thread.run(Thread.java:829) [?:?]2021-11-22T16:19:59.892-05:00 Caused by: org.folio.services.exceptions.CacheLoadingException: Error loading MappingParametersSnapshot by jobExecutionId: '4a13fa36-ce19-48ed-a66b-f9d2bd5ce1fd', status code: 500, response message: Internal Server Error, Please contact System Administrator or try again2021-11-22T16:19:59.892-05:00 at org.folio.services.caches.MappingParametersSnapshotCache.lambda$3(MappingParametersSnapshotCache.java:66) ~[ms.jar:?]2021-11-22T16:19:59.892-05:00 at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072) ~[?:?]2021-11-22T16:19:59.892-05:00 ... 22 more
      

       

      Additionally, this error was encountered:

       

       21:13:00.627 [vert.x-worker-thread-4] ERROR RecordDaoImpl [1043926504eqId] Failed to save records 21:13:00.627 [vert.x-worker-thread-4] ERROR RecordDaoImpl [1043926504eqId] Failed to save records2021-11-22T16:13:00.628-05:00 org.jooq.exception.DataAccessException: SQL [select "snapshots_lb"."id", "snapshots_lb"."status", "snapshots_lb"."processing_started_date", "snapshots_lb"."created_by_user_id", "snapshots_lb"."created_date", "snapshots_lb"."updated_by_user_id", "snapshots_lb"."updated_date" from "snapshots_lb" where "snapshots_lb"."id" = cast(? as uuid)]; FATAL: terminating connection due to administrator command2021-11-22T16:13:00.628-05:00 at org.jooq_3.13.6.POSTGRES.debug(Unknown Source) ~[?:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.Tools.translate(Tools.java:2753) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:755) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:385) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.AbstractResultQuery.fetchLazy(AbstractResultQuery.java:502) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.AbstractResultQuery.fetchLazy(AbstractResultQuery.java:471) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.AbstractResultQuery.fetchLazyNonAutoClosing(AbstractResultQuery.java:485) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.AbstractResultQuery.fetchOne(AbstractResultQuery.java:654) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.AbstractResultQuery.fetchOptional(AbstractResultQuery.java:840) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.SelectImpl.fetchOptional(SelectImpl.java:3065) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.dao.RecordDaoImpl.lambda$24(RecordDaoImpl.java:383) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:636) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:633) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:564) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.Tools$12$1.block(Tools.java:4926) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3128) ~[?:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.Tools$12.get(Tools.java:4923) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:616) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:533) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:633) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.dao.RecordDaoImpl.saveRecords(RecordDaoImpl.java:377) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.services.RecordServiceImpl.saveRecords(RecordServiceImpl.java:119) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.services.ParsedRecordChunksKafkaHandler.handle(ParsedRecordChunksKafkaHandler.java:87) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.kafka.KafkaConsumerWrapper.handle(KafkaConsumerWrapper.java:171) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.kafka.KafkaConsumerWrapper.handle(KafkaConsumerWrapper.java:24) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.kafka.client.consumer.impl.KafkaConsumerImpl.lambda$handler$1(KafkaConsumerImpl.java:81) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.kafka.client.consumer.impl.KafkaReadStreamImpl.run(KafkaReadStreamImpl.java:237) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.kafka.client.consumer.impl.KafkaReadStreamImpl.lambda$schedule$8(KafkaReadStreamImpl.java:192) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:96) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.core.impl.WorkerContext.lambda$run$1(WorkerContext.java:82) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]2021-11-22T16:13:00.628-05:00 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]2021-11-22T16:13:00.628-05:00 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [ms.jar:?]2021-11-22T16:13:00.628-05:00 at java.lang.Thread.run(Thread.java:829) [?:?]2021-11-22T16:13:00.628-05:00 Suppressed: org.jooq.exception.DataAccessException: Cannot set autoCommit2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:217) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultTransactionProvider.brace(DefaultTransactionProvider.java:246) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultTransactionProvider.rollback(DefaultTransactionProvider.java:229) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:588) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.Tools$12$1.block(Tools.java:4926) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3128) ~[?:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.Tools$12.get(Tools.java:4923) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:616) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:533) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:633) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.dao.RecordDaoImpl.saveRecords(RecordDaoImpl.java:377) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.services.RecordServiceImpl.saveRecords(RecordServiceImpl.java:119) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.services.ParsedRecordChunksKafkaHandler.handle(ParsedRecordChunksKafkaHandler.java:87) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.kafka.KafkaConsumerWrapper.handle(KafkaConsumerWrapper.java:171) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.folio.kafka.KafkaConsumerWrapper.handle(KafkaConsumerWrapper.java:24) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.kafka.client.consumer.impl.KafkaConsumerImpl.lambda$handler$1(KafkaConsumerImpl.java:81) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.kafka.client.consumer.impl.KafkaReadStreamImpl.run(KafkaReadStreamImpl.java:237) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.kafka.client.consumer.impl.KafkaReadStreamImpl.lambda$schedule$8(KafkaReadStreamImpl.java:192) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:96) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.core.impl.WorkerContext.lambda$run$1(WorkerContext.java:82) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]2021-11-22T16:13:00.628-05:00 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]2021-11-22T16:13:00.628-05:00 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [ms.jar:?]2021-11-22T16:13:00.628-05:00 at java.lang.Thread.run(Thread.java:829) [?:?]2021-11-22T16:13:00.628-05:00 Caused by: org.postgresql.util.PSQLException: Connection has been closed.2021-11-22T16:13:00.628-05:00 at org.postgresql.ds.PGPooledConnection$ConnectionHandler.invoke(PGPooledConnection.java:326) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at com.sun.proxy.$Proxy87.setAutoCommit(Unknown Source) ~[?:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:214) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 ... 24 more2021-11-22T16:13:00.628-05:00 Caused by: org.postgresql.util.PSQLException: FATAL: terminating connection due to administrator command2021-11-22T16:13:00.628-05:00 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:153) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at jdk.internal.reflect.GeneratedMethodAccessor97.invoke(Unknown Source) ~[?:?]2021-11-22T16:13:00.628-05:00 at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]2021-11-22T16:13:00.628-05:00 at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]2021-11-22T16:13:00.628-05:00 at org.postgresql.ds.PGPooledConnection$StatementHandler.invoke(PGPooledConnection.java:441) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at com.sun.proxy.$Proxy88.execute(Unknown Source) ~[?:?]2021-11-22T16:13:00.628-05:00 at org.jooq.tools.jdbc.DefaultPreparedStatement.execute(DefaultPreparedStatement.java:209) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.Tools.executeStatementAndGetFirstResultSet(Tools.java:3992) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.AbstractResultQuery.execute(AbstractResultQuery.java:295) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:371) ~[ms.jar:?]2021-11-22T16:13:00.628-05:00 ... 31 more2021-11-22T16:13:00.630-05:00 21:13:00.629 [vert.x-worker-thread-4] ERROR rdChunksKafkaHandler [1043926506eqId] RecordCollection processing has failed with errors... correlationId: 255a9369-aa66-4007-aafb-d93008e15a30, chunkNumber 4503-42021-11-22T16:13:00.630-05:00 org.jooq.exception.DataAccessException: SQL [select "snapshots_lb"."id", "snapshots_lb"."status", "snapshots_lb"."processing_started_date", "snapshots_lb"."created_by_user_id", "snapshots_lb"."created_date", "snapshots_lb"."updated_by_user_id", "snapshots_lb"."updated_date" from "snapshots_lb" where "snapshots_lb"."id" = cast(? as uuid)]; FATAL: terminating connection due to administrator command2021-11-22T16:13:00.630-05:00 at org.jooq_3.13.6.POSTGRES.debug(Unknown Source) ~[?:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.Tools.translate(Tools.java:2753) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:755) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:385) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.AbstractResultQuery.fetchLazy(AbstractResultQuery.java:502) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.AbstractResultQuery.fetchLazy(AbstractResultQuery.java:471) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.AbstractResultQuery.fetchLazyNonAutoClosing(AbstractResultQuery.java:485) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.AbstractResultQuery.fetchOne(AbstractResultQuery.java:654) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.AbstractResultQuery.fetchOptional(AbstractResultQuery.java:840) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.SelectImpl.fetchOptional(SelectImpl.java:3065) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.dao.RecordDaoImpl.lambda$24(RecordDaoImpl.java:383) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:636) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext$3.run(DefaultDSLContext.java:633) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:564) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.Tools$12$1.block(Tools.java:4926) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3128) ~[?:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.Tools$12.get(Tools.java:4923) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:616) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:533) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:633) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.dao.RecordDaoImpl.saveRecords(RecordDaoImpl.java:377) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.services.RecordServiceImpl.saveRecords(RecordServiceImpl.java:119) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.services.ParsedRecordChunksKafkaHandler.handle(ParsedRecordChunksKafkaHandler.java:87) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.kafka.KafkaConsumerWrapper.handle(KafkaConsumerWrapper.java:171) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.kafka.KafkaConsumerWrapper.handle(KafkaConsumerWrapper.java:24) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.kafka.client.consumer.impl.KafkaConsumerImpl.lambda$handler$1(KafkaConsumerImpl.java:81) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.kafka.client.consumer.impl.KafkaReadStreamImpl.run(KafkaReadStreamImpl.java:237) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.kafka.client.consumer.impl.KafkaReadStreamImpl.lambda$schedule$8(KafkaReadStreamImpl.java:192) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:96) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.core.impl.WorkerContext.lambda$run$1(WorkerContext.java:82) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]2021-11-22T16:13:00.630-05:00 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]2021-11-22T16:13:00.630-05:00 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [ms.jar:?]2021-11-22T16:13:00.630-05:00 at java.lang.Thread.run(Thread.java:829) [?:?]2021-11-22T16:13:00.630-05:00 Suppressed: org.jooq.exception.DataAccessException: Cannot set autoCommit2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:217) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultTransactionProvider.brace(DefaultTransactionProvider.java:246) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultTransactionProvider.rollback(DefaultTransactionProvider.java:229) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext.lambda$transactionResult0$0(DefaultDSLContext.java:588) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.Tools$12$1.block(Tools.java:4926) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3128) ~[?:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.Tools$12.get(Tools.java:4923) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext.transactionResult0(DefaultDSLContext.java:616) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext.transactionResult(DefaultDSLContext.java:533) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultDSLContext.transaction(DefaultDSLContext.java:633) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.dao.RecordDaoImpl.saveRecords(RecordDaoImpl.java:377) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.services.RecordServiceImpl.saveRecords(RecordServiceImpl.java:119) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.services.ParsedRecordChunksKafkaHandler.handle(ParsedRecordChunksKafkaHandler.java:87) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.kafka.KafkaConsumerWrapper.handle(KafkaConsumerWrapper.java:171) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.folio.kafka.KafkaConsumerWrapper.handle(KafkaConsumerWrapper.java:24) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.kafka.client.consumer.impl.KafkaConsumerImpl.lambda$handler$1(KafkaConsumerImpl.java:81) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.kafka.client.consumer.impl.KafkaReadStreamImpl.run(KafkaReadStreamImpl.java:237) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.kafka.client.consumer.impl.KafkaReadStreamImpl.lambda$schedule$8(KafkaReadStreamImpl.java:192) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:96) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.core.impl.WorkerContext.lambda$run$1(WorkerContext.java:82) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]2021-11-22T16:13:00.630-05:00 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]2021-11-22T16:13:00.630-05:00 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [ms.jar:?]2021-11-22T16:13:00.630-05:00 at java.lang.Thread.run(Thread.java:829) [?:?]2021-11-22T16:13:00.630-05:00 Caused by: org.postgresql.util.PSQLException: Connection has been closed.2021-11-22T16:13:00.630-05:00 at org.postgresql.ds.PGPooledConnection$ConnectionHandler.invoke(PGPooledConnection.java:326) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at com.sun.proxy.$Proxy87.setAutoCommit(Unknown Source) ~[?:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.DefaultConnectionProvider.setAutoCommit(DefaultConnectionProvider.java:214) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 ... 24 more2021-11-22T16:13:00.630-05:00 Caused by: org.postgresql.util.PSQLException: FATAL: terminating connection due to administrator command2021-11-22T16:13:00.630-05:00 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:153) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at jdk.internal.reflect.GeneratedMethodAccessor97.invoke(Unknown Source) ~[?:?]2021-11-22T16:13:00.630-05:00 at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]2021-11-22T16:13:00.630-05:00 at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]2021-11-22T16:13:00.630-05:00 at org.postgresql.ds.PGPooledConnection$StatementHandler.invoke(PGPooledConnection.java:441) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at com.sun.proxy.$Proxy88.execute(Unknown Source) ~[?:?]2021-11-22T16:13:00.630-05:00 at org.jooq.tools.jdbc.DefaultPreparedStatement.execute(DefaultPreparedStatement.java:209) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.Tools.executeStatementAndGetFirstResultSet(Tools.java:3992) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.AbstractResultQuery.execute(AbstractResultQuery.java:295) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:371) ~[ms.jar:?]2021-11-22T16:13:00.630-05:00 ... 31 more
      

       

      Steps to Reproduce:

      1. Log into PTF env: https://pre-kiwi-cap1.int.aws.folio.org/data-import
      2. Load a 25K import file and use the PTF - Create 2 profile.
      3. If the job fails, check mod-srs for the error above.

      Expected Results:

      The job would complete successfully without any errors

      Actual Results:

      The job failed with the errors above.

      Additional Information:

      TestRail: Results

        Attachments

          1. ebz-s9001366-20211220-Add-1.marc
            1006 kB
          2. image-2021-11-24-15-58-35-349.png
            image-2021-11-24-15-58-35-349.png
            224 kB
          3. image-2021-12-01-10-52-30-702.png
            image-2021-12-01-10-52-30-702.png
            145 kB
          4. image-2022-01-20-11-02-16-796.png
            image-2022-01-20-11-02-16-796.png
            61 kB
          5. image-2022-01-20-11-03-49-587.png
            image-2022-01-20-11-03-49-587.png
            105 kB
          6. image-2022-03-16-14-00-40-215.png
            image-2022-03-16-14-00-40-215.png
            68 kB
          7. Screen Shot 2022-01-28 at 9.38.49 AM.png
            Screen Shot 2022-01-28 at 9.38.49 AM.png
            525 kB
          8. SRMlog.csv
            1.06 MB
          9. SRSlog.csv
            212 kB

          Issue Links

            Activity

              People

                ruslan_lavrov Ruslan Lavrov
                mtraneis Martin Tran
                Votes:
                0 Vote for this issue
                Watchers:
                10 Start watching this issue

                Dates

                  Created:
                  Updated:
                  Resolved:

                  TestRail: Runs

                    TestRail: Cases