From b055fbda7e39d03d03ac6ae42fd8825114b2c583 Mon Sep 17 00:00:00 2001 From: Aaron Schulz Date: Wed, 14 Sep 2016 00:22:35 -0700 Subject: [PATCH] More DB related class cleanups to prepare files for /libs * Cleaned up some related logging bits. * Avoid some wf* methods in LoadBalancer. Change-Id: I5da97174441c086e61ffc120889c068e241ebfd2 --- includes/db/ChronologyProtector.php | 5 +- includes/db/loadbalancer/LBFactory.php | 8 ++- includes/db/loadbalancer/LoadBalancer.php | 58 +++++++++++-------- .../libs/rdbms/loadbalancer/ILoadBalancer.php | 4 +- .../libs/rdbms/loadmonitor/LoadMonitor.php | 8 +-- .../rdbms/loadmonitor/LoadMonitorMySQL.php | 8 +-- .../rdbms/loadmonitor/LoadMonitorNull.php | 4 +- 7 files changed, 55 insertions(+), 40 deletions(-) diff --git a/includes/db/ChronologyProtector.php b/includes/db/ChronologyProtector.php index 4d03bc6057..09b820ba2b 100644 --- a/includes/db/ChronologyProtector.php +++ b/includes/db/ChronologyProtector.php @@ -72,7 +72,7 @@ class ChronologyProtector implements LoggerAwareInterface{ $this->clientId = md5( $client['ip'] . "\n" . $client['agent'] ); $this->key = $store->makeGlobalKey( __CLASS__, $this->clientId ); $this->waitForPosTime = $posTime; - $this->logger = LoggerFactory::getInstance( 'DBReplication' ); + $this->logger = new \Psr\Log\NullLogger(); } public function setLogger( LoggerInterface $logger ) { @@ -265,10 +265,11 @@ class ChronologyProtector implements LoggerAwareInterface{ if ( $result == $loop::CONDITION_REACHED ) { $msg = "expected and found pos time {$this->waitForPosTime} ({$waitedMs}ms)"; + $this->logger->debug( $msg ); } else { $msg = "expected but missed pos time {$this->waitForPosTime} ({$waitedMs}ms)"; + $this->logger->info( $msg ); } - wfDebugLog( 'replication', $msg ); } else { $data = $this->store->get( $this->key ); } diff --git a/includes/db/loadbalancer/LBFactory.php b/includes/db/loadbalancer/LBFactory.php index 5115fbecae..9eda74208d 100644 --- a/includes/db/loadbalancer/LBFactory.php +++ b/includes/db/loadbalancer/LBFactory.php @@ -68,8 +68,6 @@ abstract class LBFactory implements DestructibleService { if ( isset( $conf['readOnlyReason'] ) && is_string( $conf['readOnlyReason'] ) ) { $this->readOnlyReason = $conf['readOnlyReason']; } - $this->chronProt = $this->newChronologyProtector(); - $this->trxProfiler = Profiler::instance()->getTransactionProfiler(); // Use APC/memcached style caching, but avoids loops with CACHE_DB (T141804) $sCache = ObjectCache::getLocalServerInstance(); if ( $sCache->getQoS( $sCache::ATTR_EMULATION ) > $sCache::QOS_EMULATION_SQL ) { @@ -89,8 +87,10 @@ abstract class LBFactory implements DestructibleService { } else { $this->wanCache = WANObjectCache::newEmpty(); } + $this->trxProfiler = Profiler::instance()->getTransactionProfiler(); $this->trxLogger = LoggerFactory::getInstance( 'DBTransaction' ); $this->replLogger = LoggerFactory::getInstance( 'DBReplication' ); + $this->chronProt = $this->newChronologyProtector(); $this->ticket = mt_rand(); } @@ -610,6 +610,7 @@ abstract class LBFactory implements DestructibleService { ], $request->getFloat( 'cpPosTime', $request->getCookie( 'cpPosTime', '' ) ) ); + $chronProt->setLogger( $this->replLogger ); if ( PHP_SAPI === 'cli' ) { $chronProt->setEnabled( false ); } elseif ( $request->getHeader( 'ChronologyProtection' ) === 'false' ) { @@ -669,7 +670,8 @@ abstract class LBFactory implements DestructibleService { 'queryLogger' => LoggerFactory::getInstance( 'DBQuery' ), 'connLogger' => LoggerFactory::getInstance( 'DBConnection' ), 'replLogger' => LoggerFactory::getInstance( 'DBReplication' ), - 'errorLogger' => [ MWExceptionHandler::class, 'logException' ] + 'errorLogger' => [ MWExceptionHandler::class, 'logException' ], + 'hostname' => wfHostname() ]; } diff --git a/includes/db/loadbalancer/LoadBalancer.php b/includes/db/loadbalancer/LoadBalancer.php index 8069cf6fc7..841231b33c 100644 --- a/includes/db/loadbalancer/LoadBalancer.php +++ b/includes/db/loadbalancer/LoadBalancer.php @@ -84,6 +84,9 @@ class LoadBalancer implements ILoadBalancer { private $trxRecurringCallbacks = []; /** @var string Local Wiki ID and default for selectDB() calls */ private $localDomain; + /** @var string Current server name */ + private $host; + /** @var callable Exception logger */ private $errorLogger; @@ -176,6 +179,10 @@ class LoadBalancer implements ILoadBalancer { foreach ( [ 'replLogger', 'connLogger', 'queryLogger', 'perfLogger' ] as $key ) { $this->$key = isset( $params[$key] ) ? $params[$key] : new \Psr\Log\NullLogger(); } + + $this->host = isset( $params['hostname'] ) + ? $params['hostname'] + : ( gethostname() ?: 'unknown' ); } /** @@ -357,7 +364,7 @@ class LoadBalancer implements ILoadBalancer { } $serverName = $this->getServerName( $i ); $this->connLogger->debug( - __METHOD__ . ": using server $serverName for group '$group'\n" ); + __METHOD__ . ": using server $serverName for group '$group'" ); } return $i; @@ -446,7 +453,7 @@ class LoadBalancer implements ILoadBalancer { $knownReachedPos = $this->srvCache->get( $key ); if ( $knownReachedPos && $knownReachedPos->hasReached( $this->mWaitForPos ) ) { $this->replLogger->debug( __METHOD__ . - ": replica DB $server known to be caught up (pos >= $knownReachedPos).\n" ); + ": replica DB $server known to be caught up (pos >= $knownReachedPos)." ); return true; } @@ -454,13 +461,13 @@ class LoadBalancer implements ILoadBalancer { $conn = $this->getAnyOpenConnection( $index ); if ( !$conn ) { if ( !$open ) { - $this->replLogger->debug( __METHOD__ . ": no connection open for $server\n" ); + $this->replLogger->debug( __METHOD__ . ": no connection open for $server" ); return false; } else { $conn = $this->openConnection( $index, '' ); if ( !$conn ) { - $this->replLogger->warning( __METHOD__ . ": failed to connect to $server\n" ); + $this->replLogger->warning( __METHOD__ . ": failed to connect to $server" ); return false; } @@ -470,18 +477,17 @@ class LoadBalancer implements ILoadBalancer { } } - $this->replLogger->info( __METHOD__ . ": Waiting for replica DB $server to catch up...\n" ); + $this->replLogger->info( __METHOD__ . ": Waiting for replica DB $server to catch up..." ); $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}"; - $this->replLogger->warning( "$msg\n" ); - $this->perfLogger->warning( "$msg:\n" . wfBacktrace( true ) ); + $this->replLogger->warning( "$msg" ); $ok = false; } else { - $this->replLogger->info( __METHOD__ . ": Done\n" ); + $this->replLogger->info( __METHOD__ . ": Done" ); $ok = true; // Remember that the DB reached this point $this->srvCache->set( $key, $this->mWaitForPos, BagOStuff::TTL_DAY ); @@ -592,9 +598,10 @@ class LoadBalancer implements ILoadBalancer { if ( $refCount <= 0 ) { $this->mConns['foreignFree'][$serverIndex][$wiki] = $conn; unset( $this->mConns['foreignUsed'][$serverIndex][$wiki] ); - wfDebug( __METHOD__ . ": freed connection $serverIndex/$wiki\n" ); + $this->connLogger->debug( __METHOD__ . ": freed connection $serverIndex/$wiki" ); } else { - wfDebug( __METHOD__ . ": reference count for $serverIndex/$wiki reduced to $refCount\n" ); + $this->connLogger->debug( __METHOD__ . + ": reference count for $serverIndex/$wiki reduced to $refCount" ); } } @@ -692,13 +699,13 @@ class LoadBalancer implements ILoadBalancer { if ( isset( $this->mConns['foreignUsed'][$i][$wiki] ) ) { // Reuse an already-used connection $conn = $this->mConns['foreignUsed'][$i][$wiki]; - wfDebug( __METHOD__ . ": reusing connection $i/$wiki\n" ); + $this->connLogger->debug( __METHOD__ . ": reusing connection $i/$wiki" ); } elseif ( isset( $this->mConns['foreignFree'][$i][$wiki] ) ) { // Reuse a free connection for the same wiki $conn = $this->mConns['foreignFree'][$i][$wiki]; unset( $this->mConns['foreignFree'][$i][$wiki] ); $this->mConns['foreignUsed'][$i][$wiki] = $conn; - wfDebug( __METHOD__ . ": reusing free connection $i/$wiki\n" ); + $this->connLogger->debug( __METHOD__ . ": reusing free connection $i/$wiki" ); } elseif ( !empty( $this->mConns['foreignFree'][$i] ) ) { // Reuse a connection from another wiki $conn = reset( $this->mConns['foreignFree'][$i] ); @@ -708,14 +715,15 @@ class LoadBalancer implements ILoadBalancer { // DatabaseMysqlBase::open() already handle this on connection. if ( $dbName !== '' && !$conn->selectDB( $dbName ) ) { $this->mLastError = "Error selecting database $dbName on server " . - $conn->getServer() . " from client host " . wfHostname() . "\n"; + $conn->getServer() . " from client host {$this->host}"; $this->mErrorConnection = $conn; $conn = false; } else { $conn->tablePrefix( $prefix ); unset( $this->mConns['foreignFree'][$i][$oldWiki] ); $this->mConns['foreignUsed'][$i][$wiki] = $conn; - wfDebug( __METHOD__ . ": reusing free connection from $oldWiki for $wiki\n" ); + $this->connLogger->debug( __METHOD__ . + ": reusing free connection from $oldWiki for $wiki" ); } } else { // Open a new connection @@ -725,13 +733,13 @@ class LoadBalancer implements ILoadBalancer { $server['foreign'] = true; $conn = $this->reallyOpenConnection( $server, $dbName ); if ( !$conn->isOpen() ) { - wfDebug( __METHOD__ . ": error opening connection for $i/$wiki\n" ); + $this->connLogger->warning( __METHOD__ . ": connection error for $i/$wiki" ); $this->mErrorConnection = $conn; $conn = false; } else { $conn->tablePrefix( $prefix ); $this->mConns['foreignUsed'][$i][$wiki] = $conn; - wfDebug( __METHOD__ . ": opened new connection for $i/$wiki\n" ); + $this->connLogger->debug( __METHOD__ . ": opened new connection for $i/$wiki" ); } } @@ -766,8 +774,9 @@ class LoadBalancer implements ILoadBalancer { * * @param array $server * @param bool $dbNameOverride - * @throws MWException * @return DatabaseBase + * @throws DBAccessError + * @throws MWException */ protected function reallyOpenConnection( $server, $dbNameOverride = false ) { if ( $this->disabled ) { @@ -790,8 +799,7 @@ class LoadBalancer implements ILoadBalancer { // Log when many connection are made on requests if ( ++$this->connsOpened >= self::CONN_HELD_WARN_THRESHOLD ) { $this->perfLogger->warning( __METHOD__ . ": " . - "{$this->connsOpened}+ connections made (master=$masterName)\n" . - wfBacktrace( true ) ); + "{$this->connsOpened}+ connections made (master=$masterName)" ); } // Set loggers @@ -838,7 +846,7 @@ class LoadBalancer implements ILoadBalancer { if ( !is_object( $conn ) ) { // No last connection, probably due to all servers being too busy - wfLogDBError( + $this->connLogger->error( "LB failure with no last connection. Connection error: {last_error}", $context ); @@ -847,7 +855,7 @@ class LoadBalancer implements ILoadBalancer { throw new DBConnectionError( null, $this->mLastError ); } else { $context['db_server'] = $conn->getProperty( 'mServer' ); - wfLogDBError( + $this->connLogger->warning( "Connection error: {last_error} ({db_server})", $context ); @@ -1028,6 +1036,7 @@ class LoadBalancer implements ILoadBalancer { if ( $limit > 0 && $time > $limit ) { throw new DBTransactionError( $conn, + "Transaction spent $time second(s) in writes, exceeding the $limit limit.", wfMessage( 'transaction-duration-limit-exceeded', $time, $limit )->text() ); } @@ -1132,7 +1141,7 @@ class LoadBalancer implements ILoadBalancer { // This happens if onTransactionIdle() callbacks leave callbacks on *another* DB // (which finished its callbacks already). Warn and recover in this case. Let the // callbacks run in the final commitMasterChanges() in LBFactory::shutdown(). - wfWarn( __METHOD__ . ": did not expect writes/callbacks pending." ); + $this->queryLogger->error( __METHOD__ . ": found writes/callbacks pending." ); return; } elseif ( $conn->trxLevel() ) { // This happens for single-DB setups where DB_REPLICA uses the master DB, @@ -1518,11 +1527,10 @@ class LoadBalancer implements ILoadBalancer { $result = $conn->masterPosWait( $pos, $timeout ); if ( $result == -1 || is_null( $result ) ) { $msg = __METHOD__ . ": Timed out waiting on {$conn->getServer()} pos {$pos}"; - $this->replLogger->warning( "$msg\n" ); - $this->perfLogger->warning( "$msg:\n" . wfBacktrace( true ) ); + $this->replLogger->warning( "$msg" ); $ok = false; } else { - $this->replLogger->info( __METHOD__ . ": Done\n" ); + $this->replLogger->info( __METHOD__ . ": Done" ); $ok = true; } diff --git a/includes/libs/rdbms/loadbalancer/ILoadBalancer.php b/includes/libs/rdbms/loadbalancer/ILoadBalancer.php index 69c62725f8..0f6bea3f93 100644 --- a/includes/libs/rdbms/loadbalancer/ILoadBalancer.php +++ b/includes/libs/rdbms/loadbalancer/ILoadBalancer.php @@ -35,8 +35,10 @@ interface ILoadBalancer { * - loadMonitor : Name of a class used to fetch server lag and load. * - readOnlyReason : Reason the master DB is read-only if so [optional] * - waitTimeout : Maximum time to wait for replicas for consistency [optional] - * - srvCache : BagOStuff object [optional] + * - srvCache : BagOStuff object for server cache [optional] + * - memCache : BagOStuff object for cluster memory cache [optional] * - wanCache : WANObjectCache object [optional] + * - hostname : the name of the current server [optional] * @throws InvalidArgumentException */ public function __construct( array $params ); diff --git a/includes/libs/rdbms/loadmonitor/LoadMonitor.php b/includes/libs/rdbms/loadmonitor/LoadMonitor.php index 46af068bab..460746baa5 100644 --- a/includes/libs/rdbms/loadmonitor/LoadMonitor.php +++ b/includes/libs/rdbms/loadmonitor/LoadMonitor.php @@ -31,11 +31,11 @@ interface LoadMonitor extends LoggerAwareInterface { /** * Construct a new LoadMonitor with a given LoadBalancer parent * - * @param BagOStuff $sCache Server local memory cache - * @param BagOStuff $cCache Server local memory cache - * @param ILoadBalancer $parent LoadBalancer this instance serves + * @param ILoadBalancer $lb LoadBalancer this instance serves + * @param BagOStuff $sCache Local server memory cache + * @param BagOStuff $cCache Local cluster memory cache */ - public function __construct( ILoadBalancer $parent, BagOStuff $sCache, BagOStuff $cCache ); + public function __construct( ILoadBalancer $lb, BagOStuff $sCache, BagOStuff $cCache ); /** * Perform pre-connection load ratio adjustment. diff --git a/includes/libs/rdbms/loadmonitor/LoadMonitorMySQL.php b/includes/libs/rdbms/loadmonitor/LoadMonitorMySQL.php index 83f4462287..02babfe677 100644 --- a/includes/libs/rdbms/loadmonitor/LoadMonitorMySQL.php +++ b/includes/libs/rdbms/loadmonitor/LoadMonitorMySQL.php @@ -37,10 +37,10 @@ class LoadMonitorMySQL implements LoadMonitor { /** @var LoggerInterface */ protected $replLogger; - public function __construct( ILoadBalancer $parent, BagOStuff $sCache, BagOStuff $cCache ) { - $this->parent = $parent; - $this->srvCache = $sCache; - $this->mainCache = $cCache; + public function __construct( ILoadBalancer $lb, BagOStuff $srvCache, BagOStuff $cache ) { + $this->parent = $lb; + $this->srvCache = $srvCache; + $this->mainCache = $cache; $this->replLogger = new \Psr\Log\NullLogger(); } diff --git a/includes/libs/rdbms/loadmonitor/LoadMonitorNull.php b/includes/libs/rdbms/loadmonitor/LoadMonitorNull.php index df95b0a4e2..a5fc85d107 100644 --- a/includes/libs/rdbms/loadmonitor/LoadMonitorNull.php +++ b/includes/libs/rdbms/loadmonitor/LoadMonitorNull.php @@ -21,13 +21,15 @@ use Psr\Log\LoggerInterface; class LoadMonitorNull implements LoadMonitor { - public function __construct( ILoadBalancer $parent, BagOStuff $sCache, BagOStuff $cCache ) { + public function __construct( ILoadBalancer $lb, BagOStuff $sCache, BagOStuff $cCache ) { + } public function setLogger( LoggerInterface $logger ) { } public function scaleLoads( &$loads, $group = false, $wiki = false ) { + } public function getLagTimes( $serverIndexes, $wiki ) { -- 2.20.1