Merge "Log errors in DeferredUpdates::handleUpdateQueue()"

diff --git a/includes/deferred/DeferredUpdates.php b/includes/deferred/DeferredUpdates.php
index f5d22c1..c754cff 100644 (file)
--- 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 );
                }
        }