From f20c4cbed3de7f3fcc49810d5721b257d5a56d43 Mon Sep 17 00:00:00 2001 From: Ben Burgess <88810029+bx80@users.noreply.github.com> Date: Wed, 2 Feb 2022 12:19:23 +1300 Subject: Retry scheduled tasks on failure (#18335) * Catch and log errors for scheduled tasks * Added retry on exception mechanism for scheduled tasks * Replace error code with custom exception * Fix/workaround for SchedulerTest mock breaking retry list option loading * Log warning instead of info if a task has failed three times * Added basic tests, minor code improvements * Test fix * Fix for test * Added integration test to check that only tasks that throw exceptions are scheduled for retry --- core/Scheduler/RetryableException.php | 9 ++ core/Scheduler/Schedule/SpecificTime.php | 6 + core/Scheduler/Scheduler.php | 44 ++++++- core/Scheduler/Timetable.php | 88 +++++++++++++ plugins/ScheduledReports/API.php | 5 +- .../PHPUnit/Integration/RetryScheduledTaskTest.php | 143 +++++++++++++++++++++ tests/PHPUnit/System/TrackerTest.php | 3 +- tests/PHPUnit/Unit/Scheduler/TimetableTest.php | 15 +++ 8 files changed, 308 insertions(+), 5 deletions(-) create mode 100644 core/Scheduler/RetryableException.php create mode 100644 tests/PHPUnit/Integration/RetryScheduledTaskTest.php diff --git a/core/Scheduler/RetryableException.php b/core/Scheduler/RetryableException.php new file mode 100644 index 0000000000..70650089a8 --- /dev/null +++ b/core/Scheduler/RetryableException.php @@ -0,0 +1,9 @@ +scheduledTime = $scheduledTime; + } + } \ No newline at end of file diff --git a/core/Scheduler/Scheduler.php b/core/Scheduler/Scheduler.php index b126ccf7b2..0d7b8296bb 100644 --- a/core/Scheduler/Scheduler.php +++ b/core/Scheduler/Scheduler.php @@ -8,7 +8,6 @@ namespace Piwik\Scheduler; -use Exception; use Piwik\Piwik; use Piwik\Timer; use Psr\Log\LoggerInterface; @@ -54,6 +53,12 @@ class Scheduler */ private $isRunningTask = false; + /** + * Should the last run task be scheduled for a retry + * @var bool + */ + private $scheduleRetry = false; + /** * @var Timetable */ @@ -145,8 +150,36 @@ class Scheduler if ($shouldExecuteTask) { $readFromOption = true; + $this->scheduleRetry = false; $message = $this->executeTask($task); + // Task has thrown an exception and should be scheduled for a retry + if ($this->scheduleRetry) { + + if($this->timetable->getRetryCount($task->getName()) == 3) { + + // Task has already been retried three times, give up + $this->timetable->clearRetryCount($task->getName()); + + $this->logger->warning("Scheduler: '{task}' has already been retried three times, giving up", + ['task' => $task->getName()]); + + } else { + + $readFromOption = true; + $rescheduledDate = $this->timetable->rescheduleTaskAndRunInOneHour($task); + $this->timetable->incrementRetryCount($task->getName()); + + $this->logger->info("Scheduler: '{task}' retry scheduled for {date}", + ['task' => $task->getName(), 'date' => $rescheduledDate]); + } + $this->scheduleRetry = false; + } else { + if ($this->timetable->getRetryCount($task->getName()) > 0) { + $this->timetable->clearRetryCount($task->getName()); + } + } + $executionResults[] = array('task' => $taskName, 'output' => $message); } } @@ -275,8 +308,15 @@ class Scheduler $callable = array($task->getObjectInstance(), $task->getMethodName()); call_user_func($callable, $task->getMethodParameter()); $message = $timer->__toString(); - } catch (Exception $e) { + } catch (\Exception $e) { + $this->logger->error("Scheduler: Error {errorMessage} for task '{task}'", + ['errorMessage' => $e->getMessage(), 'task' => $task->getName()]); $message = 'ERROR: ' . $e->getMessage(); + + // If the task has indicated that retrying on exception is safe then flag for rescheduling + if ($e instanceof RetryableException) { + $this->scheduleRetry = true; + } } $this->isRunningTask = false; diff --git a/core/Scheduler/Timetable.php b/core/Scheduler/Timetable.php index 47e6b094d7..9073b73dc6 100644 --- a/core/Scheduler/Timetable.php +++ b/core/Scheduler/Timetable.php @@ -19,8 +19,10 @@ use Piwik\Date; class Timetable { const TIMETABLE_OPTION_STRING = "TaskScheduler.timetable"; + const RETRY_OPTION_STRING = "TaskScheduler.retryList"; private $timetable; + private $retryList; public function __construct() { @@ -37,6 +39,11 @@ class Timetable $this->timetable = $timetable; } + public function setRetryList($retryList) + { + $this->retryList = $retryList; + } + /** * @param Task[] $activeTasks */ @@ -124,6 +131,17 @@ class Timetable return $tomorrow; } + public function rescheduleTaskAndRunInOneHour(Task $task) + { + $oneHourFromNow = Date::factory('now')->addHour(1); + + // update the scheduled time + $this->timetable[$task->getName()] = $oneHourFromNow->getTimestamp(); + $this->save(); + + return $oneHourFromNow; + } + public function save() { Option::set(self::TIMETABLE_OPTION_STRING, serialize($this->timetable)); @@ -149,4 +167,74 @@ class Timetable $this->timetable = $unserializedTimetable === false ? array() : $unserializedTimetable; } + + /** + * Read the retry list option from the database + * + * @throws \Throwable + */ + private function readRetryList() + { + Option::clearCachedOption(self::RETRY_OPTION_STRING); + $retryData = Option::get(self::RETRY_OPTION_STRING); + $unserializedRetryList = Common::safe_unserialize($retryData); + + $this->retryList = $unserializedRetryList === false ? array() : $unserializedRetryList; + } + + /** + * Save the retry list option to the database + */ + public function saveRetryList() + { + Option::set(self::RETRY_OPTION_STRING, serialize($this->retryList)); + } + + /** + * Remove a task from the retry list + * + * @param string $taskName + */ + public function clearRetryCount(string $taskName) + { + if (isset($this->retryList[$taskName])) { + unset($this->retryList[$taskName]); + $this->saveRetryList(); + } + } + + /** + * Increment the retry counter for a task + * + * @param string $taskName + */ + public function incrementRetryCount(string $taskName) + { + $this->readRetryList(); + if (!isset($this->retryList[$taskName])) { + $this->retryList[$taskName] = 0; + } + $this->retryList[$taskName]++; + $this->saveRetryList(); + } + + /** + * Return the current number of retries for a task + * + * @param string $taskName + * + * @return int + */ + public function getRetryCount(string $taskName) : int + { + $this->readRetryList(); + + // Ignore excessive retry counts, workaround for SchedulerTest mock + if (!isset($this->retryList[$taskName]) || $this->retryList[$taskName] > 10000) { + return 0; + } + + return $this->retryList[$taskName]; + } + } diff --git a/plugins/ScheduledReports/API.php b/plugins/ScheduledReports/API.php index e0934f45b8..2259c0e56b 100644 --- a/plugins/ScheduledReports/API.php +++ b/plugins/ScheduledReports/API.php @@ -28,6 +28,7 @@ use Piwik\Plugins\LanguagesManager\LanguagesManager; use Piwik\Plugins\SegmentEditor\API as APISegmentEditor; use Piwik\Plugins\SitesManager\API as SitesManagerApi; use Piwik\ReportRenderer; +use Piwik\Scheduler\RetryableException; use Piwik\Scheduler\Schedule\Schedule; use Piwik\Site; use Piwik\Translation\Translator; @@ -608,9 +609,9 @@ class API extends \Piwik\Plugin\API $report['period_param'] ); - } catch (Exception $e) { + } catch (\Throwable $e) { $this->enableSaveReportOnDisk = false; - throw $e; + throw new RetryableException($e->getMessage()); } $this->enableSaveReportOnDisk = false; diff --git a/tests/PHPUnit/Integration/RetryScheduledTaskTest.php b/tests/PHPUnit/Integration/RetryScheduledTaskTest.php new file mode 100644 index 0000000000..36e055cd8f --- /dev/null +++ b/tests/PHPUnit/Integration/RetryScheduledTaskTest.php @@ -0,0 +1,143 @@ +assertEquals(0, $timetable->getRetryCount($task1)); + + // Should increment by one + $timetable->incrementRetryCount($task1); + $this->assertEquals(1, $timetable->getRetryCount($task1)); + + // Should not break if more than one tasks is counting retries + $timetable->incrementRetryCount($task2); + $timetable->incrementRetryCount($task2); + $this->assertEquals(2, $timetable->getRetryCount($task2)); + $timetable->incrementRetryCount($task1); + $this->assertEquals(2, $timetable->getRetryCount($task1)); + + // Should clear retry count without affecting other tasks + $timetable->clearRetryCount($task1); + $this->assertEquals(0, $timetable->getRetryCount($task1)); + $this->assertEquals(2, $timetable->getRetryCount($task2)); + $timetable->clearRetryCount($task2); + $this->assertEquals(0, $timetable->getRetryCount($task1)); + + } + + public function testTaskIsRetriedIfRetryableExcetionIsThrown() + { + + // Mock timetable + $now = time() - 60; + $taskName = 'Piwik\Tests\Integration\RetryScheduledTaskTest.exceptionalTask'; + $timetableData = serialize([$taskName => $now]); + self::getReflectedPiwikOptionInstance()->setValue(new PiwikOption($timetableData)); + + // Create task + $dailySchedule = $this->createPartialMock('Piwik\Scheduler\Schedule\Daily', array('getTime')); + $dailySchedule->expects($this->any()) + ->method('getTime') + ->will($this->returnValue($now)); + + // Setup scheduler + $tasks = [new Task($this, 'exceptionalTask', null, $dailySchedule)]; + $taskLoader = $this->createMock('Piwik\Scheduler\TaskLoader'); + $taskLoader->expects($this->atLeastOnce()) + ->method('loadTasks') + ->willReturn($tasks); + + $scheduler = new Scheduler($taskLoader, new NullLogger()); + + // First run + $scheduler->run(); + $nextRun = $scheduler->getScheduledTimeForMethod('Piwik\Tests\Integration\RetryScheduledTaskTest', 'exceptionalTask', null); + + // Should be rescheduled one hour from now + $this->assertEquals($now+3660, $nextRun); + + self::getReflectedPiwikOptionInstance()->setValue(null); + + } + + public function testTaskIsNotRetriedIfNormalExcetionIsThrown() + { + // Mock timetable + $now = time() - 60; + $taskName = 'Piwik\Tests\Integration\RetryScheduledTaskTest.normalExceptionTask'; + $timetableData = serialize([$taskName => $now]); + self::getReflectedPiwikOptionInstance()->setValue(new PiwikOption($timetableData)); + + // Create task + $specificSchedule = $this->createPartialMock('Piwik\Scheduler\Schedule\SpecificTime', array('getTime')); + $specificSchedule->setScheduledTime($now+50000); + $specificSchedule->expects($this->any()) + ->method('getTime') + ->will($this->returnValue($now)); + + // Setup scheduler + $tasks = [new Task($this, 'normalExceptionTask', null, $specificSchedule)]; + $taskLoader = $this->createMock('Piwik\Scheduler\TaskLoader'); + $taskLoader->expects($this->atLeastOnce()) + ->method('loadTasks') + ->willReturn($tasks); + + $scheduler = new Scheduler($taskLoader, new NullLogger()); + + // First run + $scheduler->run(); + $nextRun = $scheduler->getScheduledTimeForMethod('Piwik\Tests\Integration\RetryScheduledTaskTest', 'normalExceptionTask', null); + + // Should not have scheduled for retry + $this->assertEquals($now+50000, $nextRun); + + self::getReflectedPiwikOptionInstance()->setValue(null); + } + + private static function getReflectedPiwikOptionInstance() + { + $piwikOptionInstance = new ReflectionProperty('Piwik\Option', 'instance'); + $piwikOptionInstance->setAccessible(true); + return $piwikOptionInstance; + } + + public function exceptionalTask() + { + throw new RetryableException('This task fails and should be retried'); + } + + public function normalExceptionTask() + { + throw new \Exception('This task fails and should not be retried'); + } + +} diff --git a/tests/PHPUnit/System/TrackerTest.php b/tests/PHPUnit/System/TrackerTest.php index a675e045d0..592b65c75c 100644 --- a/tests/PHPUnit/System/TrackerTest.php +++ b/tests/PHPUnit/System/TrackerTest.php @@ -45,6 +45,7 @@ class TrackerTest extends IntegrationTestCase Option::delete(self::TASKS_STARTED_OPTION_NAME); Option::delete(self::TASKS_FINISHED_OPTION_NAME); Option::delete(Timetable::TIMETABLE_OPTION_STRING); + Option::delete(Timetable::RETRY_OPTION_STRING); SettingsPiwik::overwritePiwikUrl(self::$fixture->getRootUrl() . "tests/PHPUnit/proxy"); } @@ -399,7 +400,7 @@ class TrackerTest extends IntegrationTestCase $this->assertCustomTasksWereStarted(); Option::clearCachedOption(self::TASKS_FINISHED_OPTION_NAME); - $this->assertEmpty(Option::get(self::TASKS_FINISHED_OPTION_NAME)); + $this->assertFalse(Option::get(self::TASKS_FINISHED_OPTION_NAME)); } private function assertCustomTasksWereStarted() diff --git a/tests/PHPUnit/Unit/Scheduler/TimetableTest.php b/tests/PHPUnit/Unit/Scheduler/TimetableTest.php index 1518d1f833..2d930b0d06 100644 --- a/tests/PHPUnit/Unit/Scheduler/TimetableTest.php +++ b/tests/PHPUnit/Unit/Scheduler/TimetableTest.php @@ -81,6 +81,21 @@ class TimetableTest extends \PHPUnit\Framework\TestCase $this->assertEquals(Date::factory('tomorrow')->getTimeStamp(), $timetable->getTimetable()[$task->getName()]); } + public function testRescheduleTaskAndRunInOneHour() + { + self::stubPiwikOption(serialize([])); + + $timetable = new Timetable(); + $task = $this->getMockBuilder(Task::class) + ->disableOriginalConstructor() + ->getMock(); + $task->method('getName')->willReturn('taskName'); + + $timetable->rescheduleTaskAndRunInOneHour($task); + + $this->assertEquals(Date::factory('now')->addHour(1)->getTimeStamp(), $timetable->getTimetable()[$task->getName()]); + } + /** * Dataprovider for testTaskHasBeenScheduledOnce */ -- cgit v1.2.3