From 3a044ca51ce9b35e3551e2a8aa32081ada253acb Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Wed, 26 Jun 2019 20:35:50 -0700 Subject: [PATCH] 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 --- includes/Revision/RenderedRevision.php | 54 ++++++++----------- includes/ServiceWiring.php | 3 +- includes/parser/Parser.php | 72 +++++++++++++++++--------- includes/parser/ParserFactory.php | 32 +++++++++--- 4 files changed, 98 insertions(+), 63 deletions(-) diff --git a/includes/Revision/RenderedRevision.php b/includes/Revision/RenderedRevision.php index cf1cc947a7..818494a092 100644 --- 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 339c34ce01..018c371a12 100644 --- 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 0721446ba7..863b5e8808 100644 --- 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 0446d9c640..3d15e86fd5 100644 --- 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 + ); } } -- 2.20.1