parser: inject a Logger into Parser instead of using wfDebug()

Add Parser::setOutputFlag helper method to reduce code duplication.
Also, clean up various Parser and SaveParse debug log messages.

Bug: T226785
Change-Id: I5dce2220bd43f5d642c017b88d02870dcb92f44e

diff --git a/includes/Revision/RenderedRevision.php b/includes/Revision/RenderedRevision.php
index cf1cc94..818494a 100644 (file)
--- a/includes/Revision/RenderedRevision.php
+++ b/includes/Revision/RenderedRevision.php
@@ -316,7 +316,7 @@ class RenderedRevision implements SlotRenderingProvider {
                                $this->revisionOutput = null;
                        }
                } else {
-                       $this->saveParseLogger->debug( __METHOD__ . ": no prepared revision output...\n" );
+                       $this->saveParseLogger->debug( __METHOD__ . ": no prepared revision output" );
                }
 
                foreach ( $this->slotsOutput as $role => $output ) {
@@ -397,38 +397,34 @@ class RenderedRevision implements SlotRenderingProvider {
                $actualRevId,
                $actualRevTimestamp
        ) {
-               $method = __METHOD__;
+               $logger = $this->saveParseLogger;
+               $varyMsg = __METHOD__ . ": cannot use prepared output for '{title}'";
+               $context = [ 'title' => $this->title->getPrefixedText() ];
 
                if ( $out->getFlag( 'vary-revision' ) ) {
                        // If {{PAGEID}} resolved to 0, then that word need to resolve to the actual page ID
-                       $this->saveParseLogger->info(
-                               "$method: Prepared output has vary-revision..."
-                       );
+                       $logger->info( "$varyMsg (vary-revision)", $context );
                        return true;
-               } elseif ( $out->getFlag( 'vary-revision-id' )
+               } elseif (
+                       $out->getFlag( 'vary-revision-id' )
                        && $actualRevId !== false
                        && ( $actualRevId === true || $out->getSpeculativeRevIdUsed() !== $actualRevId )
                ) {
-                       $this->saveParseLogger->info(
-                               "$method: Prepared output has vary-revision-id with wrong ID..."
-                       );
+                       $logger->info( "$varyMsg (vary-revision-id and wrong ID)", $context );
                        return true;
-               } elseif ( $out->getFlag( 'vary-revision-timestamp' )
+               } elseif (
+                       $out->getFlag( 'vary-revision-timestamp' )
                        && $actualRevTimestamp !== false
                        && ( $actualRevTimestamp === true ||
                                $out->getRevisionTimestampUsed() !== $actualRevTimestamp )
                ) {
-                       $this->saveParseLogger->info(
-                               "$method: Prepared output has vary-revision-timestamp with wrong timestamp..."
-                       );
+                       $logger->info( "$varyMsg (vary-revision-timestamp and wrong timestamp)", $context );
                        return true;
                } elseif ( $out->getFlag( 'vary-revision-exists' ) ) {
                        // If {{REVISIONID}} resolved to '', it now needs to resolve to '-'.
                        // Note that edit stashing always uses '-', which can be used for both
                        // edit filter checks and canonical parser cache.
-                       $this->saveParseLogger->info(
-                               "$method: Prepared output has vary-revision-exists..."
-                       );
+                       $logger->info( "$varyMsg (vary-revision-exists)", $context );
                        return true;
                } elseif (
                        $out->getFlag( 'vary-revision-sha1' ) &&
@@ -436,22 +432,18 @@ class RenderedRevision implements SlotRenderingProvider {
                ) {
                        // If a self-transclusion used the proposed page text, it must match the final
                        // page content after PST transformations and automatically merged edit conflicts
-                       $this->saveParseLogger->info(
-                               "$method: Prepared output has vary-revision-sha1 with wrong SHA-1..."
-                       );
+                       $logger->info( "$varyMsg (vary-revision-sha1 with wrong SHA-1)" );
                        return true;
-               } else {
-                       // NOTE: In the original fix for T135261, the output was discarded if 'vary-user' was
-                       // set for a null-edit. The reason was that the original rendering in that case was
-                       // targeting the user making the null-edit, not the user who made the original edit,
-                       // causing {{REVISIONUSER}} to return the wrong name.
-                       // This case is now expected to be handled by the code in RevisionRenderer that
-                       // constructs the ParserOptions: For a null-edit, setCurrentRevisionCallback is called
-                       // with the old, existing revision.
-
-                       $this->saveParseLogger->debug( "$method: Keeping prepared output..." );
-                       return false;
                }
-       }
 
+               // NOTE: In the original fix for T135261, the output was discarded if 'vary-user' was
+               // set for a null-edit. The reason was that the original rendering in that case was
+               // targeting the user making the null-edit, not the user who made the original edit,
+               // causing {{REVISIONUSER}} to return the wrong name.
+               // This case is now expected to be handled by the code in RevisionRenderer that
+               // constructs the ParserOptions: For a null-edit, setCurrentRevisionCallback is called
+               // with the old, existing revision.
+               $logger->debug( __METHOD__ . ": reusing prepared output for '{title}'", $context );
+               return false;
+       }
 }

