Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Severe JobRunr Exception - Deleting a job that's in process #516

Open
dmurphy-ambra opened this issue Jul 12, 2022 · 8 comments
Open

Severe JobRunr Exception - Deleting a job that's in process #516

dmurphy-ambra opened this issue Jul 12, 2022 · 8 comments
Labels
bug Something isn't working
Milestone

Comments

@dmurphy-ambra
Copy link

SevereJobRunrException occurred in BackgroundJobServer efc46e4f-e598-4d47-a966-6ade15455ed7: Could not resolve ConcurrentJobModificationException

Runtime information

  • Timestamp: 2022-07-12T12:31:40.790Z
  • Location: BackgroundJobServer efc46e4f-e598-4d47-a966-6ade15455ed7
  • JobRunr Version: 5.1.4
  • StorageProvider: org.jobrunr.storage.sql.h2.H2StorageProvider
  • Java Version: 1.8.0-adoptopenjdk
  • Is running from nested jar: false

Background Job Servers

  • BackgroundJobServer id: efc46e4f-e598-4d47-a966-6ade15455ed7
    (workerPoolSize: 32, pollIntervalInSeconds: 15, firstHeartbeat: 2022-07-12T12:11:08.355Z, lastHeartbeat: 2022-07-12T12:31:36.146Z)

Diagnostics from exception

Concurrent modified jobs:

Job id: 28ad9534-aec7-3c06-98a5-f3a5ec0bc81d
Local version: 71; Storage version: 72
Local state: DELETED (at 2022-07-12T12:30:08.670Z) ← PROCESSING (at 2022-07-12T12:30:08.626Z on BackgroundJobServer efc46e4f-e598-4d47-a966-6ade15455ed7) ← ENQUEUED (at 2022-07-12T12:23:04.050Z)
Storage state: DELETED (at 2022-07-12T12:29:54.260Z) ← PROCESSING (at 2022-07-12T12:29:53.540Z on BackgroundJobServer efc46e4f-e598-4d47-a966-6ade15455ed7) ← ENQUEUED (at 2022-07-12T12:23:04.050Z)

Exception

org.jobrunr.SevereJobRunrException: Could not resolve ConcurrentJobModificationException
	at org.jobrunr.server.JobZooKeeper.processJobList(JobZooKeeper.java:233)
	at org.jobrunr.server.JobZooKeeper.updateJobsThatAreBeingProcessed(JobZooKeeper.java:93)
	at org.jobrunr.server.JobZooKeeper.run(JobZooKeeper.java:77)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
@cefalo-partha
Copy link

I have the same error. However, in our case the reason is known. Basically, if we have a running job that does not respond properly to "DELETE" requests, we start seeing this error.

For example: lets say I submit a job. The job starts PROCESSING. After a while, I DELETE the job. The job thread is interrupted. But if the job does not respond properly to the InterruptedException, we start getting this error. I actually think this is fine.

The problem that I have is that this eventually kills the background job server. And if spring-boot actuator is also enabled, takes down the whole app server since the liveness probes start to fail.

I tried to look into the code. There is this code in JobZooKeeper:

            if (exceptionCount.getAndIncrement() < 5) {
                LOGGER.warn(JobRunrException.SHOULD_NOT_HAPPEN_MESSAGE + " - Processing will continue.", e);
            } else {
                LOGGER.error("FATAL - JobRunr encountered too many processing exceptions. Shutting down.", shouldNotHappenException(e));
                backgroundJobServer.stop();
            }

So, basically, 5 of these errors and the BackgroundJobServer will stop. Sometimes even if the PROCESSING thread is stopped within a couple of seconds, we get this error. I think this is because the JobZooKeeper runs on a schedule and you can get unlucky.

What do you recommend for this? I can't guarantee that my jobs will be stopped as soon as an InterruptedException occurs. In our case, there are some DB code (via mybatis) that can't be interrupted and there is a delay of a few seconds before we actually can check the interrupted status of the thread. For an application that may run for months, 5 of these errors are bound to happen sooner or later.

@rdehuyss
Copy link
Contributor

Indeed, @cefalo-partha describes the exact reason. This is a duplicate of #467.

