Spring boot + ShedLock with Postgresql DB, while running in rancher POD getting the n.j.s.p.j.JdbcTemplateStorageAccessor : Unexpected exception

[narasimha-reddy-kr]

Read the documentation
Read the documentation, especially the troubleshooting section.

Update to the latest version.

Describe the bug - We have two PODS running with the application (Springboot + Shedlock with Postgresql db) that has a scheduler which will run every 10 mins. Assume we have two pods running able to see the entry in the shedlock table and running successfully on POD1 but in other we are getting below exception on the same time. error details and running logs. There is slight seconds gap both trying to access the table.

1. version : <dependency> <groupId>net.javacrumbs.shedlock</groupId> <artifactId>shedlock-spring</artifactId> <version>4.47.0</version> </dependency> <dependency> <groupId>net.javacrumbs.shedlock</groupId> <artifactId>shedlock-provider-jdbc-template</artifactId> <version>4.47.0</version> </dependency>

2. Which Lock Provider `-@configuration
   @EnableSchedulerLock(defaultLockAtMostFor = "PT5M")
   public class SchedulerDataSource {

   @bean
   public LockProvider lockProvider(DataSource dataSource) {
   return new JdbcTemplateLockProvider(
   JdbcTemplateLockProvider.Configuration.builder()
   .withJdbcTemplate(new JdbcTemplate(dataSource))
   .usingDbTime()
   .build()
   );
   }
   }`

