search

lukas-krecan / ShedLock

Distributed lock for your scheduled tasks
Apache License 2.0
3.65k stars 514 forks source link

"Deadlock found when trying to get lock; try restarting transaction" on MariaDB and Spring #1094

Closed mateuszjarzyna closed 2 years ago

mateuszjarzyna commented 2 years ago

I have a few "microservices" (java apps) that shares the database (and also the spring_jobs_lock table, but each job has different name). Each "microservice" is running on two nodes and has one scheduled job. I'm getting wired deadlock in my apps.

  1. Which version do you use 4.36.0

        <shedlock.version>4.36.0</shedlock.version>

    <dependency>
        <groupId>net.javacrumbs.shedlock</groupId>
        <artifactId>shedlock-spring</artifactId>
        <version>${shedlock.version}</version>
    </dependency>
    <dependency>
        <groupId>net.javacrumbs.shedlock</groupId>
        <artifactId>shedlock-provider-jdbc-template</artifactId>
        <version>${shedlock.version}</version>
    </dependency>

  2. Which Lock Provider JDBC, full configuration below

    
@Configuration
@EnableScheduling
@EnableSchedulerLock(defaultLockAtMostFor = "50s")
class SchedulerConfiguration {

@Bean
public LockProvider lockProvider(DataSource dataSource) {
    return new JdbcTemplateLockProvider(
            JdbcTemplateLockProvider.Configuration.builder()
                    .withTableName("spring_jobs_lock")
                    .withJdbcTemplate(new JdbcTemplate(dataSource))
                    .usingDbTime()
                    .build()
    );
}

}


