More DB related class cleanups to prepare files for /libs
authorAaron Schulz <aschulz@wikimedia.org>
Wed, 14 Sep 2016 07:22:35 +0000 (00:22 -0700)
committerAaron Schulz <aschulz@wikimedia.org>
Thu, 15 Sep 2016 00:07:55 +0000 (00:07 +0000)
* Cleaned up some related logging bits.
* Avoid some wf* methods in LoadBalancer.

Change-Id: I5da97174441c086e61ffc120889c068e241ebfd2

includes/db/ChronologyProtector.php
includes/db/loadbalancer/LBFactory.php
includes/db/loadbalancer/LoadBalancer.php
includes/libs/rdbms/loadbalancer/ILoadBalancer.php
includes/libs/rdbms/loadmonitor/LoadMonitor.php
includes/libs/rdbms/loadmonitor/LoadMonitorMySQL.php
includes/libs/rdbms/loadmonitor/LoadMonitorNull.php

index 4d03bc6..09b820b 100644 (file)
@@ -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 );
                        }
index 5115fbe..9eda742 100644 (file)
@@ -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()
                ];
        }
 
index 8069cf6..841231b 100644 (file)
@@ -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;
                }
 
index 69c6272..0f6bea3 100644 (file)
@@ -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 );
index 46af068..460746b 100644 (file)
@@ -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.
index 83f4462..02babfe 100644 (file)
@@ -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();
        }
 
index df95b0a..a5fc85d 100644 (file)
 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 ) {