From aa12503923ac994873724ecaa759e1eb14b318dc Mon Sep 17 00:00:00 2001 From: Jason Woods Date: Wed, 8 Jul 2020 10:44:26 +0100 Subject: [PATCH 01/10] Add warning to deadlock cron retrier to log any future failures for investigation Change key for cron_schedule to cover all queries currently run, ensuring range is on the end of the key Refactor cron locking to remove UPDATE+JOIN which causes shared locks on the join followed by exclusive locks for the update, which can deadlock, to instead use an explicit full exclusive lock on all entries using forUpdate Implement cleanup of jobs that were running but did not complete and did not error, which can occur if PHP crashes or is killed, or database is restored from backup or migrated to staging environments --- .../Magento/Cron/Model/DeadlockRetrier.php | 15 ++++++++ .../Cron/Model/ResourceModel/Schedule.php | 36 +++++++++++++------ .../Observer/ProcessCronQueueObserver.php | 30 ++++++++++++++++ .../Test/Unit/Model/DeadlockRetrierTest.php | 13 ++++++- .../Observer/ProcessCronQueueObserverTest.php | 26 +++++++++++--- app/code/Magento/Cron/etc/db_schema.xml | 6 ++-- 6 files changed, 107 insertions(+), 19 deletions(-) diff --git a/app/code/Magento/Cron/Model/DeadlockRetrier.php b/app/code/Magento/Cron/Model/DeadlockRetrier.php index 15497910a089b..63f7453c8df3c 100644 --- a/app/code/Magento/Cron/Model/DeadlockRetrier.php +++ b/app/code/Magento/Cron/Model/DeadlockRetrier.php @@ -17,6 +17,20 @@ */ class DeadlockRetrier implements DeadlockRetrierInterface { + /** + * @var \Psr\Log\LoggerInterface + */ + private $logger; + + /** + * @param \Psr\Log\LoggerInterface $logger + */ + public function __construct( + \Psr\Log\LoggerInterface $logger + ) { + $this->logger = $logger; + } + /** * @inheritdoc */ @@ -30,6 +44,7 @@ public function execute(callable $callback, AdapterInterface $connection) try { return $callback(); } catch (DeadlockException $e) { + $this->logger->warning(sprintf("Deadlock detected in cron cleanup: %s", $e->getMessage())); continue; } } diff --git a/app/code/Magento/Cron/Model/ResourceModel/Schedule.php b/app/code/Magento/Cron/Model/ResourceModel/Schedule.php index 25ebaec5582c9..120e0ce6432c5 100644 --- a/app/code/Magento/Cron/Model/ResourceModel/Schedule.php +++ b/app/code/Magento/Cron/Model/ResourceModel/Schedule.php @@ -65,31 +65,47 @@ public function trySetJobStatusAtomic($scheduleId, $newStatus, $currentStatus) public function trySetJobUniqueStatusAtomic($scheduleId, $newStatus, $currentStatus) { $connection = $this->getConnection(); + $connection->beginTransaction(); // this condition added to avoid cron jobs locking after incorrect termination of running job $match = $connection->quoteInto( 'existing.job_code = current.job_code ' . - 'AND (existing.executed_at > UTC_TIMESTAMP() - INTERVAL 1 DAY OR existing.executed_at IS NULL) ' . - 'AND existing.status = ?', + 'AND existing.status = ? ' . + 'AND (existing.executed_at > UTC_TIMESTAMP() - INTERVAL 1 DAY OR existing.executed_at IS NULL)', $newStatus ); + // Select and lock all related schedules - this prevents deadlock in case cron overlaps and two jobs of + // the same code attempt to lock at the same time, and force them to serialize $selectIfUnlocked = $connection->select() + ->from( + ['current' => $this->getTable('cron_schedule')], + [] + ) ->joinLeft( ['existing' => $this->getTable('cron_schedule')], $match, - ['status' => new \Zend_Db_Expr($connection->quote($newStatus))] + ['existing.schedule_id'] ) ->where('current.schedule_id = ?', $scheduleId) ->where('current.status = ?', $currentStatus) - ->where('existing.schedule_id IS NULL'); - - $update = $connection->updateFromSelect($selectIfUnlocked, ['current' => $this->getTable('cron_schedule')]); - $result = $connection->query($update)->rowCount(); + ->forUpdate(true); - if ($result == 1) { - return true; + $scheduleId = $connection->fetchOne($selectIfUnlocked); + if (!empty($scheduleId)) { + // Existing running schedule found + $connection->commit(); + return false; } - return false; + + // Mark our schedule as running + $connection->update( + $this->getTable('cron_schedule'), + ['status' => new \Zend_Db_Expr($connection->quote($newStatus))], + ['schedule_id = ?' => $scheduleId] + ); + + $connection->commit(); + return true; } } diff --git a/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php b/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php index acffba02eb461..a6a8f77c039d8 100644 --- a/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php +++ b/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php @@ -550,6 +550,7 @@ private function cleanupJobs($groupId, $currentTime) ); $this->cleanupDisabledJobs($groupId); + $this->cleanupRunningJobs($groupId); $historySuccess = (int)$this->getCronGroupConfigurationValue($groupId, self::XML_PATH_HISTORY_SUCCESS); $historyFailure = (int)$this->getCronGroupConfigurationValue($groupId, self::XML_PATH_HISTORY_FAILURE); @@ -696,6 +697,35 @@ private function cleanupDisabledJobs($groupId) } } + /** + * Cleanup jobs that were left in a running state due to an unexpected stop + * + * @param string $groupId + * @return void + */ + private function cleanupRunningJobs($groupId) + { + $scheduleResource = $this->_scheduleFactory->create()->getResource(); + $connection = $scheduleResource->getConnection(); + + $jobs = $this->_config->getJobs(); + + $connection->update( + $scheduleResource->getMainTable(), + [ + 'status' => \Magento\Cron\Model\Schedule::STATUS_ERROR, + 'messages' => 'Time out' + ], + $connection->quoteInto( + 'status = ? ' . + 'AND job_code IN (?) ' . + 'AND (scheduled_at < UTC_TIMESTAMP() - INTERVAL 1 DAY)', + \Magento\Cron\Model\Schedule::STATUS_RUNNING, + array_keys($jobs[$groupId]) + ) + ); + } + /** * Get cron expression of cron job. * diff --git a/app/code/Magento/Cron/Test/Unit/Model/DeadlockRetrierTest.php b/app/code/Magento/Cron/Test/Unit/Model/DeadlockRetrierTest.php index 60eaa091a761f..36e4537383aa6 100644 --- a/app/code/Magento/Cron/Test/Unit/Model/DeadlockRetrierTest.php +++ b/app/code/Magento/Cron/Test/Unit/Model/DeadlockRetrierTest.php @@ -13,6 +13,7 @@ use Magento\Framework\DB\Adapter\AdapterInterface; use Magento\Framework\DB\Adapter\DeadlockException; use PHPUnit\Framework\MockObject\MockObject; +use Psr\Log\LoggerInterface; class DeadlockRetrierTest extends \PHPUnit\Framework\TestCase { @@ -27,6 +28,11 @@ class DeadlockRetrierTest extends \PHPUnit\Framework\TestCase */ private $adapterMock; + /** + * @var LoggerInterface|MockObject + */ + private $loggerMock; + /** * @var AbstractModel|MockObject */ @@ -38,8 +44,9 @@ class DeadlockRetrierTest extends \PHPUnit\Framework\TestCase protected function setUp(): void { $this->adapterMock = $this->getMockForAbstractClass(AdapterInterface::class); + $this->loggerMock = $this->getMockForAbstractClass(LoggerInterface::class); $this->modelMock = $this->createMock(AbstractModel::class); - $this->retrier = new DeadlockRetrier(); + $this->retrier = new DeadlockRetrier($this->loggerMock); } /** @@ -75,6 +82,8 @@ public function testRetry(): void $this->modelMock->expects($this->exactly(DeadlockRetrierInterface::MAX_RETRIES)) ->method('getId') ->willThrowException(new DeadlockException()); + $this->loggerMock->expects($this->exactly(DeadlockRetrierInterface::MAX_RETRIES - 1)) + ->method('warning'); $this->retrier->execute( function () { @@ -95,6 +104,8 @@ public function testRetrySecond(): void $this->modelMock->expects($this->at(1)) ->method('getId') ->willReturn(2); + $this->loggerMock->expects($this->once()) + ->method('warning'); $this->retrier->execute( function () { diff --git a/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php b/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php index e1e28ff6f06a3..9414680ce0e45 100644 --- a/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php +++ b/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php @@ -1047,8 +1047,8 @@ public function testMissedJobsCleanedInTime() $this->scheduleCollectionMock->expects($this->any())->method('load')->willReturnSelf(); $scheduleMock->expects($this->any())->method('getCollection')->willReturn($this->scheduleCollectionMock); - $scheduleMock->expects($this->exactly(9))->method('getResource')->willReturn($this->scheduleResourceMock); - $this->scheduleFactoryMock->expects($this->exactly(10))->method('create')->willReturn($scheduleMock); + $scheduleMock->expects($this->exactly(10))->method('getResource')->willReturn($this->scheduleResourceMock); + $this->scheduleFactoryMock->expects($this->exactly(11))->method('create')->willReturn($scheduleMock); $connectionMock = $this->getMockForAbstractClass(AdapterInterface::class); @@ -1078,11 +1078,29 @@ public function testMissedJobsCleanedInTime() ) ->willReturn(1); - $this->scheduleResourceMock->expects($this->exactly(5)) + $connectionMock->expects($this->once()) + ->method('quoteInto') + ->with( + 'status = ? AND job_code IN (?) AND (scheduled_at < UTC_TIMESTAMP() - INTERVAL 1 DAY)', + ['test_job1'], + 'running' + ) + ->willReturn(''); + + $connectionMock->expects($this->once()) + ->method('update') + ->with( + $tableName, + ['status' => 'error', 'messages' => 'Time out'], + '' + ) + ->willReturn(0); + + $this->scheduleResourceMock->expects($this->exactly(6)) ->method('getTable') ->with($tableName) ->willReturn($tableName); - $this->scheduleResourceMock->expects($this->exactly(14)) + $this->scheduleResourceMock->expects($this->exactly(15)) ->method('getConnection') ->willReturn($connectionMock); diff --git a/app/code/Magento/Cron/etc/db_schema.xml b/app/code/Magento/Cron/etc/db_schema.xml index f26b6feea3b3b..527cdbcc5fb86 100644 --- a/app/code/Magento/Cron/etc/db_schema.xml +++ b/app/code/Magento/Cron/etc/db_schema.xml @@ -21,12 +21,10 @@ - + + - - - From b0b72b0f8486ca119015e84b7786dfab13d2e475 Mon Sep 17 00:00:00 2001 From: Jason Woods Date: Thu, 16 Jul 2020 14:53:52 +0100 Subject: [PATCH 02/10] Higher cardinality first after tested shown still no deadlocks --- app/code/Magento/Cron/etc/db_schema.xml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/app/code/Magento/Cron/etc/db_schema.xml b/app/code/Magento/Cron/etc/db_schema.xml index 527cdbcc5fb86..72b1428756898 100644 --- a/app/code/Magento/Cron/etc/db_schema.xml +++ b/app/code/Magento/Cron/etc/db_schema.xml @@ -21,9 +21,9 @@ - - + + From 96029b55f7cd00b58967637aedac67ddd1767bad Mon Sep 17 00:00:00 2001 From: Jason Woods Date: Fri, 21 Aug 2020 10:37:47 +0100 Subject: [PATCH 03/10] Fix test --- .../Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php b/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php index 9414680ce0e45..98ec3c918f539 100644 --- a/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php +++ b/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php @@ -1082,8 +1082,8 @@ public function testMissedJobsCleanedInTime() ->method('quoteInto') ->with( 'status = ? AND job_code IN (?) AND (scheduled_at < UTC_TIMESTAMP() - INTERVAL 1 DAY)', - ['test_job1'], - 'running' + 'running', + ['test_job1'] ) ->willReturn(''); From 68d679b7bd7d371c5266d4803f03f204893f7af2 Mon Sep 17 00:00:00 2001 From: Jason Woods Date: Fri, 21 Aug 2020 12:04:43 +0100 Subject: [PATCH 04/10] Reduce line count to fix static testing --- .../Observer/ProcessCronQueueObserverTest.php | 40 +++++-------------- 1 file changed, 10 insertions(+), 30 deletions(-) diff --git a/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php b/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php index 98ec3c918f539..816fdb6173d8b 100644 --- a/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php +++ b/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php @@ -764,22 +764,17 @@ function ($callback) { ->method('getCollection')->willReturn($this->scheduleCollectionMock); $scheduleMock->expects($this->any()) ->method('getResource')->willReturn($this->scheduleResourceMock); - $this->scheduleFactoryMock->expects($this->once(2)) + $this->scheduleFactoryMock->expects($this->once()) ->method('create')->willReturn($scheduleMock); $testCronJob = $this->getMockBuilder('CronJob') ->setMethods(['execute'])->getMock(); $testCronJob->expects($this->atLeastOnce())->method('execute')->with($schedule); - $this->objectManagerMock->expects( - $this->once() - )->method( - 'create' - )->with( - 'CronJob' - )->willReturn( - $testCronJob - ); + $this->objectManagerMock->expects($this->once()) + ->method('create') + ->with('CronJob') + ->willReturn($testCronJob); $this->cronQueueObserver->execute($this->observerMock); } @@ -1055,26 +1050,11 @@ public function testMissedJobsCleanedInTime() $connectionMock->expects($this->exactly(5)) ->method('delete') ->withConsecutive( - [ - $tableName, - ['status = ?' => 'pending', 'job_code in (?)' => ['test_job1']] - ], - [ - $tableName, - ['status = ?' => 'success', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null] - ], - [ - $tableName, - ['status = ?' => 'missed', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null] - ], - [ - $tableName, - ['status = ?' => 'error', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null] - ], - [ - $tableName, - ['status = ?' => 'pending', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null] - ] + [$tableName, ['status = ?' => 'pending', 'job_code in (?)' => ['test_job1']]], + [$tableName, ['status = ?' => 'success', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null]], + [$tableName, ['status = ?' => 'missed', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null]], + [$tableName, ['status = ?' => 'error', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null]], + [$tableName, ['status = ?' => 'pending', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null]] ) ->willReturn(1); From a90161907aedae371cb307759b685cc254efe2d8 Mon Sep 17 00:00:00 2001 From: Jason Woods Date: Fri, 21 Aug 2020 13:10:43 +0100 Subject: [PATCH 05/10] Fix test failure due to table fetch --- app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php b/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php index a6a8f77c039d8..de42027742c6e 100644 --- a/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php +++ b/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php @@ -711,7 +711,7 @@ private function cleanupRunningJobs($groupId) $jobs = $this->_config->getJobs(); $connection->update( - $scheduleResource->getMainTable(), + $scheduleResource->getTable('cron_schedule'), [ 'status' => \Magento\Cron\Model\Schedule::STATUS_ERROR, 'messages' => 'Time out' From dda5c72c9303f9476ce7041743c87079cada87f6 Mon Sep 17 00:00:00 2001 From: Ihor Sviziev Date: Tue, 25 Aug 2020 13:40:25 +0300 Subject: [PATCH 06/10] Cron cleanup repeatedly hits deadlocks on large environments Fix failing tests --- .../Observer/ProcessCronQueueObserver.php | 47 +++++----- .../Observer/ProcessCronQueueObserverTest.php | 90 +++++++++++++------ .../Magento/Cron/etc/db_schema_whitelist.json | 5 +- 3 files changed, 87 insertions(+), 55 deletions(-) diff --git a/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php b/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php index de42027742c6e..0f266b5d62d83 100644 --- a/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php +++ b/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php @@ -9,6 +9,7 @@ */ namespace Magento\Cron\Observer; +use Magento\Cron\Model\ResourceModel\Schedule\Collection as ScheduleCollection; use Magento\Cron\Model\Schedule; use Magento\Framework\App\State; use Magento\Framework\Console\Cli; @@ -83,7 +84,7 @@ class ProcessCronQueueObserver implements ObserverInterface const MAX_RETRIES = 5; /** - * @var \Magento\Cron\Model\ResourceModel\Schedule\Collection + * @var ScheduleCollection */ protected $_pendingSchedules; @@ -278,12 +279,12 @@ function ($groupId) use ($currentTime) { * * It should be taken by standalone (child) process, not by the parent process. * - * @param int $groupId + * @param string $groupId * @param callable $callback * * @return void */ - private function lockGroup($groupId, callable $callback) + private function lockGroup(string $groupId, callable $callback): void { if (!$this->lockManager->lock(self::LOCK_PREFIX . $groupId, self::LOCK_TIMEOUT)) { $this->logger->warning( @@ -399,7 +400,7 @@ function () use ($schedule) { * @param string $jobName * @return void */ - private function startProfiling(string $jobName = '') + private function startProfiling(string $jobName = ''): void { $this->statProfiler->clear(); $this->statProfiler->start( @@ -416,7 +417,7 @@ private function startProfiling(string $jobName = '') * @param string $jobName * @return void */ - private function stopProfiling(string $jobName = '') + private function stopProfiling(string $jobName = ''): void { $this->statProfiler->stop( sprintf(self::CRON_TIMERID, $jobName), @@ -445,9 +446,9 @@ private function getProfilingStat(string $jobName): string * Return job collection from data base with status 'pending'. * * @param string $groupId - * @return \Magento\Cron\Model\ResourceModel\Schedule\Collection + * @return ScheduleCollection */ - private function getPendingSchedules($groupId) + private function getPendingSchedules(string $groupId): ScheduleCollection { $jobs = $this->_config->getJobs(); $pendingJobs = $this->_scheduleFactory->create()->getCollection(); @@ -462,7 +463,7 @@ private function getPendingSchedules($groupId) * @param string $groupId * @return $this */ - private function generateSchedules($groupId) + private function generateSchedules(string $groupId): self { /** * check if schedule generation is needed @@ -533,13 +534,13 @@ protected function _generateJobs($jobs, $exists, $groupId) * @param int $currentTime * @return void */ - private function cleanupJobs($groupId, $currentTime) + private function cleanupJobs(string $groupId, int $currentTime): void { // check if history cleanup is needed $lastCleanup = (int)$this->_cache->load(self::CACHE_KEY_LAST_HISTORY_CLEANUP_AT . $groupId); $historyCleanUp = (int)$this->getCronGroupConfigurationValue($groupId, self::XML_PATH_HISTORY_CLEANUP_EVERY); if ($lastCleanup > $this->dateTime->gmtTimestamp() - $historyCleanUp * self::SECONDS_IN_MINUTE) { - return $this; + return; } // save time history cleanup was ran with no expiration $this->_cache->save( @@ -674,7 +675,7 @@ protected function getScheduleTimeInterval($groupId) * @param string $groupId * @return void */ - private function cleanupDisabledJobs($groupId) + private function cleanupDisabledJobs(string $groupId): void { $jobs = $this->_config->getJobs(); $jobsToCleanup = []; @@ -703,7 +704,7 @@ private function cleanupDisabledJobs($groupId) * @param string $groupId * @return void */ - private function cleanupRunningJobs($groupId) + private function cleanupRunningJobs(string $groupId): void { $scheduleResource = $this->_scheduleFactory->create()->getResource(); $connection = $scheduleResource->getConnection(); @@ -716,13 +717,11 @@ private function cleanupRunningJobs($groupId) 'status' => \Magento\Cron\Model\Schedule::STATUS_ERROR, 'messages' => 'Time out' ], - $connection->quoteInto( - 'status = ? ' . - 'AND job_code IN (?) ' . - 'AND (scheduled_at < UTC_TIMESTAMP() - INTERVAL 1 DAY)', - \Magento\Cron\Model\Schedule::STATUS_RUNNING, - array_keys($jobs[$groupId]) - ) + [ + $connection->quoteInto('status = ?', \Magento\Cron\Model\Schedule::STATUS_RUNNING), + $connection->quoteInto('job_code IN (?)', array_keys($jobs[$groupId])), + 'scheduled_at < UTC_TIMESTAMP() - INTERVAL 1 DAY' + ] ); } @@ -803,13 +802,13 @@ private function isGroupInFilter($groupId): bool * @param array $jobsRoot * @param int $currentTime */ - private function processPendingJobs($groupId, $jobsRoot, $currentTime) + private function processPendingJobs(string $groupId, array $jobsRoot, int $currentTime): void { - $procesedJobs = []; + $processedJobs = []; $pendingJobs = $this->getPendingSchedules($groupId); /** @var Schedule $schedule */ foreach ($pendingJobs as $schedule) { - if (isset($procesedJobs[$schedule->getJobCode()])) { + if (isset($processedJobs[$schedule->getJobCode()])) { // process only on job per run continue; } @@ -826,7 +825,7 @@ private function processPendingJobs($groupId, $jobsRoot, $currentTime) $this->tryRunJob($scheduledTime, $currentTime, $jobConfig, $schedule, $groupId); if ($schedule->getStatus() === Schedule::STATUS_SUCCESS) { - $procesedJobs[$schedule->getJobCode()] = true; + $processedJobs[$schedule->getJobCode()] = true; } $this->retrier->execute( @@ -851,7 +850,7 @@ private function tryRunJob($scheduledTime, $currentTime, $jobConfig, $schedule, { // use sha1 to limit length // phpcs:ignore Magento2.Security.InsecureFunction - $lockName = self::LOCK_PREFIX . md5($groupId . '_' . $schedule->getJobCode()); + $lockName = self::LOCK_PREFIX . md5($groupId . '_' . $schedule->getJobCode()); try { for ($retries = self::MAX_RETRIES; $retries > 0; $retries--) { diff --git a/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php b/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php index 816fdb6173d8b..134d4ea04d171 100644 --- a/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php +++ b/app/code/Magento/Cron/Test/Unit/Observer/ProcessCronQueueObserverTest.php @@ -1045,53 +1045,85 @@ public function testMissedJobsCleanedInTime() $scheduleMock->expects($this->exactly(10))->method('getResource')->willReturn($this->scheduleResourceMock); $this->scheduleFactoryMock->expects($this->exactly(11))->method('create')->willReturn($scheduleMock); + $connectionMock = $this->prepareConnectionMock($tableName); + + $this->scheduleResourceMock->expects($this->exactly(6)) + ->method('getTable') + ->with($tableName) + ->willReturn($tableName); + $this->scheduleResourceMock->expects($this->exactly(15)) + ->method('getConnection') + ->willReturn($connectionMock); + + $this->retrierMock->expects($this->exactly(5)) + ->method('execute') + ->willReturnCallback( + function ($callback) { + return $callback(); + } + ); + + $this->cronQueueObserver->execute($this->observerMock); + } + + /** + * @param string $tableName + * @return AdapterInterface|MockObject + */ + private function prepareConnectionMock(string $tableName) + { $connectionMock = $this->getMockForAbstractClass(AdapterInterface::class); $connectionMock->expects($this->exactly(5)) ->method('delete') ->withConsecutive( - [$tableName, ['status = ?' => 'pending', 'job_code in (?)' => ['test_job1']]], - [$tableName, ['status = ?' => 'success', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null]], - [$tableName, ['status = ?' => 'missed', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null]], - [$tableName, ['status = ?' => 'error', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null]], - [$tableName, ['status = ?' => 'pending', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null]] + [ + $tableName, + ['status = ?' => 'pending', 'job_code in (?)' => ['test_job1']] + ], + [ + $tableName, + ['status = ?' => 'success', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null] + ], + [ + $tableName, + ['status = ?' => 'missed', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null] + ], + [ + $tableName, + ['status = ?' => 'error', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null] + ], + [ + $tableName, + ['status = ?' => 'pending', 'job_code in (?)' => ['test_job1'], 'scheduled_at < ?' => null] + ] ) ->willReturn(1); - $connectionMock->expects($this->once()) + $connectionMock->expects($this->any()) ->method('quoteInto') - ->with( - 'status = ? AND job_code IN (?) AND (scheduled_at < UTC_TIMESTAMP() - INTERVAL 1 DAY)', - 'running', - ['test_job1'] + ->withConsecutive( + ['status = ?', \Magento\Cron\Model\Schedule::STATUS_RUNNING], + ['job_code IN (?)', ['test_job1']], ) - ->willReturn(''); + ->willReturnOnConsecutiveCalls( + "status = 'running'", + "job_code IN ('test_job1')" + ); $connectionMock->expects($this->once()) ->method('update') ->with( $tableName, ['status' => 'error', 'messages' => 'Time out'], - '' + [ + "status = 'running'", + "job_code IN ('test_job1')", + 'scheduled_at < UTC_TIMESTAMP() - INTERVAL 1 DAY' + ] ) ->willReturn(0); - $this->scheduleResourceMock->expects($this->exactly(6)) - ->method('getTable') - ->with($tableName) - ->willReturn($tableName); - $this->scheduleResourceMock->expects($this->exactly(15)) - ->method('getConnection') - ->willReturn($connectionMock); - - $this->retrierMock->expects($this->exactly(5)) - ->method('execute') - ->willReturnCallback( - function ($callback) { - return $callback(); - } - ); - - $this->cronQueueObserver->execute($this->observerMock); + return $connectionMock; } } diff --git a/app/code/Magento/Cron/etc/db_schema_whitelist.json b/app/code/Magento/Cron/etc/db_schema_whitelist.json index c8666896627e2..74836c0be8a2e 100644 --- a/app/code/Magento/Cron/etc/db_schema_whitelist.json +++ b/app/code/Magento/Cron/etc/db_schema_whitelist.json @@ -12,10 +12,11 @@ }, "index": { "CRON_SCHEDULE_JOB_CODE": true, - "CRON_SCHEDULE_SCHEDULED_AT_STATUS": true + "CRON_SCHEDULE_SCHEDULED_AT_STATUS": true, + "CRON_SCHEDULE_JOB_CODE_STATUS_SCHEDULED_AT": true }, "constraint": { "PRIMARY": true } } -} \ No newline at end of file +} From e95d2fefefb62150e566f000a4a17f58f6716af5 Mon Sep 17 00:00:00 2001 From: Jason Woods Date: Mon, 21 Sep 2020 16:36:46 +0100 Subject: [PATCH 07/10] Revert #27391 changes Status field is no longer used in that query after this PR --- app/code/Magento/Cron/etc/db_schema.xml | 4 ---- 1 file changed, 4 deletions(-) diff --git a/app/code/Magento/Cron/etc/db_schema.xml b/app/code/Magento/Cron/etc/db_schema.xml index de7ebf3fc50b6..72b1428756898 100644 --- a/app/code/Magento/Cron/etc/db_schema.xml +++ b/app/code/Magento/Cron/etc/db_schema.xml @@ -26,9 +26,5 @@ - - - - From 916bc93138f7a81f65c2e8b5069eeb0f35fceb43 Mon Sep 17 00:00:00 2001 From: Jason Woods Date: Mon, 21 Sep 2020 16:40:43 +0100 Subject: [PATCH 08/10] Revert #27391 changes Status field is no longer used in the query --- app/code/Magento/Cron/etc/db_schema_whitelist.json | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/app/code/Magento/Cron/etc/db_schema_whitelist.json b/app/code/Magento/Cron/etc/db_schema_whitelist.json index a598c6d213c55..74836c0be8a2e 100644 --- a/app/code/Magento/Cron/etc/db_schema_whitelist.json +++ b/app/code/Magento/Cron/etc/db_schema_whitelist.json @@ -13,8 +13,7 @@ "index": { "CRON_SCHEDULE_JOB_CODE": true, "CRON_SCHEDULE_SCHEDULED_AT_STATUS": true, - "CRON_SCHEDULE_JOB_CODE_STATUS_SCHEDULED_AT": true, - "CRON_SCHEDULE_SCHEDULE_ID_STATUS": true + "CRON_SCHEDULE_JOB_CODE_STATUS_SCHEDULED_AT": true }, "constraint": { "PRIMARY": true From edd77531f8847f7b13dbaca9aefa315ba4aa5e57 Mon Sep 17 00:00:00 2001 From: Ihor Sviziev Date: Mon, 21 Sep 2020 22:23:38 +0300 Subject: [PATCH 09/10] Fix SVC failure --- app/code/Magento/Cron/etc/db_schema_whitelist.json | 1 + 1 file changed, 1 insertion(+) diff --git a/app/code/Magento/Cron/etc/db_schema_whitelist.json b/app/code/Magento/Cron/etc/db_schema_whitelist.json index 74836c0be8a2e..2e5cc6e0a4618 100644 --- a/app/code/Magento/Cron/etc/db_schema_whitelist.json +++ b/app/code/Magento/Cron/etc/db_schema_whitelist.json @@ -13,6 +13,7 @@ "index": { "CRON_SCHEDULE_JOB_CODE": true, "CRON_SCHEDULE_SCHEDULED_AT_STATUS": true, + "CRON_SCHEDULE_SCHEDULE_ID_STATUS": true, "CRON_SCHEDULE_JOB_CODE_STATUS_SCHEDULED_AT": true }, "constraint": { From 92dc76438063e68f7523d5ab036a57d7faf7bc03 Mon Sep 17 00:00:00 2001 From: Jason Woods Date: Tue, 24 Nov 2020 17:26:00 +0000 Subject: [PATCH 10/10] Update app/code/Magento/Cron/Model/DeadlockRetrier.php Co-authored-by: Buba Suma --- app/code/Magento/Cron/Model/DeadlockRetrier.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/app/code/Magento/Cron/Model/DeadlockRetrier.php b/app/code/Magento/Cron/Model/DeadlockRetrier.php index 63f7453c8df3c..ab180e93e0ca3 100644 --- a/app/code/Magento/Cron/Model/DeadlockRetrier.php +++ b/app/code/Magento/Cron/Model/DeadlockRetrier.php @@ -44,7 +44,7 @@ public function execute(callable $callback, AdapterInterface $connection) try { return $callback(); } catch (DeadlockException $e) { - $this->logger->warning(sprintf("Deadlock detected in cron cleanup: %s", $e->getMessage())); + $this->logger->warning(sprintf("Deadlock detected in cron: %s", $e->getMessage())); continue; } }