diff --git a/includes/ServiceWiring.php b/includes/ServiceWiring.php
index 339c34c..018c371 100644 (file)
--- a/includes/ServiceWiring.php
+++ b/includes/ServiceWiring.php
@@ -439,7 +439,8 @@ return [
                        wfUrlProtocols(),
                        $services->getSpecialPageFactory(),
                        $services->getLinkRendererFactory(),
-                       $services->getNamespaceInfo()
+                       $services->getNamespaceInfo(),
+                       LoggerFactory::getInstance( 'Parser' )
                );
        },
 

diff --git a/includes/parser/Parser.php b/includes/parser/Parser.php
index 0721446..863b5e8 100644 (file)
--- a/includes/parser/Parser.php
+++ b/includes/parser/Parser.php
@@ -26,7 +26,9 @@ use MediaWiki\Linker\LinkRendererFactory;
 use MediaWiki\Linker\LinkTarget;
 use MediaWiki\MediaWikiServices;
 use MediaWiki\Special\SpecialPageFactory;
+use Psr\Log\NullLogger;
 use Wikimedia\ScopedCallback;
+use Psr\Log\LoggerInterface;
 
 /**
  * @defgroup Parser Parser
@@ -294,6 +296,9 @@ class Parser {
        /** @var NamespaceInfo */
        private $nsInfo;
 