Normally, your job should be interruptible. If it's part of an external library off-course this is not ideal - especially IO operations like MyBatis should be interruptible in my eyes. If you're doing some CPU intensive work yourself, you can check whether the Thread is interrupted using Thread.currentThread().isInterrupted(). If that is the case, you should throw an InterruptedException or finish the job asap.

This will be solved in JobRunr 6 which will be released in Q3.

@rdehuyss rdehuyss added the bug Something isn't working label Jul 15, 2022
@rdehuyss rdehuyss added this to the 6.0.0 milestone Jul 21, 2022
@stale
Copy link

stale bot commented Aug 11, 2022

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the wontfix This will not be worked on label Aug 11, 2022
@rdehuyss rdehuyss removed the wontfix This will not be worked on label Aug 12, 2022
@AlexanderBartash
Copy link

AlexanderBartash commented Aug 31, 2022

I see a similar issue as well. We are using a cluster with 2 nodes.

<dependency>
  <groupId>org.jobrunr</groupId>
  <artifactId>jobrunr-spring-boot-starter</artifactId>
  <version>5.1.6</version>
</dependency>

Logs from node 1 where you can see how job 401cc7c0-52e3-499e-b501-07e736521540 failed to be updated.

[2022-08-31 06:30:08.379] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobServer.processJob:230 - Submitted BackgroundJobPerformer for job 401cc7c0-52e3-499e-b501-07e736521540 to executor service
[2022-08-31 06:30:08.379] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobServer.processJob:230 - Submitted BackgroundJobPerformer for job ed8bb64e-f200-49c5-a6fa-6799655d9b8d to executor service
[2022-08-31 06:30:08.381] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToProcessingRunJobFiltersAndReturnIfProcessingCanStart:71 - Job(id=ed8bb64e-f200-49c5-a6fa-6799655d9b8d, jobName='this-was-hidden') processing started
[2022-08-31 06:30:08.382] [backgroundjob-worker-pool-11-thread-3]  TRACE o.j.s.BackgroundJobPerformer.runActualJob:85 - Job(id=ed8bb64e-f200-49c5-a6fa-6799655d9b8d, jobName='this-was-hidden') is running
[2022-08-31 06:30:08.384] [backgroundjob-worker-pool-11-thread-4]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToProcessingRunJobFiltersAndReturnIfProcessingCanStart:71 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='this-was-hidden') processing started
[2022-08-31 06:30:08.385] [backgroundjob-worker-pool-11-thread-4]  TRACE o.j.s.BackgroundJobPerformer.runActualJob:85 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='this-was-hidden') is running
[2022-08-31 06:30:12.686] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:30:17.859] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:30:24.346] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:30:30.216] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:30:35.736] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:30:41.908] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:30:47.257] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:30:52.405] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:30:57.418] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:04.565] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:10.148] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:15.247] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:20.330] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:25.501] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:30.641] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:35.818] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:41.877] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:47.004] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:52.061] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:31:57.087] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:02.255] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:07.544] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:08.380] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:99 - Job(id=ed8bb64e-f200-49c5-a6fa-6799655d9b8d, jobName='this-was-hidden') processing succeeded
[2022-08-31 06:32:12.624] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:17.685] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:22.759] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:27.831] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:33.229] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:38.378] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:43.483] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:48.601] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:32:53.815] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
	at java.base/java.lang.String.valueOf(String.java:2951)
