SERVER-10007 better logging for dbclient_rs.cpp

3 files changed, 136 insertions, 20 deletions

diff --git a/jstests/sharding/read_pref_cmd.js b/jstests/sharding/read_pref_cmd.js
index 320cd035031..d5c30499379 100644
--- a/jstests/sharding/read_pref_cmd.js
+++ b/jstests/sharding/read_pref_cmd.js
@@ -265,7 +265,8 @@ var testAllModes = function(conn, hostList, isMongos) {
     });
 };
 
-var st = new ShardingTest({ shards: { rs0: { nodes: NODE_COUNT }}});
+var st = new ShardingTest({shards : {rs0 : {nodes : NODE_COUNT, verbose : 1}},
+                           other : {mongosOptions : {verbose : 3}}});
 st.stopBalancer();
 
 ReplSetTest.awaitRSClientHosts(st.s, st.rs0.nodes);
diff --git a/src/mongo/client/dbclient_rs.cpp b/src/mongo/client/dbclient_rs.cpp
index 50d00b65103..eac4063e537 100644
--- a/src/mongo/client/dbclient_rs.cpp
+++ b/src/mongo/client/dbclient_rs.cpp
@@ -223,6 +223,10 @@ namespace mongo {
             }
 
             if (secOnly && !node.okForSecondaryQueries()) {
+                LOG(3) << "dbclient_rs not selecting " << node
+                                  << ", not ok for secondary queries ("
+                                  << ( !node.secondary ? "not secondary" : "hidden" ) << ")"
+                                  << endl;
                 continue;
             }
 
@@ -233,8 +237,8 @@ namespace mongo {
 
                 if (node.isLocalSecondary(localThresholdMillis)) {
                     // found a local node.  return early.
-                    LOG(2) << "dbclient_rs _selectNode found local secondary for queries: "
-                           << nextNodeIndex << ", ping time: " << node.pingTimeMillis << endl;
+                    LOG(2) << "dbclient_rs selecting local secondary " << fallbackHost
+                                      << ", ping time: " << node.pingTimeMillis << endl;
                     *lastHost = fallbackHost;
                     return fallbackHost;
                 }
@@ -245,6 +249,14 @@ namespace mongo {
             *lastHost = fallbackHost;
         }
 
+        if ( fallbackHost.empty() ) {
+            LOG(3) << "dbclient_rs no node selected for tag " << readPreferenceTag << endl;
+        }
+        else {
+            LOG(3) << "dbclient_rs node " << fallbackHost << " selected for tag "
+                              << readPreferenceTag << endl;
+        }
+
         return fallbackHost;
     }
 