3. ShedLock configuration - @Scheduled(cron = "* */10 * ? * *") @SchedulerLock(name = "processingTask",lockAtLeastFor = "PT5M", lockAtMostFor = "PT7M") public void processData() { LockAssert.assertLocked(); // DO business logic }

4. ShedLock logs
   POD1 (Success) - 2024-04-23 14:20:00.350 DEBUG 1 --- [ scheduling-1] n.j.s.core.DefaultLockingTaskExecutor : Locked 'itemDeletesProcessingTask', lock will be held at most until 2024-04-23T18:27:00.002Z 2024-04-23T18:20:00.358153599Z 2024-04-23 14:20:00.357 INFO 1 --- [ scheduling-1] c.k.m.p.s.ItemDeleteDataProcessor : process Item deletes started 2024-04-23T18:20:00.611795870Z 2024-04-23 14:20:00.611 INFO 1 --- [ scheduling-1] c.k.m.p.s.DataProcessor : process started.

POD2 (Exception) - **2024-04-23 14:20:00.330 ** ERROR 1 --- [ scheduling-1] n.j.s.p.j.JdbcTemplateStorageAccessor : Unexpected exception Tue, Apr 23 2024 2:20:00 pm2024-04-23T18:20:00.332247321Z org.springframework.transaction.TransactionSystemException: JDBC commit failed; nested exception is org.postgresql.util.PSQLException: ERROR: Transaction 6d0f0c9d-c1a6-44c4-b6e7-8146740bb981 expired or aborted by a conflict: 40001 2024-04-23T18:20:00.332252922Z at org.springframework.jdbc.datasource.DataSourceTransactionManager.translateException(DataSourceTransactionManager.java:435) ~[spring-jdbc-5.3.5.jar!/:5.3.5] Tue, Apr 23 2024 2:20:00 pm at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:336) ~[spring-jdbc-5.3.5.jar!/:5.3.5] 2024-04-23T18:20:00.332260622Z at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743) ~[spring-tx-5.3.5.jar!/:5.3.5] 2024-04-23T18:20:00.332263822Z at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) ~[spring-tx-5.3.5.jar!/:5.3.5] 2024-04-23T18:20:00.332267922Z at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:152) ~[spring-tx-5.3.5.jar!/:5.3.5] 2024-04-23T18:20:00.332270922Z at net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateStorageAccessor.execute(JdbcTemplateStorageAccessor.java:117) ~[shedlock-provider-jdbc-template-4.47.0.jar!/:na] 2024-04-23T18:20:00.332275322Z at net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateStorageAccessor.updateRecord(JdbcTemplateStorageAccessor.java:82) ~[shedlock-provider-jdbc-template-4.47.0.jar!/:na] 2024-04-23T18:20:00.332278223Z at net.javacrumbs.shedlock.support.StorageBasedLockProvider.doLock(StorageBasedLockProvider.java:93) ~[shedlock-core-4.47.0.jar!/:na] 2024-04-23T18:20:00.332281223Z at net.javacrumbs.shedlock.support.StorageBasedLockProvider.lock(StorageBasedLockProvider.java:65) ~[shedlock-core-4.47.0.jar!/:na] Tue, Apr 23 2024 2:20:00 pm at jdk.internal.reflect.GeneratedMethodAccessor89.invoke(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332287823Z at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332290923Z at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332294023Z at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.3.5.jar!/:5.3.5] 2024-04-23T18:20:00.332297023Z at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208) ~[spring-aop-5.3.5.jar!/:5.3.5] 2024-04-23T18:20:00.332300023Z at com.sun.proxy.$Proxy112.lock(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332302924Z at net.javacrumbs.shedlock.core.DefaultLockingTaskExecutor.executeWithLock(DefaultLockingTaskExecutor.java:63) ~[shedlock-core-4.47.0.jar!/:na] 2024-04-23T18:20:00.332306124Z at net.javacrumbs.shedlock.spring.aop.MethodProxyScheduledLockAdvisor$LockingInterceptor.invoke(MethodProxyScheduledLockAdvisor.java:86) ~[shedlock-spring-4.47.0.jar!/:na] Tue, Apr 23 2024 2:20:00 pm at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.5.jar!/:5.3.5] 2024-04-23T18:20:00.332312024Z at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) ~[spring-aop-5.3.5.jar!/:5.3.5] Tue, Apr 23 2024 2:20:00 pm at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692) ~[spring-aop-5.3.5.jar!/:5.3.5] 2024-04-23T18:20:00.332332425Z at com.kroger.merchandising.pricedelivery.scheduler.ItemDeleteDataProcessor$$EnhancerBySpringCGLIB$$307fe984.processItemDeleteData() ~[classes!/:1.0.0-SNAPSHOT] 2024-04-23T18:20:00.332335625Z at jdk.internal.reflect.GeneratedMethodAccessor87.invoke(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332338625Z at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332341625Z at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332344725Z at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.3.32.jar!/:5.3.32] 2024-04-23T18:20:00.332347625Z at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.3.32.jar!/:5.3.32] 2024-04-23T18:20:00.332350526Z at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:95) ~[spring-context-5.3.32.jar!/:5.3.32] 2024-04-23T18:20:00.332353426Z at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332356426Z at java.base/java.util.concurrent.FutureTask.run(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332374227Z at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332377727Z at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332381027Z at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:na] 2024-04-23T18:20:00.332383927Z at java.base/java.lang.Thread.run(Unknown Source) ~[na:na] Tue, Apr 23 2024 2:20:00 pmCaused by: org.postgresql.util.PSQLException: ERROR: Transaction 6d0f0c9d-c1a6-44c4-b6e7-8146740bb981 expired or aborted by a conflict: 40001 2024-04-23T18:20:00.332389727Z at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2725) ~[postgresql-42.7.2.jar!/:42.7.2]

DEBUG 1 --- [ scheduling-1] n.j.s.core.DefaultLockingTaskExecutor : Not executing 'itemDeletesProcessingTask'. It's locked.
DEBUG 1 --- [ scheduling-1] n.j.s.core.DefaultLockingTaskExecutor : Not executing 'itemDeletesProcessingTask'. It's locked.
--- [ scheduling-1] n.j.s.core.DefaultLockingTaskExecutor : Not executing 'itemDeletesProcessingTask'. It's locked.

Expected behavior
How to medicate this erroring in other POD2?, why it is even trying multiple attempts and first time it has above exception.

Actual behavior
What happened instead.
Error in the second POD2.

https://stackoverflow.com/questions/78375433/spring-boot-shedlock-with-postgresql-db-while-running-in-rancher-pod-getting

[lukas-krecan]

Can you please upgrade to the newest version?

[narasimha-reddy-kr]

Thanks lukas-krecan for quick response.
We are in the Java 11 version and spring boot 2.5.15, noticing maven build issues when we use the newer version. And we have a plan to migrate Java latest version.

org.springframework.boot
spring-boot-starter-parent
2.5.15

With latest version is that issue will be resolved?.

[lukas-krecan]

It should be