+       /** @var LoggerInterface */
+       private $logger;
+
        /**
         * TODO Make this a const when HHVM support is dropped (T192166)
         *
@@ -333,11 +338,18 @@ class Parser {
         * @param SpecialPageFactory|null $spFactory
         * @param LinkRendererFactory|null $linkRendererFactory
         * @param NamespaceInfo|null $nsInfo
+        * @param LoggerInterface|null $logger
         */
        public function __construct(
-               $svcOptions = null, MagicWordFactory $magicWordFactory = null,
-               Language $contLang = null, ParserFactory $factory = null, $urlProtocols = null,
-               SpecialPageFactory $spFactory = null, $linkRendererFactory = null, $nsInfo = null
+               $svcOptions = null,
+               MagicWordFactory $magicWordFactory = null,
+               Language $contLang = null,
+               ParserFactory $factory = null,
+               $urlProtocols = null,
+               SpecialPageFactory $spFactory = null,
+               $linkRendererFactory = null,
+               $nsInfo = null,
+               $logger = null
        ) {
                $services = MediaWikiServices::getInstance();
                if ( !$svcOptions || is_array( $svcOptions ) ) {
@@ -382,6 +394,7 @@ class Parser {
                $this->specialPageFactory = $spFactory ?? $services->getSpecialPageFactory();
                $this->linkRendererFactory = $linkRendererFactory ?? $services->getLinkRendererFactory();
                $this->nsInfo = $nsInfo ?? $services->getNamespaceInfo();
+               $this->logger = $logger ?: new NullLogger();
        }
 
        /**
@@ -2776,8 +2789,7 @@ class Parser {
                                        # which means the user is previewing a new page.
                                        # The vary-revision flag must be set, because the magic word
                                        # will have a different value once the page is saved.
-                                       $this->mOutput->setFlag( 'vary-revision' );
-                                       wfDebug( __METHOD__ . ": {{PAGEID}} used in a new page, setting vary-revision" );
+                                       $this->setOutputFlag( 'vary-revision', '{{PAGEID}} on new page' );
                                }
                                $value = $pageid ?: null;
                                break;
@@ -2793,15 +2805,13 @@ class Parser {
                                        if ( $this->getRevisionId() || $this->mOptions->getSpeculativeRevId() ) {
                                                $value = '-';
                                        } else {
-                                               $this->mOutput->setFlag( 'vary-revision-exists' );
-                                               wfDebug( __METHOD__ . ": {{REVISIONID}} used, setting vary-revision-exists" );
+                                               $this->setOutputFlag( 'vary-revision-exists', '{{REVISIONID}} used' );
                                                $value = '';
                                        }
                                } else {
                                        # Inform the edit saving system that getting the canonical output after
                                        # revision insertion requires another parse using the actual revision ID
-                                       $this->mOutput->setFlag( 'vary-revision-id' );
-                                       wfDebug( __METHOD__ . ": {{REVISIONID}} used, setting vary-revision-id" );
+                                       $this->setOutputFlag( 'vary-revision-id', '{{REVISIONID}} used' );
                                        $value = $this->getRevisionId();
                                        if ( $value === 0 ) {
                                                $rev = $this->getRevisionObject();
@@ -2836,8 +2846,7 @@ class Parser {
                        case 'revisionuser':
                                # Inform the edit saving system that getting the canonical output after
                                # revision insertion requires a parse that used the actual user ID
-                               $this->mOutput->setFlag( 'vary-user' );
-                               wfDebug( __METHOD__ . ": {{REVISIONUSER}} used, setting vary-user" );
+                               $this->setOutputFlag( 'vary-user', '{{REVISIONUSER}} used' );
                                $value = $this->getRevisionUser();
                                break;
                        case 'revisionsize':
@@ -3007,8 +3016,7 @@ class Parser {
                        if ( $resNow !== $resThen ) {
                                # Inform the edit saving system that getting the canonical output after
                                # revision insertion requires a parse that used an actual revision timestamp
-                               $this->mOutput->setFlag( 'vary-revision-timestamp' );
-                               wfDebug( __METHOD__ . ": $variable used, setting vary-revision-timestamp" );
+                               $this->setOutputFlag( 'vary-revision-timestamp', "$variable used" );
                        }
                }
 
@@ -3105,8 +3113,10 @@ class Parser {
                if ( $frame === false ) {
                        $frame = $this->getPreprocessor()->newFrame();
                } elseif ( !( $frame instanceof PPFrame ) ) {
-                       wfDebug( __METHOD__ . " called using plain parameters instead of "
-                               . "a PPFrame instance. Creating custom frame.\n" );
+                       $this->logger->debug(
+                               __METHOD__ . " called using plain parameters instead of " .
+                               "a PPFrame instance. Creating custom frame."
+                       );
                        $frame = $this->getPreprocessor()->newCustomFrame( $frame );
                }
 
@@ -3407,8 +3417,10 @@ class Parser {
                                        }
                                } elseif ( $this->nsInfo->isNonincludable( $title->getNamespace() ) ) {
                                        $found = false; # access denied
-                                       wfDebug( __METHOD__ . ": template inclusion denied for " .
-                                               $title->getPrefixedDBkey() . "\n" );
+                                       $this->logger->debug(
+                                               __METHOD__ .
+                                               ": template inclusion denied for " . $title->getPrefixedDBkey()
+                                       );
                                } else {
                                        list( $text, $title ) = $this->getTemplateDom( $title );
                                        if ( $text !== false ) {
@@ -3446,7 +3458,7 @@ class Parser {
                                $this->addTrackingCategory( 'template-loop-category' );
                                $this->mOutput->addWarning( wfMessage( 'template-loop-warning',
                                        wfEscapeWikiText( $titleText ) )->text() );
-                               wfDebug( __METHOD__ . ": template loop broken at '$titleText'\n" );
+                               $this->logger->debug( __METHOD__ . ": template loop broken at '$titleText'" );
                        }
                }
 
@@ -3740,8 +3752,7 @@ class Parser {
                                $this->mOutput->addTemplate( $dep['title'], $dep['page_id'], $dep['rev_id'] );
                                if ( $dep['title']->equals( $this->getTitle() ) ) {
                                        // Self-transclusion; final result may change based on the new page version
-                                       $this->mOutput->setFlag( 'vary-revision' );
-                                       wfDebug( __METHOD__ . ": self transclusion, setting vary-revision" );
+                                       $this->setOutputFlag( 'vary-revision', 'Self transclusion' );
                                }
                        }
                }
@@ -4685,7 +4696,7 @@ class Parser {
                                '~~~' => $sigText
                        ] );
                        # The main two signature forms used above are time-sensitive
-                       $this->mOutput->setFlag( 'user-signature' );
+                       $this->setOutputFlag( 'user-signature', 'User signature detected' );
                }
 
                # Context links ("pipe tricks"): [[|name]] and [[name (context)|]]
@@ -4750,7 +4761,7 @@ class Parser {
 
                if ( mb_strlen( $nickname ) > $this->svcOptions->get( 'MaxSigChars' ) ) {
                        $nickname = $username;
-                       wfDebug( __METHOD__ . ": $username has overlong signature.\n" );
+                       $this->logger->debug( __METHOD__ . ": $username has overlong signature." );
                } elseif ( $fancySig !== false ) {
                        # Sig. might contain markup; validate this
                        if ( $this->validateSig( $nickname ) !== false ) {
@@ -4759,7 +4770,7 @@ class Parser {
                        } else {
                                # Failed to validate; fall back to the default
                                $nickname = $username;
-                               wfDebug( __METHOD__ . ": $username has bad XML tags in signature.\n" );
+                               $this->logger->debug( __METHOD__ . ": $username has bad XML tags in signature." );
                        }
                }
 
@@ -5256,7 +5267,8 @@ class Parser {
                                                                        $handlerOptions[$paramName] = $match;
                                                                } else {
                                                                        // Guess not, consider it as caption.
-                                                                       wfDebug( "$parameterMatch failed parameter validation\n" );
+                                                                       $this->logger->debug(
+                                                                               "$parameterMatch failed parameter validation" );
                                                                        $label = $parameterMatch;
                                                                }
                                                }
@@ -5642,7 +5654,7 @@ class Parser {
         * @deprecated since 1.28; use getOutput()->updateCacheExpiry()
         */
        public function disableCache() {
-               wfDebug( "Parser output marked as uncacheable.\n" );
+               $this->logger->debug( "Parser output marked as uncacheable." );
                if ( !$this->mOutput ) {
                        throw new MWException( __METHOD__ .
                                " can only be called when actually parsing something" );
@@ -6448,4 +6460,14 @@ class Parser {
                OutputPage::setupOOUI();
                $this->mOutput->setEnableOOUI( true );
        }
+
+       /**
+        * @param string $flag
+        * @param string $reason
+        */
+       protected function setOutputFlag( $flag, $reason ) {
+               $this->mOutput->setFlag( $flag );
+               $name = $this->mTitle->getPrefixedText();
+               $this->logger->debug( __METHOD__ . ": set $flag flag on '$name'; $reason" );
+       }
 }

diff --git a/includes/parser/ParserFactory.php b/includes/parser/ParserFactory.php
index 0446d9c..3d15e86 100644 (file)
--- a/includes/parser/ParserFactory.php
+++ b/includes/parser/ParserFactory.php
@@ -23,6 +23,8 @@ use MediaWiki\Config\ServiceOptions;
 use MediaWiki\Linker\LinkRendererFactory;
 use MediaWiki\MediaWikiServices;
 use MediaWiki\Special\SpecialPageFactory;
+use Psr\Log\LoggerInterface;
+use Psr\Log\NullLogger;
 
 /**
  * @since 1.32
@@ -49,6 +51,9 @@ class ParserFactory {
        /** @var NamespaceInfo */
        private $nsInfo;
 
+       /** @var LoggerInterface */
+       private $logger;
+
        /**
         * Old parameter list, which we support for backwards compatibility, were:
         *   array $parserConf See $wgParserConf documentation
@@ -71,12 +76,18 @@ class ParserFactory {
         * @param SpecialPageFactory $spFactory
         * @param LinkRendererFactory $linkRendererFactory
         * @param NamespaceInfo|LinkRendererFactory|null $nsInfo
+        * @param LoggerInterface|null $logger
         * @since 1.32
         */
        public function __construct(
-               $svcOptions, MagicWordFactory $magicWordFactory, Language $contLang,
-               $urlProtocols, SpecialPageFactory $spFactory, $linkRendererFactory,
-               $nsInfo = null
+               $svcOptions,
+               MagicWordFactory $magicWordFactory,
+               Language $contLang,
+               $urlProtocols,
+               SpecialPageFactory $spFactory,
+               $linkRendererFactory,
+               $nsInfo = null,
+               $logger = null
        ) {
                // @todo Do we need to retain compat for constructing this class directly?
                if ( !$nsInfo ) {
@@ -107,6 +118,7 @@ class ParserFactory {
                $this->specialPageFactory = $spFactory;
                $this->linkRendererFactory = $linkRendererFactory;
                $this->nsInfo = $nsInfo;
+               $this->logger = $logger ?: new NullLogger();
        }
 
        /**
@@ -114,8 +126,16 @@ class ParserFactory {
         * @since 1.32
         */
        public function create() : Parser {
-               return new Parser( $this->svcOptions, $this->magicWordFactory, $this->contLang, $this,
-                       $this->urlProtocols, $this->specialPageFactory, $this->linkRendererFactory,
-                       $this->nsInfo );
+               return new Parser(
+                       $this->svcOptions,
+                       $this->magicWordFactory,
+                       $this->contLang,
+                       $this,
+                       $this->urlProtocols,
+                       $this->specialPageFactory,
+                       $this->linkRendererFactory,
+                       $this->nsInfo,
+                       $this->logger
+               );
        }
 }