@@ -1192,6 +1204,10 @@ namespace mongo {
         }
 
         if (candidate.empty()) {
+
+            LOG( 3 ) << "dbclient_rs no compatible nodes found, refreshing view of replica set "
+                                << _name << endl;
+
             // mimic checkMaster behavior, which refreshes the local view of the replica set
             _check(false);
 
@@ -1650,9 +1666,21 @@ namespace mongo {
                                                        const BSONObj *fieldsToReturn,
                                                        int queryOptions,
                                                        int batchSize) {
-        if (_isQueryOkToSecondary(ns, queryOptions, query.obj)) {
+
+        if ( _isQueryOkToSecondary( ns, queryOptions, query.obj ) ) {
+
             shared_ptr<ReadPreferenceSetting> readPref(_extractReadPref(query.obj));
 
+            LOG( 3 ) << "dbclient_rs query using secondary or tagged node selection in "
+                                << _getMonitor()->getName() << ", read pref is "
+                                << readPref->toBSON() << " (primary : "
+                                << ( _master.get() != NULL ?
+                                        _master->getServerAddress() : "[not cached]" )
+                                << ", lastTagged : "
+                                << ( _lastSlaveOkConn.get() != NULL ?
+                                        _lastSlaveOkConn->getServerAddress() : "[not cached]" )
+                                << ")" << endl;
+
             for (size_t retry = 0; retry < MAX_RETRY; retry++) {
                 try {
                     DBClientConnection* conn = selectNodeUsingTags(readPref);
@@ -1668,16 +1696,19 @@ namespace mongo {
                     return checkSlaveQueryResult(cursor);
                 }
                 catch (const DBException &dbExcep) {
-                    LOG(1) << "can't query replica set slave " << _lastSlaveOkHost
+                    LOG(1) << "can't query replica set node " << _lastSlaveOkHost
                            << ": " << causedBy(dbExcep) << endl;
                     invalidateLastSlaveOkCache();
                 }
             }
 
-            uasserted(16370, str::stream() << "Failed to do query, no good nodes in "
-                        << _getMonitor()->getName());
+            uasserted( 16370,
+                       str::stream() << "Failed to do query, no good nodes in "
+                               << _getMonitor()->getName() );
         }
 
+        LOG( 3 ) << "dbclient_rs query to primary node in " << _getMonitor()->getName() << endl;
+
         return checkMaster()->query(ns, query, nToReturn, nToSkip, fieldsToReturn,
                 queryOptions, batchSize);
     }
@@ -1687,8 +1718,19 @@ namespace mongo {
                                         const BSONObj *fieldsToReturn,
                                         int queryOptions) {
         if (_isQueryOkToSecondary(ns, queryOptions, query.obj)) {
+
             shared_ptr<ReadPreferenceSetting> readPref(_extractReadPref(query.obj));
 
+            LOG( 3 ) << "dbclient_rs findOne using secondary or tagged node selection in "
+                                << _getMonitor()->getName() << ", read pref is "
+                                << readPref->toBSON() << " (primary : "
+                                << ( _master.get() != NULL ?
+                                        _master->getServerAddress() : "[not cached]" )
+                                << ", lastTagged : "
+                                << ( _lastSlaveOkConn.get() != NULL ?
+                                        _lastSlaveOkConn->getServerAddress() : "[not cached]" )
+                                << ")" << endl;
+
             for (size_t retry = 0; retry < MAX_RETRY; retry++) {
                 try {
                     DBClientConnection* conn = selectNodeUsingTags(readPref);
@@ -1699,9 +1741,9 @@ namespace mongo {
 
                     return conn->findOne(ns,query,fieldsToReturn,queryOptions);
                 }
-                catch (const DBException &dbExcep) {
-                    LOG(1) << "can't findone replica set slave " << _lastSlaveOkHost
-                           << ": " << causedBy(dbExcep) << endl;
+                catch ( const DBException &dbExcep ) {
+                    LOG(1) << "can't findone replica set node " << _lastSlaveOkHost << ": "
+                                      << causedBy( dbExcep ) << endl;
                     invalidateLastSlaveOkCache();
                 }
             }
@@ -1710,6 +1752,9 @@ namespace mongo {
                         << _getMonitor()->getName());
         }
 
+        LOG( 3 ) << "dbclient_rs findOne to primary node in " << _getMonitor()->getName()
+                            << endl;
+
         return checkMaster()->findOne(ns,query,fieldsToReturn,queryOptions);
     }
 
@@ -1762,6 +1807,10 @@ namespace mongo {
     DBClientConnection* DBClientReplicaSet::selectNodeUsingTags(
             shared_ptr<ReadPreferenceSetting> readPref) {
         if (checkLastHost(readPref.get())) {
+
+            LOG( 3 ) << "dbclient_rs selecting compatible last used node " << _lastSlaveOkHost
+                                << endl;
+
             return _lastSlaveOkConn.get();
         }
 
@@ -1771,6 +1820,9 @@ namespace mongo {
                 &isPrimarySelected);
 
         if ( _lastSlaveOkHost.empty() ){
+
+            LOG( 3 ) << "dbclient_rs no compatible node found" << endl;
+
             return NULL;
         }
 
@@ -1784,6 +1836,9 @@ namespace mongo {
             checkMaster();
             _lastSlaveOkConn = _master;
             _lastSlaveOkHost = _masterHost; // implied, but still assign just to be safe
+
+            LOG( 3 ) << "dbclient_rs selecting primary node " << _lastSlaveOkHost << endl;
+
             return _master.get();
         }
 
@@ -1797,14 +1852,16 @@ namespace mongo {
 
         // Assert here instead of returning NULL since the contract of this method is such
         // that returning NULL means none of the nodes were good, which is not the case here.
-        uassert(16532, str::stream() << "Failed to connect to "
-                << _lastSlaveOkHost.toString(true),
+        uassert(16532, str::stream() << "Failed to connect to " << _lastSlaveOkHost,
                 newConn != NULL);
 
         _lastSlaveOkConn.reset(newConn);
         _lastSlaveOkConn->setReplSetClientCallback(this);
 
         _auth(_lastSlaveOkConn.get());
+
+        LOG( 3 ) << "dbclient_rs selecting node " << _lastSlaveOkHost << endl;
+
         return _lastSlaveOkConn.get();
     }
 
@@ -1823,8 +1880,19 @@ namespace mongo {
 
             const bool slaveOk = qm.queryOptions & QueryOption_SlaveOk;
             if (_isQueryOkToSecondary(qm.ns, qm.queryOptions, qm.query)) {
+
                 shared_ptr<ReadPreferenceSetting> readPref(_extractReadPref(qm.query));
 
+                LOG( 3 ) << "dbclient_rs say using secondary or tagged node selection in "
+                                    << _getMonitor()->getName() << ", read pref is "
+                                    << readPref->toBSON() << " (primary : "
+                                    << ( _master.get() != NULL ?
+                                            _master->getServerAddress() : "[not cached]" )
+                                    << ", lastTagged : "
+                                    << ( _lastSlaveOkConn.get() != NULL ?
+                                            _lastSlaveOkConn->getServerAddress() : "[not cached]" )
+                                    << ")" << endl;
+
                 for (size_t retry = 0; retry < MAX_RETRY; retry++) {
                     _lazyState._retries = retry;
                     try {
@@ -1844,9 +1912,9 @@ namespace mongo {
                         _lazyState._slaveOk = slaveOk;
                         _lazyState._lastClient = conn;
                     }
-                    catch (const DBException& DBExcep) {
-                        LOG(1) << "can't callLazy replica set slave " << _lastSlaveOkHost
-                                << ": " << causedBy(DBExcep) << endl;
+                    catch ( const DBException& DBExcep ) {
+                        LOG(1) << "can't callLazy replica set node " << _lastSlaveOkHost << ": "
+                                          << causedBy( DBExcep ) << endl;
                         invalidateLastSlaveOkCache();
                         continue;
                     }
@@ -1859,6 +1927,9 @@ namespace mongo {
             }
         }
 
+        LOG( 3 ) << "dbclient_rs say to primary node in " << _getMonitor()->getName()
+                            << endl;
+
         DBClientConnection* master = checkMaster();
         if (actualServer)
             *actualServer = master->getServerAddress();
@@ -1965,8 +2036,19 @@ namespace mongo {
             ns = qm.ns;
 
             if (_isQueryOkToSecondary(ns, qm.queryOptions, qm.query)) {
+
                 shared_ptr<ReadPreferenceSetting> readPref(_extractReadPref(qm.query));
 
+                LOG( 3 ) << "dbclient_rs call using secondary or tagged node selection in "
+                                    << _getMonitor()->getName() << ", read pref is "
+                                    << readPref->toBSON() << " (primary : "
+                                    << ( _master.get() != NULL ?
+                                            _master->getServerAddress() : "[not cached]" )
+                                    << ", lastTagged : "
+                                    << ( _lastSlaveOkConn.get() != NULL ?
+                                            _lastSlaveOkConn->getServerAddress() : "[not cached]" )
+                                    << ")" << endl;
+
                 for (size_t retry = 0; retry < MAX_RETRY; retry++) {
                     try {
                         DBClientConnection* conn = selectNodeUsingTags(readPref);
@@ -1981,12 +2063,11 @@ namespace mongo {
 
                         return conn->call(toSend, response, assertOk);
                     }
-                    catch (const DBException& dbExcep) {
-                        LOG(1) << "can't call replica set slave " << _lastSlaveOkHost
-                               << ": " << causedBy(dbExcep) << endl;
+                    catch ( const DBException& dbExcep ) {
+                        LOG(1) << "can't call replica set node " << _lastSlaveOkHost << ": "
+                                          << causedBy( dbExcep ) << endl;
 
-                        if (actualServer)
-                            *actualServer = "";
+                        if ( actualServer ) *actualServer = "";
 
                         invalidateLastSlaveOkCache();
                     }
@@ -1997,6 +2078,8 @@ namespace mongo {
             }
         }
         
+        LOG( 3 ) << "dbclient_rs call to primary node in " << _getMonitor()->getName() << endl;
+
         DBClientConnection* m = checkMaster();
         if ( actualServer )
             *actualServer = m->getServerAddress();
@@ -2076,4 +2159,32 @@ namespace mongo {
     bool TagSet::equals(const TagSet& other) const {
         return _tags.equal(other._tags);
     }
+
+    const BSONArray& TagSet::getTagBSON() const {
+        return _tags;
+    }
+
+    string readPrefToString( ReadPreference pref ) {
+        switch ( pref ) {
+        case ReadPreference_PrimaryOnly:
+            return "primary only";
+        case ReadPreference_PrimaryPreferred:
+            return "primary pref";
+        case ReadPreference_SecondaryOnly:
+            return "secondary only";
+        case ReadPreference_SecondaryPreferred:
+            return "secondary pref";
+        case ReadPreference_Nearest:
+            return "nearest";
+        default:
+            return "Unknown";
+        }
+    }
+
+    BSONObj ReadPreferenceSetting::toBSON() const {
+        BSONObjBuilder bob;
+        bob.append( "pref", readPrefToString( pref ) );
+        bob.append( "tags", tags.getTagBSON() );
+        return bob.obj();
+    }
 }
diff --git a/src/mongo/client/dbclient_rs.h b/src/mongo/client/dbclient_rs.h
index 61e9306c8fd..05f7faa9b2b 100644
--- a/src/mongo/client/dbclient_rs.h
+++ b/src/mongo/client/dbclient_rs.h
@@ -675,6 +675,8 @@ namespace mongo {
          */
         bool equals(const TagSet& other) const;
 
+        const BSONArray& getTagBSON() const;
+
     private:
         /**
          * This is purposely undefined as the semantics for assignment can be
@@ -706,6 +708,8 @@ namespace mongo {
             return pref == other.pref && tags.equals(other.tags);
         }
 
+        BSONObj toBSON() const;
+
         const ReadPreference pref;
         TagSet tags;
     };