[2022-08-31 06:32:58.882] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:03.961] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:09.042] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:14.139] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:19.212] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:25.073] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:30.244] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:35.415] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:37.368] [backgroundjob-worker-pool-11-thread-2]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:99 - Job(id=154d2dd4-1bf6-4bc0-b5a7-78a0dbc8475f, jobName='this-was-hidden') processing succeeded
[2022-08-31 06:33:37.445] [backgroundjob-worker-pool-11-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForEnqueuedJobs:162 - Looking for enqueued jobs... 
[2022-08-31 06:33:38.352] [backgroundjob-worker-pool-11-thread-2]  DEBUG o.j.s.s.BasicWorkDistributionStrategy.getWorkPageRequest:39 - Can onboard 2 new work (occupiedWorkerCount = 2; workerCount = 4).
[2022-08-31 06:33:38.356] [backgroundjob-worker-pool-11-thread-2]  DEBUG o.j.s.BackgroundJobServer.processJob:230 - Submitted BackgroundJobPerformer for job 9f2f87df-cf78-4be1-a090-a1beec284d5d to executor service
[2022-08-31 06:33:38.356] [backgroundjob-worker-pool-11-thread-2]  DEBUG o.j.s.BackgroundJobServer.processJob:230 - Submitted BackgroundJobPerformer for job 4c589973-695f-4cbb-a07c-701bb30036fd to executor service
[2022-08-31 06:33:38.363] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToProcessingRunJobFiltersAndReturnIfProcessingCanStart:71 - Job(id=9f2f87df-cf78-4be1-a090-a1beec284d5d, jobName='this-was-hidden') processing started
[2022-08-31 06:33:38.363] [backgroundjob-worker-pool-11-thread-3]  TRACE o.j.s.BackgroundJobPerformer.runActualJob:85 - Job(id=9f2f87df-cf78-4be1-a090-a1beec284d5d, jobName='this-was-hidden') is running
[2022-08-31 06:33:38.365] [backgroundjob-worker-pool-11-thread-2]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToProcessingRunJobFiltersAndReturnIfProcessingCanStart:71 - Job(id=4c589973-695f-4cbb-a07c-701bb30036fd, jobName='this-was-hidden') processing started
[2022-08-31 06:33:38.365] [backgroundjob-worker-pool-11-thread-2]  TRACE o.j.s.BackgroundJobPerformer.runActualJob:85 - Job(id=4c589973-695f-4cbb-a07c-701bb30036fd, jobName='this-was-hidden') is running
[2022-08-31 06:33:40.535] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:45.692] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:50.843] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:33:56.485] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:01.732] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:06.741] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:20.897] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.pollIntervalInSecondsTimeBoxIsAboutToPass:266 - JobRunr is passing the poll interval in seconds timebox because of too many tasks.
[2022-08-31 06:34:25.915] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:54.332] [backgroundjob-zookeeper-pool-10-thread-2]  WARN o.j.s.JobZooKeeper.run:82 - JobRunr encountered a problematic exception. Please create a bug report (if possible, provide the code to reproduce this and the stacktrace) - Processing will continue.
org.jobrunr.SevereJobRunrException: Could not resolve ConcurrentJobModificationException
	at org.jobrunr.server.JobZooKeeper.processJobList(JobZooKeeper.java:212)
	at org.jobrunr.server.JobZooKeeper.updateJobsThatAreBeingProcessed(JobZooKeeper.java:92)
	at org.jobrunr.server.JobZooKeeper.run(JobZooKeeper.java:76)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:34:59.332] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:59.446] [backgroundjob-zookeeper-pool-10-thread-2]  WARN o.j.s.JobZooKeeper.run:82 - JobRunr encountered a problematic exception. Please create a bug report (if possible, provide the code to reproduce this and the stacktrace) - Processing will continue.
org.jobrunr.SevereJobRunrException: Could not resolve ConcurrentJobModificationException
	at org.jobrunr.server.JobZooKeeper.processJobList(JobZooKeeper.java:212)
	at org.jobrunr.server.JobZooKeeper.updateJobsThatAreBeingProcessed(JobZooKeeper.java:92)
	at org.jobrunr.server.JobZooKeeper.run(JobZooKeeper.java:76)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:35:15.472] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:35:15.501] [backgroundjob-zookeeper-pool-10-thread-2]  WARN o.j.s.JobZooKeeper.run:82 - JobRunr encountered a problematic exception. Please create a bug report (if possible, provide the code to reproduce this and the stacktrace) - Processing will continue.
org.jobrunr.SevereJobRunrException: Could not resolve ConcurrentJobModificationException
	at org.jobrunr.server.JobZooKeeper.processJobList(JobZooKeeper.java:212)
	at org.jobrunr.server.JobZooKeeper.updateJobsThatAreBeingProcessed(JobZooKeeper.java:92)
	at org.jobrunr.server.JobZooKeeper.run(JobZooKeeper.java:76)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:35:20.501] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:35:20.566] [backgroundjob-zookeeper-pool-10-thread-2]  WARN o.j.s.JobZooKeeper.run:82 - JobRunr encountered a problematic exception. Please create a bug report (if possible, provide the code to reproduce this and the stacktrace) - Processing will continue.
