Fix detection of stuck cronjobs
authorTim Düsterhus <duesterhus@woltlab.com>
Tue, 30 Jun 2020 12:15:03 +0000 (14:15 +0200)
committerTim Düsterhus <duesterhus@woltlab.com>
Tue, 30 Jun 2020 13:00:24 +0000 (15:00 +0200)
Consider the following scenario:

A cronjob is scheduled to run `0 * * * *` (i.e. every hour). The cronjob
successfully executes it's 23:00 execution belated on 23:30. Then the
nextExec will be 00:00. afterNextExec will be 01:00.

During night time nothing happens within the community, until at 05:xx when
the first user wakes up and opens their web browser. It restores two tabs
with our community and fetches them. Now the following will happen:

1. Request 1: Notices that the cronjob is due (00:00 < 05:xx). Setting
              the cronjob's state to pending and starting execution.
2. Request 2: Notices that the cronjob is overdue (01:00 < 05:xx,
              state = pending). Logging an error about a stuck job and
              setting the cronjob's state to ready.
3. Request 1: Finishes executing the cronjob and updates nextExec = 06:00,
              afterNextExec = 07:00, also setting the cronjob's state to
              ready.

Fix this issue by updating the times for the next executions together with
the update of the state in a single database query / transaction. This will
prevent other requests from seeing the cronjob with state = pending or
state = executing and an way outdated date.

A side effect of this change is that cronjobs will match the intended
schedule better.

Consider the following:

A cronjob running every minute, taking 5 seconds to execute. The execution
is triggered at 00:00:58. It will finish executing 00:01:03. Previously the
nextExec would be set to 00:02:00, now it will be 00:01:00. Thus the first
request after 00:01:03 (i.e. once the state is set back to ready) will
trigger execution, more closely matching the intended schedule.

wcfsetup/install/files/lib/system/cronjob/CronjobScheduler.class.php

index 180efe13299291dece89abf10b3e01997073d80a..784ecf3c8d2c5efc8052be6681d6caa117eb89bc 100644 (file)
@@ -86,16 +86,9 @@ class CronjobScheduler extends SingletonFactory {
                                $this->logResult($logEditor);
                        }
                        
-                       // get time of next execution
-                       $nextExec = $cronjobEditor->getNextExec();
-                       $afterNextExec = $cronjobEditor->getNextExec($nextExec + 120);
-                       
                        // mark cronjob as done
                        $cronjobEditor->update([
-                               'lastExec' => TIME_NOW,
-                               'afterNextExec' => $afterNextExec,
                                'failCount' => 0,
-                               'nextExec' => $nextExec,
                                'state' => Cronjob::READY
                        ]);
                }
@@ -206,11 +199,23 @@ class CronjobScheduler extends SingletonFactory {
                                Cronjob::READY,
                                TIME_NOW
                        ]);
+                       /** @var Cronjob $cronjob */
                        while ($cronjob = $statement->fetchObject(Cronjob::class)) {
                                $cronjobEditor = new CronjobEditor($cronjob);
                                
                                // Mark the cronjob as pending to prevent concurrent requests from executing it.
-                               $cronjobEditor->update(['state' => Cronjob::PENDING]);
+                               $data = ['state' => Cronjob::PENDING];
+                               
+                               // Update next execution time.
+                               // This needs to be done before executing the job to allow for a proper detection of
+                               // stuck jobs. If the timestamps are updated after executing then concurrent requests
+                               // might believe that a cronjob is stuck, despite the cronjob just having started just
+                               // a few milliseconds before.
+                               $data['nextExec'] = $cronjob->getNextExec(TIME_NOW);
+                               $data['afterNextExec'] = $cronjob->getNextExec($data['nextExec'] + 120);
+                               $data['lastExec'] = TIME_NOW;
+                               
+                               $cronjobEditor->update($data);
                                
                                $this->cronjobEditors[] = $cronjobEditor;
                        }