3. ShedLock configuration
```java
    @Scheduled(cron = "*/10 * * * * *")
    @SchedulerLock(
            name = "my-job",
            lockAtMostFor = "9000",
            lockAtLeastFor = "9000"
    )
    void removeExpired() {
        //....
    }
  1. ShedLock logs 
    2022-07-04 10:12:10.007 DEBUG --- [scheduling-1] rovider.jdbctemplate.SqlStatementsSource : [systemId:;] : Using MySqlServerTimeStatementsSource (for MariaDB)
2022-07-04 10:12:10.076 DEBUG --- [scheduling-1] shedlock.core.DefaultLockingTaskExecutor : [systemId:;] : Not executing 'my-job'. It's locked.
2022-07-04 10:12:20.018 ERROR --- [scheduling-1] jdbctemplate.JdbcTemplateStorageAccessor : [systemId:;] : Unexpected exception
org.springframework.transaction.TransactionSystemException: JDBC commit failed; nested exception is java.sql.SQLTransactionRollbackException: (conn=17800809) Deadlock found when trying to get lock; try restarting transaction
at org.springframework.jdbc.datasource.DataSourceTransactionManager.translateException(DataSourceTransactionManager.java:435)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:336)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:152)
at net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateStorageAccessor.execute(JdbcTemplateStorageAccessor.java:115)
at net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateStorageAccessor.updateRecord(JdbcTemplateStorageAccessor.java:81)
at net.javacrumbs.shedlock.support.StorageBasedLockProvider.doLock(StorageBasedLockProvider.java:91)
at net.javacrumbs.shedlock.support.StorageBasedLockProvider.lock(StorageBasedLockProvider.java:65)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
at jdk.proxy2/jdk.proxy2.$Proxy92.lock(Unknown Source)
at net.javacrumbs.shedlock.core.DefaultLockingTaskExecutor.executeWithLock(DefaultLockingTaskExecutor.java:63)
at net.javacrumbs.shedlock.spring.aop.MethodProxyScheduledLockAdvisor$LockingInterceptor.invoke(MethodProxyScheduledLockAdvisor.java:86)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698)
at com.mycompany.RemoveExpiredSubscriptionJob$$EnhancerBySpringCGLIB$$ebc30431.removeExpired(<generated>)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84)
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:95)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.sql.SQLTransactionRollbackException: (conn=17800809) Deadlock found when trying to get lock; try restarting transaction
at org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.createException(ExceptionFactory.java:76)
at org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.create(ExceptionFactory.java:158)
at org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:266)
at org.mariadb.jdbc.MariaDbStatement.executeInternal(MariaDbStatement.java:366)
at org.mariadb.jdbc.MariaDbStatement.execute(MariaDbStatement.java:504)
at org.mariadb.jdbc.MariaDbConnection.commit(MariaDbConnection.java:741)
at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:387)
at com.zaxxer.hikari.pool.HikariProxyConnection.commit(HikariProxyConnection.java)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:333)
... 33 common frames omitted
Caused by: org.mariadb.jdbc.internal.util.exceptions.MariaDbSqlException: Deadlock found when trying to get lock; try restarting transaction
at org.mariadb.jdbc.internal.util.exceptions.MariaDbSqlException.of(MariaDbSqlException.java:34)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.exceptionWithQuery(AbstractQueryProtocol.java:194)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:262)
at org.mariadb.jdbc.MariaDbStatement.executeInternal(MariaDbStatement.java:360)
... 38 common frames omitted
Caused by: java.sql.SQLException: Deadlock found when trying to get lock; try restarting transaction
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.readErrorPacket(AbstractQueryProtocol.java:1694)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.readPacket(AbstractQueryProtocol.java:1556)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.getResult(AbstractQueryProtocol.java:1519)
at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:256)
... 39 common frames omitted
2022-07-04 10:12:20.019 DEBUG --- [scheduling-1] shedlock.core.DefaultLockingTaskExecutor : [systemId:;] : Not executing 'my-job'. It's locked.
2022-07-04 10:12:30.015 ERROR --- [scheduling-1] jdbctemplate.JdbcTemplateStorageAccessor : [systemId:;] : Unexpected exception
org.springframework.transaction.TransactionSystemException: JDBC commit failed; nested exception is java.sql.SQLTransactionRollbackException: (conn=17800809) Deadlock found when trying to get lock; try restarting transaction
2022-07-04 10:17:30.015 DEBUG --- [scheduling-1] shedlock.core.DefaultLockingTaskExecutor : [systemId:;] : Not executing 'my-job'. It's locked.
2022-07-04 10:17:40.008 DEBUG --- [scheduling-1] shedlock.core.DefaultLockingTaskExecutor : [systemId:;] : Locked 'my-job', lock will be held at most until 2022-07-04T10:17:49Z
////// domain logs, ommiting
2022-07-04 10:17:40.011 DEBUG --- [scheduling-1] shedlock.core.DefaultLockingTaskExecutor : [systemId:;] : Task finished, lock 'my-job' will be released at 2022-07-04T10:17:49Z
2022-07-04 10:17:50.015 ERROR --- [scheduling-1] jdbctemplate.JdbcTemplateStorageAccessor : [systemId:;] : Unexpected exception
org.springframework.transaction.TransactionSystemException: JDBC commit failed; nested exception is java.sql.SQLTransactionRollbackException: (conn=17800809) Deadlock found when trying to get lock; try restarting transaction
    at org.springframework.jdbc.datasource.DataSourceTransactionManager.translateException(DataSourceTransactionManager.java:435)
    at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:336)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)
    at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:152)
    at net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateStorageAccessor.execute(JdbcTemplateStorageAccessor.java:115)
    at net.javacrumbs.shedlock.provider.jdbctemplate.JdbcTemplateStorageAccessor.updateRecord(JdbcTemplateStorageAccessor.java:81)
    at net.javacrumbs.shedlock.support.StorageBasedLockProvider.doLock(StorageBasedLockProvider.java:91)
    at net.javacrumbs.shedlock.support.StorageBasedLockProvider.lock(StorageBasedLockProvider.java:65)
    at jdk.internal.reflect.GeneratedMethodAccessor57.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
    at jdk.proxy2/jdk.proxy2.$Proxy92.lock(Unknown Source)
    at net.javacrumbs.shedlock.core.DefaultLockingTaskExecutor.executeWithLock(DefaultLockingTaskExecutor.java:63)
    at net.javacrumbs.shedlock.spring.aop.MethodProxyScheduledLockAdvisor$LockingInterceptor.invoke(MethodProxyScheduledLockAdvisor.java:86)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698)
    at com.my-company.RemoveExpiredSubscriptionJob$$EnhancerBySpringCGLIB$$ebc30431.removeExpired(<generated>)
    at jdk.internal.reflect.GeneratedMethodAccessor54.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84)
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
    at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:95)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.sql.SQLTransactionRollbackException: (conn=17800809) Deadlock found when trying to get lock; try restarting transaction
    at org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.createException(ExceptionFactory.java:76)
    at org.mariadb.jdbc.internal.util.exceptions.ExceptionFactory.create(ExceptionFactory.java:158)
    at org.mariadb.jdbc.MariaDbStatement.executeExceptionEpilogue(MariaDbStatement.java:266)
    at org.mariadb.jdbc.MariaDbStatement.executeInternal(MariaDbStatement.java:366)
    at org.mariadb.jdbc.MariaDbStatement.execute(MariaDbStatement.java:504)
    at org.mariadb.jdbc.MariaDbConnection.commit(MariaDbConnection.java:741)
    at com.zaxxer.hikari.pool.ProxyConnection.commit(ProxyConnection.java:387)
    at com.zaxxer.hikari.pool.HikariProxyConnection.commit(HikariProxyConnection.java)
    at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:333)
    ... 31 common frames omitted
Caused by: org.mariadb.jdbc.internal.util.exceptions.MariaDbSqlException: Deadlock found when trying to get lock; try restarting transaction
    at org.mariadb.jdbc.internal.util.exceptions.MariaDbSqlException.of(MariaDbSqlException.java:34)
    at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.exceptionWithQuery(AbstractQueryProtocol.java:194)
    at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:262)
    at org.mariadb.jdbc.MariaDbStatement.executeInternal(MariaDbStatement.java:360)
    ... 36 common frames omitted
Caused by: java.sql.SQLException: Deadlock found when trying to get lock; try restarting transaction
    at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.readErrorPacket(AbstractQueryProtocol.java:1694)
    at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.readPacket(AbstractQueryProtocol.java:1556)
    at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.getResult(AbstractQueryProtocol.java:1519)
    at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:256)
    ... 37 common frames omitted
2022-07-04 10:17:50.015 DEBUG --- [scheduling-1] shedlock.core.DefaultLockingTaskExecutor : [systemId:;] : Not executing 'my-job'. It's locked.
2022-07-04 10:18:00.015 ERROR --- [scheduling-1] jdbctemplate.JdbcTemplateStorageAccessor : [systemId:;] : Unexpected exception
org.springframework.transaction.TransactionSystemException: JDBC commit failed; nested exception is java.sql.SQLTransactionRollbackException: (conn=17800809) Deadlock found when trying to get lock; try restarting transaction

Expected behavior Jobs should be run without exception.

Actual behavior Sometimes the job is running with no problem, sometimes I can see Not executing 'my-job'. It's locked. message, but sometimes I got the deadlock exception with no additional logs.

I've also checked that when the exception occurs, the second node works fine, the job is executed

More details: Database: mysql Ver 15.1 Distrib 10.4.24-MariaDB, for Linux (x86_64) using readline 5.1 Spring boot version: 2.6.1

lukas-krecan commented 2 years ago

Hi, I am sorry, bute there is not much I can do to help you. It seems like a MySql issue (maybe related to this one). You can try JdbcStorageAccessor which works in autocommit mode (without transactions), it might help.

mateuszjarzyna commented 2 years ago

It works, thanks a lot!

For people in the future with the same problem: This is how the LockProvider looks like:

@Configuration
@EnableScheduling
@EnableSchedulerLock(defaultLockAtMostFor = "50s")
class SchedulerConfiguration {

    @Bean
    public LockProvider lockProvider(DataSource dataSource) {
        return new JdbcLockProvider(dataSource, "spring_jobs_lock");
    }

}

Also, there is a need to remove theshedlock-provider-jdbc-template dependency and add a new one:

        <dependency>
            <groupId>net.javacrumbs.shedlock</groupId>
            <artifactId>shedlock-provider-jdbc</artifactId>
            <version>${shedlock.version}</version>
        </dependency>