From f910dd7a1006810a910678317ff9dac217e477f8 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Mon, 12 Sep 2016 15:10:16 -0700 Subject: [PATCH] Convert LoadBalancer/Database class logging to PSR Reorder DatabaseBase constructor/factory to the top. Change-Id: I2ffff950b9170d6ff15dcd46b64dd366f1e441a8 --- includes/db/ChronologyProtector.php | 31 +- includes/db/Database.php | 360 ++++++++++-------- includes/db/loadbalancer/LBFactory.php | 13 +- includes/db/loadbalancer/LoadBalancer.php | 97 +++-- includes/db/loadbalancer/LoadMonitor.php | 11 +- includes/db/loadbalancer/LoadMonitorMySQL.php | 22 +- 6 files changed, 299 insertions(+), 235 deletions(-) diff --git a/includes/db/ChronologyProtector.php b/includes/db/ChronologyProtector.php index 1cdb49f350..9b01adcdf4 100644 --- a/includes/db/ChronologyProtector.php +++ b/includes/db/ChronologyProtector.php @@ -20,14 +20,19 @@ * @file * @ingroup Database */ +use Psr\Log\LoggerAwareInterface; +use Psr\Log\LoggerInterface; +use MediaWiki\Logger\LoggerFactory; /** * Class for ensuring a consistent ordering of events as seen by the user, despite replication. * Kind of like Hawking's [[Chronology Protection Agency]]. */ -class ChronologyProtector { +class ChronologyProtector implements LoggerAwareInterface{ /** @var BagOStuff */ protected $store; + /** @var LoggerInterface */ + protected $logger; /** @var string Storage key name */ protected $key; @@ -67,6 +72,11 @@ class ChronologyProtector { $this->clientId = md5( $client['ip'] . "\n" . $client['agent'] ); $this->key = $store->makeGlobalKey( __CLASS__, $this->clientId ); $this->waitForPosTime = $posTime; + $this->logger = LoggerFactory::getInstance( 'DBReplication' ); + } + + public function setLogger( LoggerInterface $logger ) { + $this->logger = $logger; } /** @@ -106,7 +116,7 @@ class ChronologyProtector { $masterName = $lb->getServerName( $lb->getWriterIndex() ); if ( !empty( $this->startupPositions[$masterName] ) ) { $pos = $this->startupPositions[$masterName]; - wfDebugLog( 'replication', __METHOD__ . ": LB for '$masterName' set to pos $pos\n" ); + $this->logger->info( __METHOD__ . ": LB for '$masterName' set to pos $pos\n" ); $lb->waitFor( $pos ); } } @@ -129,10 +139,10 @@ class ChronologyProtector { $masterName = $lb->getServerName( $lb->getWriterIndex() ); if ( $lb->getServerCount() > 1 ) { $pos = $lb->getMasterPos(); - wfDebugLog( 'replication', __METHOD__ . ": LB for '$masterName' has pos $pos\n" ); + $this->logger->info( __METHOD__ . ": LB for '$masterName' has pos $pos\n" ); $this->shutdownPositions[$masterName] = $pos; } else { - wfDebugLog( 'replication', __METHOD__ . ": DB '$masterName' touched\n" ); + $this->logger->info( __METHOD__ . ": DB '$masterName' touched\n" ); } $this->shutdownTouchDBs[$masterName] = 1; } @@ -165,8 +175,7 @@ class ChronologyProtector { return []; // nothing to save } - wfDebugLog( 'replication', - __METHOD__ . ": saving master pos for " . + $this->logger->info( __METHOD__ . ": saving master pos for " . implode( ', ', array_keys( $this->shutdownPositions ) ) . "\n" ); @@ -193,16 +202,14 @@ class ChronologyProtector { if ( !$ok ) { $bouncedPositions = $this->shutdownPositions; // Raced out too many times or stash is down - wfDebugLog( 'replication', - __METHOD__ . ": failed to save master pos for " . + $this->logger->warning( __METHOD__ . ": failed to save master pos for " . implode( ', ', array_keys( $this->shutdownPositions ) ) . "\n" ); } elseif ( $mode === 'sync' && $store->getQoS( $store::ATTR_SYNCWRITES ) < $store::QOS_SYNCWRITES_BE ) { // Positions may not be in all datacenters, force LBFactory to play it safe - wfDebugLog( 'replication', - __METHOD__ . ": store does not report ability to sync replicas. " ); + $this->logger->info( __METHOD__ . ": store may not support synchronous writes." ); $bouncedPositions = $this->shutdownPositions; } else { $bouncedPositions = []; @@ -267,10 +274,10 @@ class ChronologyProtector { } $this->startupPositions = $data ? $data['positions'] : []; - wfDebugLog( 'replication', __METHOD__ . ": key is {$this->key} (read)\n" ); + $this->logger->info( __METHOD__ . ": key is {$this->key} (read)\n" ); } else { $this->startupPositions = []; - wfDebugLog( 'replication', __METHOD__ . ": key is {$this->key} (unread)\n" ); + $this->logger->info( __METHOD__ . ": key is {$this->key} (unread)\n" ); } } diff --git a/includes/db/Database.php b/includes/db/Database.php index c41e7c7b93..b044e23c18 100644 --- a/includes/db/Database.php +++ b/includes/db/Database.php @@ -1,5 +1,4 @@ srvCache = ObjectCache::getLocalServerInstance( 'hash' ); + + $server = $params['host']; + $user = $params['user']; + $password = $params['password']; + $dbName = $params['dbname']; + $flags = $params['flags']; + $tablePrefix = $params['tablePrefix']; + $schema = $params['schema']; + $foreign = $params['foreign']; + + $this->cliMode = isset( $params['cliMode'] ) + ? $params['cliMode'] + : ( PHP_SAPI === 'cli' ); + + $this->mFlags = $flags; + if ( $this->mFlags & DBO_DEFAULT ) { + if ( $this->cliMode ) { + $this->mFlags &= ~DBO_TRX; + } else { + $this->mFlags |= DBO_TRX; + } + } + + $this->mSessionVars = $params['variables']; + + /** Get the default table prefix*/ + if ( $tablePrefix === 'get from global' ) { + $this->mTablePrefix = $wgDBprefix; + } else { + $this->mTablePrefix = $tablePrefix; + } + + /** Get the database schema*/ + if ( $schema === 'get from global' ) { + $this->mSchema = $wgDBmwschema; + } else { + $this->mSchema = $schema; + } + + $this->mForeign = $foreign; + + $this->profiler = isset( $params['profiler'] ) + ? $params['profiler'] + : Profiler::instance(); // @TODO: remove global state + $this->trxProfiler = isset( $params['trxProfiler'] ) + ? $params['trxProfiler'] + : new TransactionProfiler(); + $this->connLogger = isset( $params['connLogger'] ) + ? $params['connLogger'] + : new \Psr\Log\NullLogger(); + $this->queryLogger = isset( $params['queryLogger'] ) + ? $params['queryLogger'] + : new \Psr\Log\NullLogger(); + + if ( $user ) { + $this->open( $server, $user, $password, $dbName ); + } + } + + /** + * Given a DB type, construct the name of the appropriate child class of + * DatabaseBase. This is designed to replace all of the manual stuff like: + * $class = 'Database' . ucfirst( strtolower( $dbType ) ); + * as well as validate against the canonical list of DB types we have + * + * This factory function is mostly useful for when you need to connect to a + * database other than the MediaWiki default (such as for external auth, + * an extension, et cetera). Do not use this to connect to the MediaWiki + * database. Example uses in core: + * @see LoadBalancer::reallyOpenConnection() + * @see ForeignDBRepo::getMasterDB() + * @see WebInstallerDBConnect::execute() + * + * @since 1.18 + * + * @param string $dbType A possible DB type + * @param array $p An array of options to pass to the constructor. + * Valid options are: host, user, password, dbname, flags, tablePrefix, schema, driver + * @throws MWException If the database driver or extension cannot be found + * @return DatabaseBase|null DatabaseBase subclass or null + */ + final public static function factory( $dbType, $p = [] ) { + global $wgCommandLineMode; + + $canonicalDBTypes = [ + 'mysql' => [ 'mysqli', 'mysql' ], + 'postgres' => [], + 'sqlite' => [], + 'oracle' => [], + 'mssql' => [], + ]; + + $driver = false; + $dbType = strtolower( $dbType ); + if ( isset( $canonicalDBTypes[$dbType] ) && $canonicalDBTypes[$dbType] ) { + $possibleDrivers = $canonicalDBTypes[$dbType]; + if ( !empty( $p['driver'] ) ) { + if ( in_array( $p['driver'], $possibleDrivers ) ) { + $driver = $p['driver']; + } else { + throw new MWException( __METHOD__ . + " cannot construct Database with type '$dbType' and driver '{$p['driver']}'" ); + } + } else { + foreach ( $possibleDrivers as $posDriver ) { + if ( extension_loaded( $posDriver ) ) { + $driver = $posDriver; + break; + } + } + } + } else { + $driver = $dbType; + } + if ( $driver === false ) { + throw new MWException( __METHOD__ . + " no viable database extension found for type '$dbType'" ); + } + + // Determine schema defaults. Currently Microsoft SQL Server uses $wgDBmwschema, + // and everything else doesn't use a schema (e.g. null) + // Although postgres and oracle support schemas, we don't use them (yet) + // to maintain backwards compatibility + $defaultSchemas = [ + 'mssql' => 'get from global', + ]; + + $class = 'Database' . ucfirst( $driver ); + if ( class_exists( $class ) && is_subclass_of( $class, 'DatabaseBase' ) ) { + // Resolve some defaults for b/c + $p['host'] = isset( $p['host'] ) ? $p['host'] : false; + $p['user'] = isset( $p['user'] ) ? $p['user'] : false; + $p['password'] = isset( $p['password'] ) ? $p['password'] : false; + $p['dbname'] = isset( $p['dbname'] ) ? $p['dbname'] : false; + $p['flags'] = isset( $p['flags'] ) ? $p['flags'] : 0; + $p['variables'] = isset( $p['variables'] ) ? $p['variables'] : []; + $p['tablePrefix'] = isset( $p['tablePrefix'] ) ? $p['tablePrefix'] : 'get from global'; + if ( !isset( $p['schema'] ) ) { + $p['schema'] = isset( $defaultSchemas[$dbType] ) ? $defaultSchemas[$dbType] : null; + } + $p['foreign'] = isset( $p['foreign'] ) ? $p['foreign'] : false; + $p['cliMode'] = $wgCommandLineMode; + + $conn = new $class( $p ); + if ( isset( $p['connLogger'] ) ) { + $conn->connLogger = $p['connLogger']; + } + if ( isset( $p['queryLogger'] ) ) { + $conn->queryLogger = $p['queryLogger']; + } + } else { + $conn = null; + } + + return $conn; + } + + public function setLogger( LoggerInterface $logger ) { + $this->quertLogger = $logger; + } + public function getServerInfo() { return $this->getServerVersion(); } @@ -552,76 +734,6 @@ abstract class DatabaseBase implements IDatabase { */ abstract function strencode( $s ); - /** - * Constructor. - * - * FIXME: It is possible to construct a Database object with no associated - * connection object, by specifying no parameters to __construct(). This - * feature is deprecated and should be removed. - * - * DatabaseBase subclasses should not be constructed directly in external - * code. DatabaseBase::factory() should be used instead. - * - * @param array $params Parameters passed from DatabaseBase::factory() - */ - function __construct( array $params ) { - global $wgDBprefix, $wgDBmwschema; - - $this->srvCache = ObjectCache::getLocalServerInstance( 'hash' ); - - $server = $params['host']; - $user = $params['user']; - $password = $params['password']; - $dbName = $params['dbname']; - $flags = $params['flags']; - $tablePrefix = $params['tablePrefix']; - $schema = $params['schema']; - $foreign = $params['foreign']; - - $this->cliMode = isset( $params['cliMode'] ) - ? $params['cliMode'] - : ( PHP_SAPI === 'cli' ); - - $this->mFlags = $flags; - if ( $this->mFlags & DBO_DEFAULT ) { - if ( $this->cliMode ) { - $this->mFlags &= ~DBO_TRX; - } else { - $this->mFlags |= DBO_TRX; - } - } - - $this->mSessionVars = $params['variables']; - - /** Get the default table prefix*/ - if ( $tablePrefix === 'get from global' ) { - $this->mTablePrefix = $wgDBprefix; - } else { - $this->mTablePrefix = $tablePrefix; - } - - /** Get the database schema*/ - if ( $schema === 'get from global' ) { - $this->mSchema = $wgDBmwschema; - } else { - $this->mSchema = $schema; - } - - $this->mForeign = $foreign; - - $this->profiler = isset( $params['profiler'] ) - ? $params['profiler'] - : Profiler::instance(); // @TODO: remove global state - $this->trxProfiler = isset( $params['trxProfiler'] ) - ? $params['trxProfiler'] - : new TransactionProfiler(); - - if ( $user ) { - $this->open( $server, $user, $password, $dbName ); - } - - } - /** * Called by serialize. Throw an exception when DB connection is serialized. * This causes problems on some database engines because the connection is @@ -632,96 +744,6 @@ abstract class DatabaseBase implements IDatabase { 'the connection is not restored on wakeup.' ); } - /** - * Given a DB type, construct the name of the appropriate child class of - * DatabaseBase. This is designed to replace all of the manual stuff like: - * $class = 'Database' . ucfirst( strtolower( $dbType ) ); - * as well as validate against the canonical list of DB types we have - * - * This factory function is mostly useful for when you need to connect to a - * database other than the MediaWiki default (such as for external auth, - * an extension, et cetera). Do not use this to connect to the MediaWiki - * database. Example uses in core: - * @see LoadBalancer::reallyOpenConnection() - * @see ForeignDBRepo::getMasterDB() - * @see WebInstallerDBConnect::execute() - * - * @since 1.18 - * - * @param string $dbType A possible DB type - * @param array $p An array of options to pass to the constructor. - * Valid options are: host, user, password, dbname, flags, tablePrefix, schema, driver - * @throws MWException If the database driver or extension cannot be found - * @return DatabaseBase|null DatabaseBase subclass or null - */ - final public static function factory( $dbType, $p = [] ) { - global $wgCommandLineMode; - - $canonicalDBTypes = [ - 'mysql' => [ 'mysqli', 'mysql' ], - 'postgres' => [], - 'sqlite' => [], - 'oracle' => [], - 'mssql' => [], - ]; - - $driver = false; - $dbType = strtolower( $dbType ); - if ( isset( $canonicalDBTypes[$dbType] ) && $canonicalDBTypes[$dbType] ) { - $possibleDrivers = $canonicalDBTypes[$dbType]; - if ( !empty( $p['driver'] ) ) { - if ( in_array( $p['driver'], $possibleDrivers ) ) { - $driver = $p['driver']; - } else { - throw new MWException( __METHOD__ . - " cannot construct Database with type '$dbType' and driver '{$p['driver']}'" ); - } - } else { - foreach ( $possibleDrivers as $posDriver ) { - if ( extension_loaded( $posDriver ) ) { - $driver = $posDriver; - break; - } - } - } - } else { - $driver = $dbType; - } - if ( $driver === false ) { - throw new MWException( __METHOD__ . - " no viable database extension found for type '$dbType'" ); - } - - // Determine schema defaults. Currently Microsoft SQL Server uses $wgDBmwschema, - // and everything else doesn't use a schema (e.g. null) - // Although postgres and oracle support schemas, we don't use them (yet) - // to maintain backwards compatibility - $defaultSchemas = [ - 'mssql' => 'get from global', - ]; - - $class = 'Database' . ucfirst( $driver ); - if ( class_exists( $class ) && is_subclass_of( $class, 'DatabaseBase' ) ) { - // Resolve some defaults for b/c - $p['host'] = isset( $p['host'] ) ? $p['host'] : false; - $p['user'] = isset( $p['user'] ) ? $p['user'] : false; - $p['password'] = isset( $p['password'] ) ? $p['password'] : false; - $p['dbname'] = isset( $p['dbname'] ) ? $p['dbname'] : false; - $p['flags'] = isset( $p['flags'] ) ? $p['flags'] : 0; - $p['variables'] = isset( $p['variables'] ) ? $p['variables'] : []; - $p['tablePrefix'] = isset( $p['tablePrefix'] ) ? $p['tablePrefix'] : 'get from global'; - if ( !isset( $p['schema'] ) ) { - $p['schema'] = isset( $defaultSchemas[$dbType] ) ? $defaultSchemas[$dbType] : null; - } - $p['foreign'] = isset( $p['foreign'] ) ? $p['foreign'] : false; - $p['cliMode'] = $wgCommandLineMode; - - return new $class( $p ); - } else { - return null; - } - } - protected function installErrorHandler() { $this->mPHPError = false; $this->htmlErrors = ini_set( 'html_errors', '0' ); @@ -912,7 +934,7 @@ abstract class DatabaseBase implements IDatabase { } if ( $this->debug() ) { - wfDebugLog( 'queries', sprintf( "%s: %s", $this->mDBname, $commentedSql ) ); + $this->queryLogger->debug( "{$this->mDBname} {$commentedSql}" ); } # Avoid fatals if close() was called @@ -929,11 +951,10 @@ abstract class DatabaseBase implements IDatabase { $lastErrno = $this->lastErrno(); # Update state tracking to reflect transaction loss due to disconnection $this->handleTransactionLoss(); - wfDebug( "Connection lost, reconnecting...\n" ); if ( $this->reconnect() ) { - wfDebug( "Reconnected\n" ); $msg = __METHOD__ . ": lost connection to {$this->getServer()}; reconnected"; - wfDebugLog( 'DBPerformance', "$msg:\n" . wfBacktrace( true ) ); + $this->connLogger->warning( $msg ); + $this->queryLogger->warning( "$msg:\n" . wfBacktrace( true ) ); if ( !$recoverable ) { # Callers may catch the exception and continue to use the DB @@ -943,7 +964,8 @@ abstract class DatabaseBase implements IDatabase { $ret = $this->doProfiledQuery( $sql, $commentedSql, $isWrite, $fname ); } } else { - wfDebug( "Failed\n" ); + $msg = __METHOD__ . ": lost connection to {$this->getServer()} permanently"; + $this->connLogger->error( $msg ); } } @@ -1078,7 +1100,7 @@ abstract class DatabaseBase implements IDatabase { public function reportQueryError( $error, $errno, $sql, $fname, $tempIgnore = false ) { if ( $this->ignoreErrors() || $tempIgnore ) { - wfDebug( "SQL ERROR (ignored): $error\n" ); + $this->queryLogger->debug( "SQL ERROR (ignored): $error\n" ); } else { $sql1line = mb_substr( str_replace( "\n", "\\n", $sql ), 0, 5 * 1024 ); wfLogDBError( @@ -1091,7 +1113,7 @@ abstract class DatabaseBase implements IDatabase { 'fname' => $fname, ] ) ); - wfDebug( "SQL ERROR: " . $error . "\n" ); + $this->queryLogger->debug( "SQL ERROR: " . $error . "\n" ); throw new DBQueryError( $this, $error, $errno, $sql, $fname ); } } diff --git a/includes/db/loadbalancer/LBFactory.php b/includes/db/loadbalancer/LBFactory.php index 440954f54f..27bef0a27a 100644 --- a/includes/db/loadbalancer/LBFactory.php +++ b/includes/db/loadbalancer/LBFactory.php @@ -21,9 +21,9 @@ * @ingroup Database */ +use Psr\Log\LoggerInterface; use MediaWiki\MediaWikiServices; use MediaWiki\Services\DestructibleService; -use Psr\Log\LoggerInterface; use MediaWiki\Logger\LoggerFactory; /** @@ -37,6 +37,8 @@ abstract class LBFactory implements DestructibleService { protected $trxProfiler; /** @var LoggerInterface */ protected $trxLogger; + /** @var LoggerInterface */ + protected $replLogger; /** @var BagOStuff */ protected $srvCache; /** @var WANObjectCache */ @@ -80,6 +82,7 @@ abstract class LBFactory implements DestructibleService { $this->wanCache = WANObjectCache::newEmpty(); } $this->trxLogger = LoggerFactory::getInstance( 'DBTransaction' ); + $this->replLogger = LoggerFactory::getInstance( 'DBReplication' ); $this->ticket = mt_rand(); } @@ -645,14 +648,18 @@ abstract class LBFactory implements DestructibleService { /** * Base parameters to LoadBalancer::__construct() + * @return array */ final protected function baseLoadBalancerParams() { return [ + 'localDomain' => wfWikiID(), 'readOnlyReason' => $this->readOnlyReason, - 'trxProfiler' => $this->trxProfiler, 'srvCache' => $this->srvCache, 'wanCache' => $this->wanCache, - 'localDomain' => wfWikiID(), + 'trxProfiler' => $this->trxProfiler, + 'queryLogger' => LoggerFactory::getInstance( 'DBQuery' ), + 'connLogger' => LoggerFactory::getInstance( 'DBConnection' ), + 'replLogger' => LoggerFactory::getInstance( 'DBReplication' ), 'errorLogger' => [ MWExceptionHandler::class, 'logException' ] ]; } diff --git a/includes/db/loadbalancer/LoadBalancer.php b/includes/db/loadbalancer/LoadBalancer.php index a02c75984d..b4898d571c 100644 --- a/includes/db/loadbalancer/LoadBalancer.php +++ b/includes/db/loadbalancer/LoadBalancer.php @@ -1,6 +1,6 @@ mServers = $params['servers']; $this->mWaitTimeout = isset( $params['waitTimeout'] ) @@ -116,7 +124,6 @@ class LoadBalancer { $this->localDomain = isset( $params['localDomain'] ) ? $params['localDomain'] : ''; $this->mReadIndex = -1; - $this->mWriteIndex = -1; $this->mConns = [ 'local' => [], 'foreignUsed' => [], @@ -174,6 +181,10 @@ class LoadBalancer { : function ( Exception $e ) { trigger_error( E_WARNING, $e->getMessage() ); }; + + foreach ( [ 'replLogger', 'connLogger', 'queryLogger', 'perfLogger' ] as $key ) { + $this->$key = isset( $params[$key] ) ? $params[$key] : new \Psr\Log\NullLogger(); + } } /** @@ -185,6 +196,7 @@ class LoadBalancer { if ( !isset( $this->mLoadMonitor ) ) { $class = $this->mLoadMonitorClass; $this->mLoadMonitor = new $class( $this ); + $this->mLoadMonitor->setLogger( $this->replLogger ); } return $this->mLoadMonitor; @@ -211,10 +223,10 @@ class LoadBalancer { $host = $this->getServerName( $i ); if ( $lag === false && !is_infinite( $maxServerLag ) ) { - wfDebugLog( 'replication', "Server $host (#$i) is not replicating?" ); + $this->replLogger->error( "Server $host (#$i) is not replicating?" ); unset( $loads[$i] ); } elseif ( $lag > $maxServerLag ) { - wfDebugLog( 'replication', "Server $host (#$i) has >= $lag seconds of lag" ); + $this->replLogger->warning( "Server $host (#$i) has >= $lag seconds of lag" ); unset( $loads[$i] ); } } @@ -267,7 +279,7 @@ class LoadBalancer { $nonErrorLoads = $this->mGroupLoads[$group]; } else { # No loads for this group, return false and the caller can use some other group - wfDebugLog( 'connect', __METHOD__ . ": no loads for group $group\n" ); + $this->connLogger->info( __METHOD__ . ": no loads for group $group" ); return false; } @@ -308,7 +320,7 @@ class LoadBalancer { } if ( $i === false && count( $currentLoads ) != 0 ) { # All replica DBs lagged. Switch to read-only mode - wfDebugLog( 'replication', "All replica DBs lagged. Switch to read-only mode" ); + $this->replLogger->error( "All replica DBs lagged. Switch to read-only mode" ); $i = ArrayUtils::pickRandom( $currentLoads ); $laggedReplicaMode = true; } @@ -318,17 +330,17 @@ class LoadBalancer { # pickRandom() returned false # This is permanent and means the configuration or the load monitor # wants us to return false. - wfDebugLog( 'connect', __METHOD__ . ": pickRandom() returned false" ); + $this->connLogger->debug( __METHOD__ . ": pickRandom() returned false" ); return false; } $serverName = $this->getServerName( $i ); - wfDebugLog( 'connect', __METHOD__ . ": Using reader #$i: $serverName..." ); + $this->connLogger->debug( __METHOD__ . ": Using reader #$i: $serverName..." ); $conn = $this->openConnection( $i, $wiki ); if ( !$conn ) { - wfDebugLog( 'connect', __METHOD__ . ": Failed connecting to $i/$wiki" ); + $this->connLogger->warning( __METHOD__ . ": Failed connecting to $i/$wiki" ); unset( $nonErrorLoads[$i] ); unset( $currentLoads[$i] ); $i = false; @@ -347,7 +359,7 @@ class LoadBalancer { # If all servers were down, quit now if ( !count( $nonErrorLoads ) ) { - wfDebugLog( 'connect', "All servers down" ); + $this->connLogger->error( "All servers down" ); } if ( $i !== false ) { @@ -364,8 +376,8 @@ class LoadBalancer { } } $serverName = $this->getServerName( $i ); - wfDebugLog( 'connect', __METHOD__ . - ": using server $serverName for group '$group'\n" ); + $this->connLogger->debug( + __METHOD__ . ": using server $serverName for group '$group'\n" ); } return $i; @@ -472,7 +484,7 @@ class LoadBalancer { /** @var DBMasterPos $knownReachedPos */ $knownReachedPos = $this->srvCache->get( $key ); if ( $knownReachedPos && $knownReachedPos->hasReached( $this->mWaitForPos ) ) { - wfDebugLog( 'replication', __METHOD__ . + $this->replLogger->debug( __METHOD__ . ": replica DB $server known to be caught up (pos >= $knownReachedPos).\n" ); return true; } @@ -481,13 +493,13 @@ class LoadBalancer { $conn = $this->getAnyOpenConnection( $index ); if ( !$conn ) { if ( !$open ) { - wfDebugLog( 'replication', __METHOD__ . ": no connection open for $server\n" ); + $this->replLogger->debug( __METHOD__ . ": no connection open for $server\n" ); return false; } else { $conn = $this->openConnection( $index, '' ); if ( !$conn ) { - wfDebugLog( 'replication', __METHOD__ . ": failed to connect to $server\n" ); + $this->replLogger->warning( __METHOD__ . ": failed to connect to $server\n" ); return false; } @@ -497,18 +509,18 @@ class LoadBalancer { } } - wfDebugLog( 'replication', __METHOD__ . ": Waiting for replica DB $server to catch up...\n" ); + $this->replLogger->info( __METHOD__ . ": Waiting for replica DB $server to catch up...\n" ); $timeout = $timeout ?: $this->mWaitTimeout; $result = $conn->masterPosWait( $this->mWaitForPos, $timeout ); if ( $result == -1 || is_null( $result ) ) { // Timed out waiting for replica DB, use master instead $msg = __METHOD__ . ": Timed out waiting on $server pos {$this->mWaitForPos}"; - wfDebugLog( 'replication', "$msg\n" ); - wfDebugLog( 'DBPerformance', "$msg:\n" . wfBacktrace( true ) ); + $this->replLogger->warning( "$msg\n" ); + $this->perfLogger->warning( "$msg:\n" . wfBacktrace( true ) ); $ok = false; } else { - wfDebugLog( 'replication', __METHOD__ . ": Done\n" ); + $this->replLogger->info( __METHOD__ . ": Done\n" ); $ok = true; // Remember that the DB reached this point $this->srvCache->set( $key, $this->mWaitForPos, BagOStuff::TTL_DAY ); @@ -703,10 +715,10 @@ class LoadBalancer { $conn = $this->reallyOpenConnection( $server, false ); $serverName = $this->getServerName( $i ); if ( $conn->isOpen() ) { - wfDebugLog( 'connect', "Connected to database $i at $serverName\n" ); + $this->connLogger->debug( "Connected to database $i at '$serverName'." ); $this->mConns['local'][$i][0] = $conn; } else { - wfDebugLog( 'connect', "Failed to connect to database $i at $serverName\n" ); + $this->connLogger->warning( "Failed to connect to database $i at '$serverName'." ); $this->mErrorConnection = $conn; $conn = false; } @@ -847,12 +859,16 @@ class LoadBalancer { // Log when many connection are made on requests if ( ++$this->connsOpened >= self::CONN_HELD_WARN_THRESHOLD ) { - wfDebugLog( 'DBPerformance', __METHOD__ . ": " . + $this->perfLogger->warning( __METHOD__ . ": " . "{$this->connsOpened}+ connections made (master=$masterName)\n" . wfBacktrace( true ) ); } - # Create object + // Set loggers + $server['connLogger'] = $this->connLogger; + $server['queryLogger'] = $this->queryLogger; + + // Create a live connection object try { $db = DatabaseBase::factory( $server['type'], $server ); } catch ( DBConnectionError $e ) { @@ -1670,11 +1686,11 @@ class LoadBalancer { * * @param IDatabase $conn Replica DB * @param DBMasterPos|bool $pos Master position; default: current position - * @param integer|null $timeout Timeout in seconds [optional] + * @param integer $timeout Timeout in seconds * @return bool Success * @since 1.27 */ - public function safeWaitForMasterPos( IDatabase $conn, $pos = false, $timeout = null ) { + public function safeWaitForMasterPos( IDatabase $conn, $pos = false, $timeout = 10 ) { if ( $this->getServerCount() == 1 || !$conn->getLBInfo( 'replica' ) ) { return true; // server is not a replica DB } @@ -1684,15 +1700,14 @@ class LoadBalancer { return false; // something is misconfigured } - $timeout = $timeout ?: $this->mWaitTimeout; $result = $conn->masterPosWait( $pos, $timeout ); if ( $result == -1 || is_null( $result ) ) { $msg = __METHOD__ . ": Timed out waiting on {$conn->getServer()} pos {$pos}"; - wfDebugLog( 'replication', "$msg\n" ); - wfDebugLog( 'DBPerformance', "$msg:\n" . wfBacktrace( true ) ); + $this->replLogger->warning( "$msg\n" ); + $this->perfLogger->warning( "$msg:\n" . wfBacktrace( true ) ); $ok = false; } else { - wfDebugLog( 'replication', __METHOD__ . ": Done\n" ); + $this->replLogger->info( __METHOD__ . ": Done\n" ); $ok = true; } diff --git a/includes/db/loadbalancer/LoadMonitor.php b/includes/db/loadbalancer/LoadMonitor.php index e68cf1a518..247955a8f0 100644 --- a/includes/db/loadbalancer/LoadMonitor.php +++ b/includes/db/loadbalancer/LoadMonitor.php @@ -20,19 +20,21 @@ * @file * @ingroup Database */ +use Psr\Log\LoggerAwareInterface; +use Psr\Log\LoggerInterface; /** * An interface for database load monitoring * * @ingroup Database */ -interface LoadMonitor { +interface LoadMonitor extends LoggerAwareInterface { /** * Construct a new LoadMonitor with a given LoadBalancer parent * * @param LoadBalancer $parent */ - public function __construct( $parent ); + public function __construct( LoadBalancer $parent ); /** * Perform pre-connection load ratio adjustment. @@ -62,7 +64,10 @@ interface LoadMonitor { } class LoadMonitorNull implements LoadMonitor { - public function __construct( $parent ) { + public function __construct( LoadBalancer $parent ) { + } + + public function setLogger( LoggerInterface $logger ) { } public function scaleLoads( &$loads, $group = false, $wiki = false ) { diff --git a/includes/db/loadbalancer/LoadMonitorMySQL.php b/includes/db/loadbalancer/LoadMonitorMySQL.php index 444c4b4ed6..7238388944 100644 --- a/includes/db/loadbalancer/LoadMonitorMySQL.php +++ b/includes/db/loadbalancer/LoadMonitorMySQL.php @@ -19,6 +19,8 @@ * @ingroup Database */ +use Psr\Log\LoggerInterface; + /** * Basic MySQL load monitor with no external dependencies * Uses memcached to cache the replication lag for a short time @@ -32,12 +34,18 @@ class LoadMonitorMySQL implements LoadMonitor { protected $srvCache; /** @var BagOStuff */ protected $mainCache; + /** @var LoggerInterface */ + protected $replLogger; - public function __construct( $parent ) { + public function __construct( LoadBalancer $parent ) { $this->parent = $parent; - $this->srvCache = ObjectCache::getLocalServerInstance( 'hash' ); $this->mainCache = ObjectCache::getLocalClusterInstance(); + $this->replLogger = new \Psr\Log\NullLogger(); + } + + public function setLogger( LoggerInterface $logger ) { + $this->replLogger = $logger; } public function scaleLoads( &$loads, $group = false, $wiki = false ) { @@ -58,7 +66,7 @@ class LoadMonitorMySQL implements LoadMonitor { # (a) Check the local APC cache $value = $this->srvCache->get( $key ); if ( $value && $value['timestamp'] > ( microtime( true ) - $ttl ) ) { - wfDebugLog( 'replication', __METHOD__ . ": got lag times ($key) from local cache" ); + $this->replLogger->debug( __METHOD__ . ": got lag times ($key) from local cache" ); return $value['lagTimes']; // cache hit } $staleValue = $value ?: false; @@ -67,7 +75,7 @@ class LoadMonitorMySQL implements LoadMonitor { $value = $this->mainCache->get( $key ); if ( $value && $value['timestamp'] > ( microtime( true ) - $ttl ) ) { $this->srvCache->set( $key, $value, $staleTTL ); - wfDebugLog( 'replication', __METHOD__ . ": got lag times ($key) from main cache" ); + $this->replLogger->debug( __METHOD__ . ": got lag times ($key) from main cache" ); return $value['lagTimes']; // cache hit } @@ -104,14 +112,14 @@ class LoadMonitorMySQL implements LoadMonitor { if ( !$conn ) { $lagTimes[$i] = false; $host = $this->parent->getServerName( $i ); - wfDebugLog( 'replication', __METHOD__ . ": host $host (#$i) is unreachable" ); + $this->replLogger->error( __METHOD__ . ": host $host (#$i) is unreachable" ); continue; } $lagTimes[$i] = $conn->getLag(); if ( $lagTimes[$i] === false ) { $host = $this->parent->getServerName( $i ); - wfDebugLog( 'replication', __METHOD__ . ": host $host (#$i) is not replicating?" ); + $this->replLogger->error( __METHOD__ . ": host $host (#$i) is not replicating?" ); } if ( $close ) { @@ -127,7 +135,7 @@ class LoadMonitorMySQL implements LoadMonitor { $value = [ 'lagTimes' => $lagTimes, 'timestamp' => microtime( true ) ]; $this->mainCache->set( $key, $value, $staleTTL ); $this->srvCache->set( $key, $value, $staleTTL ); - wfDebugLog( 'replication', __METHOD__ . ": re-calculated lag times ($key)" ); + $this->replLogger->info( __METHOD__ . ": re-calculated lag times ($key)" ); return $value['lagTimes']; } -- 2.20.1