org.jobrunr.SevereJobRunrException: Could not resolve ConcurrentJobModificationException
	at org.jobrunr.server.JobZooKeeper.processJobList(JobZooKeeper.java:212)
	at org.jobrunr.server.JobZooKeeper.updateJobsThatAreBeingProcessed(JobZooKeeper.java:92)
	at org.jobrunr.server.JobZooKeeper.run(JobZooKeeper.java:76)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:35:25.566] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:35:25.605] [backgroundjob-zookeeper-pool-10-thread-2]  WARN o.j.s.JobZooKeeper.run:82 - JobRunr encountered a problematic exception. Please create a bug report (if possible, provide the code to reproduce this and the stacktrace) - Processing will continue.
org.jobrunr.SevereJobRunrException: Could not resolve ConcurrentJobModificationException
	at org.jobrunr.server.JobZooKeeper.processJobList(JobZooKeeper.java:212)
	at java.base/java.lang.StringBuilder.append(StringBuilder.java:172)
	at org.jobrunr.server.JobZooKeeper.updateJobsThatAreBeingProcessed(JobZooKeeper.java:92)
	at org.jobrunr.server.JobZooKeeper.run(JobZooKeeper.java:76)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:35:25.913] [backgroundjob-worker-pool-11-thread-4]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:99 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='this-was-hidden') processing succeeded
[2022-08-31 06:35:25.915] [backgroundjob-worker-pool-11-thread-4]  ERROR o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:109 - ERROR - could not update job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='this-was-hidden') to SUCCEEDED state
org.jobrunr.storage.ConcurrentJobModificationException: The following jobs where concurrently updated: 401cc7c0-52e3-499e-b501-07e736521540
	at org.jobrunr.storage.sql.common.JobTable.save(JobTable.java:77)
	at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.save(DefaultSqlStorageProvider.java:176)
	at org.jobrunr.storage.ThreadSafeStorageProvider.save(ThreadSafeStorageProvider.java:105)
	at org.jobrunr.server.BackgroundJobPerformer.saveAndRunStateRelatedJobFilters(BackgroundJobPerformer.java:139)
	at org.jobrunr.server.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters(BackgroundJobPerformer.java:101)
	at org.jobrunr.server.BackgroundJobPerformer.performJob(BackgroundJobPerformer.java:63)
	at org.jobrunr.server.BackgroundJobPerformer.run(BackgroundJobPerformer.java:41)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	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:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:35:30.607] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:35:30.625] [backgroundjob-zookeeper-pool-10-thread-2]  ERROR o.j.s.JobZooKeeper.run:84 - FATAL - JobRunr encountered too many processing exceptions. Shutting down.
org.jobrunr.SevereJobRunrException: Could not resolve ConcurrentJobModificationException
	at org.jobrunr.server.JobZooKeeper.processJobList(JobZooKeeper.java:212)
	at org.jobrunr.server.JobZooKeeper.updateJobsThatAreBeingProcessed(JobZooKeeper.java:92)
	at org.jobrunr.server.JobZooKeeper.run(JobZooKeeper.java:76)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:35:30.626] [backgroundjob-zookeeper-pool-10-thread-2]  INFO o.j.s.BackgroundJobServer.stop:136 - BackgroundJobServer and BackgroundJobPerformers - stopping (waiting for all jobs to complete - max 10 seconds)
[2022-08-31 06:35:32.834] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:99 - Job(id=9f2f87df-cf78-4be1-a090-a1beec284d5d, jobName='this-was-hidden') processing succeeded
[2022-08-31 06:35:32.835] [backgroundjob-worker-pool-11-thread-3]  ERROR o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:109 - ERROR - could not update job(id=9f2f87df-cf78-4be1-a090-a1beec284d5d, jobName='this-was-hidden') to SUCCEEDED state
org.jobrunr.storage.ConcurrentJobModificationException: The following jobs where concurrently updated: 9f2f87df-cf78-4be1-a090-a1beec284d5d
	at org.jobrunr.storage.sql.common.JobTable.save(JobTable.java:77)
	at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.save(DefaultSqlStorageProvider.java:176)
	at org.jobrunr.storage.ThreadSafeStorageProvider.save(ThreadSafeStorageProvider.java:105)
	at org.jobrunr.server.BackgroundJobPerformer.saveAndRunStateRelatedJobFilters(BackgroundJobPerformer.java:139)
	at org.jobrunr.server.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters(BackgroundJobPerformer.java:101)
	at org.jobrunr.server.BackgroundJobPerformer.performJob(BackgroundJobPerformer.java:63)
	at org.jobrunr.server.BackgroundJobPerformer.run(BackgroundJobPerformer.java:41)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	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:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:35:32.836] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.JobZooKeeper.checkForEnqueuedJobs:162 - Looking for enqueued jobs... 

