Job not fired again after connection to database was lost

[buschluschni]

Version: 4.42.0
Provider: JdbcTemplateLockProvider
Config: @EnableSchedulerLock(defaultLockAtMostFor = "10m", defaultLockAtLeastFor = "10m")

When connection to database is lost during a job run (and then re-established), it will not be triggered again, although the lock_until is in the past. ("n.j.s.core.DefaultLockingTaskExecutor Not executing 'xxxx'. It's locked.")
After a restart (Spring Boot) it is triggered again as expected.

[lukas-krecan]

Hi, thanks for feedback. Is there anything you see in the logs? Stack traces?

[buschluschni]

No, I turned on DEBUG loglevel, there are no errors/stacktraces, just the debug message
_n.j.s.core.DefaultLockingTaskExecutor Not executing 'xxxx'. It's locked.
is written each time the job should be triggered.

[lukas-krecan]

Does it happen just after the start of the app or after several executions of the job?

[buschluschni]

It only happens when connection to database is temporarily unavailable during a job run. No matter how often the job was already executed.

[lukas-krecan]

From the code it can't happen 🙂 Would you be willing to help me to debug it? I can release a new version with more logging and it may give us some hints.

[buschluschni]

I'd like to help you debug it 👍

[lukas-krecan]

Hi, I have just release version 4.43.0 with more logging, can you please try? Thank you

[buschluschni]

Hi, thanks for the new version. I tried it out, but I'm afraid the output won't help you much (Shedlock lock time is 1m, Scheduler runs every min):

2022-12-05 06:53:00.311 DEBUG 2628 --- [   scheduling-1] n.j.s.core.DefaultLockingTaskExecutor : Locked 'PriceInitJob', lock will be held at most until 2022-12-05T05:54:00.014Z
...
2022-12-05 06:55:00.004 DEBUG 2628 --- [   scheduling-1] n.j.s.core.DefaultLockingTaskExecutor : Not executing 'PriceInitJob'. It's locked.
...
2022-12-05 06:56:00.020 DEBUG 2628 --- [   scheduling-1] n.j.s.core.DefaultLockingTaskExecutor : Not executing 'PriceInitJob'. It's locked.

[lukas-krecan]

Can you please check what's in the ShedLock DB table (lock_until)?

[buschluschni]

Sorry for the late response...

Log file entry:
Locked 'PriceInitJob', lock will be held at most until 2022-12-14T05:53:00.021Z

DB entry
'PriceInitJob', '2022-12-14 06:53:00.021', '2022-12-14 06:52:00.329', 'DSWD12025'

Update:
after one hour (difference between UTC and my local timezone) it was fired again.

[lukas-krecan]

Ok, the one hour difference is an interesting clue (unless it's a coincidence). Do you have usingDbTime in you lock provider config or not? If so, which DB do you use?

[crain]

I can add some more detail here.

The issue occurs if the database connection is lost just before a job finishes and want to unlock through:

ShedLock/shedlock-core/src/main/java/net/javacrumbs/shedlock/core/DefaultLockingTaskExecutor.java

Line 75 in 884eacf

activeLock.unlock();

After this I am seeing the same log outputs mentioned above.

Everything is fine if the database connection is lost before/after executing the job.

I hope this helps - let me know if I can add more information to understand the issue.

My setup:

Gradle

implementation('net.javacrumbs.shedlock:shedlock-spring:5.13.0')
implementation('net.javacrumbs.shedlock:shedlock-provider-jdbc-template:5.13.0')

My config:

@Bean
public LockProvider lockProvider(final DataSource dataSource) {
  final JdbcTemplateLockProvider.Configuration configuration = JdbcTemplateLockProvider.Configuration.builder()
      .withTableName("my_lock")
      .withJdbcTemplate(new JdbcTemplate(dataSource))
      .usingDbTime()
      .build();

  return new JdbcTemplateLockProvider(configuration);
  }