Log deprecated vars in the cached phase in the new parser

For the new parser, xhgui shows that AbuseFilterParser::getVarValue is
taking up a lot of time; in turn, most of the time spent inside
getVarValue is used to log the use of deprecated variables. Hence, given
that:
 - We should keep the new parser performant
 - There are tons of deprecated variables out there and they likely
 won't be replaced
 - Having gazillions of debugLog entries doesn't help

log them only in the cached phase.

Bug: T234427
Change-Id: I2bfc692c829c3cbe889e5076f5205e2c99097087

includes/AbuseFilterVariableHolder.php

@@ -110,10 +110,11 @@ class AbuseFilterVariableHolder {
 	 */
 	public function getVar( $varName, $flags = self::GET_STRICT, $tempFilter = null ) : AFPData {
 		$varName = strtolower( $varName );
-		if ( $this->mVarsVersion === 1 && in_array( $varName, AbuseFilter::getDeprecatedVariables() ) ) {
+		$deprecatedVars = AbuseFilter::getDeprecatedVariables();
+		if ( $this->mVarsVersion === 1 && in_array( $varName, $deprecatedVars ) ) {
 			// Variables are stored with old names, but the parser has given us
 			// a new name. Translate it back.
-			$varName = array_search( $varName, AbuseFilter::getDeprecatedVariables() );
+			$varName = array_search( $varName, $deprecatedVars );
 		}
 
 		if ( $this->varIsSet( $varName ) ) {

includes/parser/AFPTreeParser.php

@@ -672,6 +672,8 @@ class AFPTreeParser extends AFPTransitionBase {
 		$tok = $this->mCur->value;
 		switch ( $this->mCur->type ) {
 			case AFPToken::TID:
+				$this->checkLogDeprecatedVar( strtolower( $tok ) );
+				// Fallthrough intended
 			case AFPToken::TSTRING:
 			case AFPToken::TFLOAT:
 			case AFPToken::TINT:
@@ -731,4 +733,16 @@ class AFPTreeParser extends AFPTransitionBase {
 		$this->move();
 		return $result;
 	}
+
+	/**
+	 * Given a variable name, check if the variable is deprecated. If it is, log the use.
+	 * Do that here, and not every time the AST is eval'ed. This means less logging, but more
+	 * performance.
+	 * @param string $varname
+	 */
+	protected function checkLogDeprecatedVar( $varname ) {
+		if ( array_key_exists( $varname, AbuseFilter::getDeprecatedVariables() ) ) {
+			$this->logger->debug( "Deprecated variable $varname used in filter {$this->mFilter}." );
+		}
+	}
 }

includes/parser/AbuseFilterCachingParser.php

@@ -390,4 +390,12 @@ class AbuseFilterCachingParser extends AbuseFilterParser {
 			}
 		}
 	}
+
+	/**
+	 * @inheritDoc
+	 * This parser should not log, because that's handled in AFPTreeParser
+	 */
+	protected function logsDeprecatedVars() {
+		return false;
+	}
 }

includes/parser/AbuseFilterParser.php

@@ -1067,7 +1067,9 @@ class AbuseFilterParser extends AFPTransitionBase {
 		$deprecatedVars = AbuseFilter::getDeprecatedVariables();
 
 		if ( array_key_exists( $var, $deprecatedVars ) ) {
-			$this->logger->debug( "AbuseFilter: deprecated variable $var used." );
+			if ( $this->logsDeprecatedVars() ) {
+				$this->logger->debug( "Deprecated variable $var used in filter {$this->mFilter}." );
+			}
 			$var = $deprecatedVars[ $var ];
 		}
 		if ( array_key_exists( $var, AbuseFilter::DISABLED_VARS ) ) {
@@ -1092,6 +1094,14 @@ class AbuseFilterParser extends AFPTransitionBase {
 		return $this->mVariables->getVar( $var, $flags, $this->mFilter );
 	}
 
+	/**
+	 * Whether this parser should log deprecated vars use.
+	 * @return bool
+	 */
+	protected function logsDeprecatedVars() {
+		return true;
+	}
+
 	/**
 	 * @param string $name
 	 * @param mixed $value

tests/phpunit/unit/AbuseFilterParserTest.php

@@ -819,7 +819,7 @@ class AbuseFilterParserTest extends AbuseFilterParserTestCase {
 			// Check that the use has been logged
 			$found = false;
 			foreach ( $loggerBuffer as $entry ) {
-				$check = preg_match( '/AbuseFilter: deprecated variable/', $entry[1] );
+				$check = preg_match( '/^Deprecated variable/', $entry[1] );
 				if ( $check ) {
 					$found = true;
 					break;