From dce07b4c2178ca66fd3301469404e271ef09df55 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Thu, 11 Jul 2019 12:47:48 -0700 Subject: [PATCH] Log errors in DeferredUpdates::handleUpdateQueue() Other cleanups and fixes: * Split up handleUpdate() method into run() and jobify() * Handle Throwable errors * Use 'cli' in stats keys in CLI mode instead of "get" * Tweak some code comments Change-Id: I7749465df2d7b58e66ee5ebdd3c3d25aea52eeb3 --- includes/deferred/DeferredUpdates.php | 169 ++++++++++++++++++-------- 1 file changed, 117 insertions(+), 52 deletions(-) diff --git a/includes/deferred/DeferredUpdates.php b/includes/deferred/DeferredUpdates.php index f5d22c15d6..c754cff685 100644 --- a/includes/deferred/DeferredUpdates.php +++ b/includes/deferred/DeferredUpdates.php @@ -19,6 +19,10 @@ * * @file */ + +use Liuggio\StatsdClient\Factory\StatsdDataFactoryInterface; +use MediaWiki\Logger\LoggerFactory; +use Psr\Log\LoggerInterface; use Wikimedia\Rdbms\IDatabase; use MediaWiki\MediaWikiServices; use Wikimedia\Rdbms\LBFactory; @@ -181,11 +185,14 @@ class DeferredUpdates { protected static function handleUpdateQueue( array &$queue, $mode, $stage ) { $services = MediaWikiServices::getInstance(); $stats = $services->getStatsdDataFactory(); - $lbFactory = $services->getDBLoadBalancerFactory(); - $method = RequestContext::getMain()->getRequest()->getMethod(); - - /** @var ErrorPageError $reportableError */ - $reportableError = null; + $lbf = $services->getDBLoadBalancerFactory(); + $logger = LoggerFactory::getInstance( 'DeferredUpdates' ); + $httpMethod = $services->getMainConfig()->get( 'CommandLineMode' ) + ? 'cli' + : strtolower( RequestContext::getMain()->getRequest()->getMethod() ); + + /** @var ErrorPageError $guiEx */ + $guiEx = null; /** @var DeferrableUpdate[] $updates Snapshot of queue */ $updates = $queue; @@ -193,37 +200,37 @@ class DeferredUpdates { while ( $updates ) { $queue = []; // clear the queue - // Order will be DataUpdate followed by generic DeferrableUpdate tasks - $updatesByType = [ 'data' => [], 'generic' => [] ]; - foreach ( $updates as $du ) { - if ( $du instanceof DataUpdate ) { - $updatesByType['data'][] = $du; + // Segregate the queue into one for DataUpdate and one for everything else + $dataUpdateQueue = []; + $genericUpdateQueue = []; + foreach ( $updates as $update ) { + if ( $update instanceof DataUpdate ) { + $dataUpdateQueue[] = $update; } else { - $updatesByType['generic'][] = $du; + $genericUpdateQueue[] = $update; } - - $name = ( $du instanceof DeferrableCallback ) - ? get_class( $du ) . '-' . $du->getOrigin() - : get_class( $du ); - $stats->increment( 'deferred_updates.' . $method . '.' . $name ); } - - // Execute all remaining tasks... - foreach ( $updatesByType as $updatesForType ) { - foreach ( $updatesForType as $update ) { + // Execute all DataUpdate queue followed by the DeferrableUpdate queue... + foreach ( [ $dataUpdateQueue, $genericUpdateQueue ] as $updateQueue ) { + foreach ( $updateQueue as $du ) { + // Enqueue the task into the job queue system instead if applicable + if ( $mode === 'enqueue' && $du instanceof EnqueueableDataUpdate ) { + self::jobify( $du, $lbf, $logger, $stats, $httpMethod ); + continue; + } + // Otherwise, execute the task and any subtasks that it spawns self::$executeContext = [ 'stage' => $stage, 'subqueue' => [] ]; try { - /** @var DeferrableUpdate $update */ - $guiError = self::handleUpdate( $update, $lbFactory, $mode, $stage ); - $reportableError = $reportableError ?: $guiError; + $e = self::run( $du, $lbf, $logger, $stats, $httpMethod ); + $guiEx = $guiEx ?: ( $e instanceof ErrorPageError ? $e : null ); // Do the subqueue updates for $update until there are none while ( self::$executeContext['subqueue'] ) { - $subUpdate = reset( self::$executeContext['subqueue'] ); + $duChild = reset( self::$executeContext['subqueue'] ); $firstKey = key( self::$executeContext['subqueue'] ); unset( self::$executeContext['subqueue'][$firstKey] ); - $guiError = self::handleUpdate( $subUpdate, $lbFactory, $mode, $stage ); - $reportableError = $reportableError ?: $guiError; + $e = self::run( $duChild, $lbf, $logger, $stats, $httpMethod ); + $guiEx = $guiEx ?: ( $e instanceof ErrorPageError ? $e : null ); } } finally { // Make sure we always clean up the context. @@ -237,40 +244,53 @@ class DeferredUpdates { $updates = $queue; // new snapshot of queue (check for new entries) } - if ( $reportableError ) { - throw $reportableError; // throw the first of any GUI errors + // Throw the first of any GUI errors as long as the context is HTTP pre-send. However, + // callers should check permissions *before* enqueueing updates. If the main transaction + // round actions succeed but some deferred updates fail due to permissions errors then + // there is a risk that some secondary data was not properly updated. + if ( $guiEx && $stage === self::PRESEND && !headers_sent() ) { + throw $guiEx; } } /** - * Run or enqueue an update + * Run a task and catch/log any exceptions * * @param DeferrableUpdate $update * @param LBFactory $lbFactory - * @param string $mode - * @param int $stage - * @return ErrorPageError|null + * @param LoggerInterface $logger + * @param StatsdDataFactoryInterface $stats + * @param string $httpMethod + * @return Exception|Throwable|null */ - private static function handleUpdate( - DeferrableUpdate $update, LBFactory $lbFactory, $mode, $stage + private static function run( + DeferrableUpdate $update, + LBFactory $lbFactory, + LoggerInterface $logger, + StatsdDataFactoryInterface $stats, + $httpMethod ) { - $guiError = null; + $name = get_class( $update ); + $suffix = ( $update instanceof DeferrableCallback ) ? "_{$update->getOrigin()}" : ''; + $stats->increment( "deferred_updates.$httpMethod.{$name}{$suffix}" ); + + $e = null; try { - if ( $mode === 'enqueue' && $update instanceof EnqueueableDataUpdate ) { - // Run only the job enqueue logic to complete the update later - $spec = $update->getAsJobSpecification(); - $domain = $spec['domain'] ?? $spec['wiki']; - JobQueueGroup::singleton( $domain )->push( $spec['job'] ); - } else { - self::attemptUpdate( $update, $lbFactory ); - } + self::attemptUpdate( $update, $lbFactory ); } catch ( Exception $e ) { - // Reporting GUI exceptions does not work post-send - if ( $e instanceof ErrorPageError && $stage === self::PRESEND ) { - $guiError = $e; - } - $lbFactory->rollbackMasterChanges( __METHOD__ ); + } catch ( Throwable $e ) { + } + if ( $e ) { + $logger->error( + "Deferred update {type} failed: {message}", + [ + 'type' => $name . $suffix, + 'message' => $e->getMessage(), + 'trace' => $e->getTraceAsString() + ] + ); + $lbFactory->rollbackMasterChanges( __METHOD__ ); // VW-style hack to work around T190178, so we can make sure // PageMetaDataUpdater doesn't throw exceptions. if ( defined( 'MW_PHPUNIT_TEST' ) ) { @@ -278,7 +298,46 @@ class DeferredUpdates { } } - return $guiError; + return $e; + } + + /** + * Push a task into the job queue system and catch/log any exceptions + * + * @param EnqueueableDataUpdate $update + * @param LBFactory $lbFactory + * @param LoggerInterface $logger + * @param StatsdDataFactoryInterface $stats + * @param string $httpMethod + */ + private static function jobify( + EnqueueableDataUpdate $update, + LBFactory $lbFactory, + LoggerInterface $logger, + StatsdDataFactoryInterface $stats, + $httpMethod + ) { + $stats->increment( "deferred_updates.$httpMethod." . get_class( $update ) ); + + $e = null; + try { + $spec = $update->getAsJobSpecification(); + JobQueueGroup::singleton( $spec['domain'] ?? $spec['wiki'] )->push( $spec['job'] ); + } catch ( Exception $e ) { + } catch ( Throwable $e ) { + } + + if ( $e ) { + $logger->error( + "Job insertion of deferred update {type} failed: {message}", + [ + 'type' => get_class( $update ), + 'message' => $e->getMessage(), + 'trace' => $e->getTraceAsString() + ] + ); + $lbFactory->rollbackMasterChanges( __METHOD__ ); + } } /** @@ -301,12 +360,18 @@ class DeferredUpdates { $update instanceof TransactionRoundAwareUpdate && $update->getTransactionRoundRequirement() == $update::TRX_ROUND_ABSENT ) { - $update->doUpdate(); + $fnameTrxOwner = null; } else { - // Run the bulk of the update now $fnameTrxOwner = get_class( $update ) . '::doUpdate'; + } + + if ( $fnameTrxOwner !== null ) { $lbFactory->beginMasterChanges( $fnameTrxOwner ); - $update->doUpdate(); + } + + $update->doUpdate(); + + if ( $fnameTrxOwner !== null ) { $lbFactory->commitMasterChanges( $fnameTrxOwner ); } } -- 2.20.1