Logs from node 2 at the time when the errors happened on node 1:

[2022-08-31 06:34:34.834] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForRecurringJobs:110 - Looking for recurring jobs... 
[2022-08-31 06:34:34.836] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.processRecurringJobs:177 - Found 19 recurring jobs
[2022-08-31 06:34:34.837] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForScheduledJobs:116 - Looking for scheduled jobs... 
[2022-08-31 06:34:34.852] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForOrphanedJobs:123 - Looking for orphan jobs... 
[2022-08-31 06:34:34.856] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForSucceededJobsThanCanGoToDeletedState:131 - Looking for succeeded jobs that can go to the deleted state... 
[2022-08-31 06:34:35.060] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForJobsThatCanBeDeleted:148 - Looking for deleted jobs that can be deleted permanently... 
[2022-08-31 06:34:40.255] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:41.044] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForRecurringJobs:110 - Looking for recurring jobs... 
[2022-08-31 06:34:41.046] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.processRecurringJobs:177 - Found 19 recurring jobs
[2022-08-31 06:34:41.046] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForScheduledJobs:116 - Looking for scheduled jobs... 
[2022-08-31 06:34:41.048] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForOrphanedJobs:123 - Looking for orphan jobs... 
[2022-08-31 06:34:41.050] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForSucceededJobsThanCanGoToDeletedState:131 - Looking for succeeded jobs that can go to the deleted state... 
[2022-08-31 06:34:41.132] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForJobsThatCanBeDeleted:148 - Looking for deleted jobs that can be deleted permanently... 
[2022-08-31 06:34:46.228] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:46.337] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForRecurringJobs:110 - Looking for recurring jobs... 
[2022-08-31 06:34:46.338] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.processRecurringJobs:177 - Found 19 recurring jobs
[2022-08-31 06:34:46.339] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForScheduledJobs:116 - Looking for scheduled jobs... 
[2022-08-31 06:34:46.341] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForOrphanedJobs:123 - Looking for orphan jobs... 
[2022-08-31 06:34:46.359] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForSucceededJobsThanCanGoToDeletedState:131 - Looking for succeeded jobs that can go to the deleted state... 
[2022-08-31 06:34:46.419] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForJobsThatCanBeDeleted:148 - Looking for deleted jobs that can be deleted permanently... 
[2022-08-31 06:34:51.494] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:51.557] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForRecurringJobs:110 - Looking for recurring jobs... 
[2022-08-31 06:34:51.558] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.processRecurringJobs:177 - Found 19 recurring jobs
[2022-08-31 06:34:51.558] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForScheduledJobs:116 - Looking for scheduled jobs... 
[2022-08-31 06:34:51.566] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForOrphanedJobs:123 - Looking for orphan jobs... 
[2022-08-31 06:34:51.692] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForSucceededJobsThanCanGoToDeletedState:131 - Looking for succeeded jobs that can go to the deleted state... 
[2022-08-31 06:34:51.733] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForJobsThatCanBeDeleted:148 - Looking for deleted jobs that can be deleted permanently... 
[2022-08-31 06:34:56.802] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:34:56.886] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForRecurringJobs:110 - Looking for recurring jobs... 
[2022-08-31 06:34:56.887] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.processRecurringJobs:177 - Found 19 recurring jobs
[2022-08-31 06:34:56.891] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForScheduledJobs:116 - Looking for scheduled jobs... 
[2022-08-31 06:34:56.901] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForOrphanedJobs:123 - Looking for orphan jobs... 
[2022-08-31 06:34:56.904] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForSucceededJobsThanCanGoToDeletedState:131 - Looking for succeeded jobs that can go to the deleted state... 
[2022-08-31 06:34:56.993] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForJobsThatCanBeDeleted:148 - Looking for deleted jobs that can be deleted permanently... 
[2022-08-31 06:35:02.072] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:35:02.114] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:99 - Job(id=4f27e38d-0dc6-4e12-9a43-ae1089e2521c, jobName='') processing succeeded
[2022-08-31 06:35:02.222] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForRecurringJobs:110 - Looking for recurring jobs... 
[2022-08-31 06:35:02.224] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.processRecurringJobs:177 - Found 19 recurring jobs
[2022-08-31 06:35:02.224] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForScheduledJobs:116 - Looking for scheduled jobs... 
[2022-08-31 06:35:02.231] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.JobZooKeeper.checkForEnqueuedJobs:162 - Looking for enqueued jobs... 
[2022-08-31 06:35:02.231] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.s.BasicWorkDistributionStrategy.getWorkPageRequest:39 - Can onboard 2 new work (occupiedWorkerCount = 2; workerCount = 4).
[2022-08-31 06:35:02.234] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobServer.processJob:230 - Submitted BackgroundJobPerformer for job 65fac800-28e4-43cb-b97d-98bcd69054da to executor service
[2022-08-31 06:35:02.234] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobServer.processJob:230 - Submitted BackgroundJobPerformer for job efef3e3f-1451-463d-835e-5dc739c8bc73 to executor service
[2022-08-31 06:35:02.237] [backgroundjob-worker-pool-11-thread-4]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToProcessingRunJobFiltersAndReturnIfProcessingCanStart:71 - Job(id=65fac800-28e4-43cb-b97d-98bcd69054da, jobName='') processing started
[2022-08-31 06:35:02.238] [backgroundjob-worker-pool-11-thread-4]  TRACE o.j.s.BackgroundJobPerformer.runActualJob:85 - Job(id=65fac800-28e4-43cb-b97d-98bcd69054da, jobName='') is running
[2022-08-31 06:35:02.257] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForOrphanedJobs:123 - Looking for orphan jobs... 
[2022-08-31 06:35:02.263] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToProcessingRunJobFiltersAndReturnIfProcessingCanStart:71 - Job(id=efef3e3f-1451-463d-835e-5dc739c8bc73, jobName='') processing started
[2022-08-31 06:35:02.263] [backgroundjob-worker-pool-11-thread-3]  TRACE o.j.s.BackgroundJobPerformer.runActualJob:85 - Job(id=efef3e3f-1451-463d-835e-5dc739c8bc73, jobName='') is running
[2022-08-31 06:35:02.266] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForSucceededJobsThanCanGoToDeletedState:131 - Looking for succeeded jobs that can go to the deleted state... 
[2022-08-31 06:35:02.375] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForJobsThatCanBeDeleted:148 - Looking for deleted jobs that can be deleted permanently... 
[2022-08-31 06:35:07.447] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.updateJobsThatAreBeingProcessed:91 - Updating currently processed jobs... 
[2022-08-31 06:35:07.518] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForRecurringJobs:110 - Looking for recurring jobs... 
[2022-08-31 06:35:07.519] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.processRecurringJobs:177 - Found 19 recurring jobs
[2022-08-31 06:35:07.519] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForScheduledJobs:116 - Looking for scheduled jobs... 
[2022-08-31 06:35:07.522] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForOrphanedJobs:123 - Looking for orphan jobs... 
[2022-08-31 06:35:07.525] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForSucceededJobsThanCanGoToDeletedState:131 - Looking for succeeded jobs that can go to the deleted state... 
[2022-08-31 06:35:07.615] [backgroundjob-zookeeper-pool-10-thread-2]  DEBUG o.j.s.JobZooKeeper.checkForJobsThatCanBeDeleted:148 - Looking for deleted jobs that can be deleted permanently... 
[2022-08-31 06:35:11.140] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:99 - Job(id=efef3e3f-1451-463d-835e-5dc739c8bc73, jobName='') processing succeeded

@AlexanderBartash
Copy link

It seems to be that this bug is a bit more serious than it might look initially because jobs get run multiple times which in some cases is worse than not running them at all.

It looks like Jobrunr is updating 'updatedAt' field on all running jobs and if that coincides in time with some job transferring to SUCCEEDED or FAILED state the transactions conflict.

As the result of this bug the job is not being marked as finished and gets run another time, which I do see in logs:

[2022-08-31 06:30:02.093] DEBUG o.j.s.AbstractJobScheduler.saveJob:135 - Created Job with id 401cc7c0-52e3-499e-b501-07e736521540
[2022-08-31 06:30:08.379] [backgroundjob-worker-pool-11-thread-3]  DEBUG o.j.s.BackgroundJobServer.processJob:230 - Submitted BackgroundJobPerformer for job 401cc7c0-52e3-499e-b501-07e736521540 to executor service
[2022-08-31 06:30:08.384] [backgroundjob-worker-pool-11-thread-4]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToProcessingRunJobFiltersAndReturnIfProcessingCanStart:71 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='xxx') processing started

### The first execution
[2022-08-31 06:30:08.385] [backgroundjob-worker-pool-11-thread-4]  TRACE o.j.s.BackgroundJobPerformer.runActualJob:85 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='xxx') is running

[2022-08-31 06:35:25.913] [backgroundjob-worker-pool-11-thread-4]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:99 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='xxx') processing succeeded
[2022-08-31 06:35:25.915] [backgroundjob-worker-pool-11-thread-4]  ERROR o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:109 - ERROR - could not update job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='xxx') to SUCCEEDED state
org.jobrunr.storage.ConcurrentJobModificationException: The following jobs where concurrently updated: 401cc7c0-52e3-499e-b501-07e736521540
	at org.jobrunr.storage.sql.common.JobTable.save(JobTable.java:77)
	at org.jobrunr.storage.sql.common.DefaultSqlStorageProvider.save(DefaultSqlStorageProvider.java:176)
	at org.jobrunr.storage.ThreadSafeStorageProvider.save(ThreadSafeStorageProvider.java:105)
	at org.jobrunr.server.BackgroundJobPerformer.saveAndRunStateRelatedJobFilters(BackgroundJobPerformer.java:139)
	at org.jobrunr.server.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters(BackgroundJobPerformer.java:101)
	at org.jobrunr.server.BackgroundJobPerformer.performJob(BackgroundJobPerformer.java:63)
	at org.jobrunr.server.BackgroundJobPerformer.run(BackgroundJobPerformer.java:41)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	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:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
[2022-08-31 06:41:23.484] [backgroundjob-worker-pool-11-thread-1]  DEBUG o.j.s.BackgroundJobServer.processJob:230 - Submitted BackgroundJobPerformer for job 401cc7c0-52e3-499e-b501-07e736521540 to executor service
[2022-08-31 06:41:23.489] [backgroundjob-worker-pool-11-thread-2]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToProcessingRunJobFiltersAndReturnIfProcessingCanStart:71 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='xxx') processing started


### The second execution
[2022-08-31 06:41:23.489] [backgroundjob-worker-pool-11-thread-2]  TRACE o.j.s.BackgroundJobPerformer.runActualJob:85 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='xxx') is running

[2022-08-31 06:45:33.576] [backgroundjob-worker-pool-11-thread-2]  DEBUG o.j.s.BackgroundJobPerformer.updateJobStateToSucceededAndRunJobFilters:99 - Job(id=401cc7c0-52e3-499e-b501-07e736521540, jobName='xxx') processing succeeded

@AlexanderBartash
Copy link

AlexanderBartash commented Aug 31, 2022

@rdehuyss How much $ would it take to fix this? Just asking.

@rdehuyss
Copy link
Contributor

Hi @AlexanderBartash : let's perhaps connect as I'm not completely following. I've reached out to you via LinkedIn.

@rdehuyss
Copy link
Contributor

Could you also attach the automatic report generation from JobRunr? Normally, if such an error occurs, JobRunr allows to generate a Github issue automatically from the dashboard.

This info helps in diagnosing root causes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
Status: Todo
Development

No branches or pull requests

4 participants