SERVER-15804 ensure ramlog contains state changes, syncsource changes, and write acceptance changes

12 files changed, 95 insertions, 115 deletions

diff --git a/src/mongo/db/repl/bgsync.cpp b/src/mongo/db/repl/bgsync.cpp
index e5b2cbe032d..00f2e2a5818 100644
--- a/src/mongo/db/repl/bgsync.cpp
+++ b/src/mongo/db/repl/bgsync.cpp
@@ -44,7 +44,6 @@
 #include "mongo/db/repl/repl_coordinator_impl.h"
 #include "mongo/db/repl/rs_rollback.h"
 #include "mongo/db/repl/rs_sync.h"
-#include "mongo/db/repl/rslog.h"
 #include "mongo/db/stats/timer_stats.h"
 #include "mongo/util/fail_point_service.h"
 #include "mongo/util/log.h"
@@ -148,11 +147,11 @@ namespace {
             }
             catch (const DBException& e) {
                 std::string msg(str::stream() << "sync producer problem: " << e.toString());
-                error() << msg << rsLog;
+                error() << msg;
                 _replCoord->setMyHeartbeatMessage(msg);
             }
             catch (const std::exception& e2) {
-                severe() << "sync producer exception: " << e2.what() << rsLog;
+                severe() << "sync producer exception: " << e2.what();
                 fassertFailed(28546);
             }
         }
@@ -311,7 +310,7 @@ namespace {
 
                     _syncSourceReader.tailCheck();
                     if( !_syncSourceReader.haveCursor() ) {
-                        LOG(1) << "replSet end syncTail pass" << rsLog;
+                        LOG(1) << "replSet end syncTail pass";
                         return;
                     }
 
@@ -338,7 +337,7 @@ namespace {
             }
 
             OCCASIONALLY {
-                LOG(2) << "bgsync buffer has " << _buffer.size() << " bytes" << rsLog;
+                LOG(2) << "bgsync buffer has " << _buffer.size() << " bytes";
             }
 
             bufferCountGauge.increment();
@@ -349,8 +348,7 @@ namespace {
                 boost::unique_lock<boost::mutex> lock(_mutex);
                 _lastFetchedHash = o["h"].numberLong();
                 _lastOpTimeFetched = o["ts"]._opTime();
-                LOG(3) << "replSet lastOpTimeFetched: "
-                       << _lastOpTimeFetched.toStringPretty() << rsLog;
+                LOG(3) << "replSet lastOpTimeFetched: " << _lastOpTimeFetched.toStringPretty();
             }
         }
     }
@@ -397,8 +395,8 @@ namespace {
             if (lastOpTimeFetched >= remoteTs) {
                 return false;
             }
-            log() << "replSet remoteOldestOp:    " << remoteTs.toStringLong() << rsLog;
-            log() << "replSet lastOpTimeFetched: " << lastOpTimeFetched.toStringLong() << rsLog;
+            log() << "replSet remoteOldestOp:    " << remoteTs.toStringLong();
+            log() << "replSet lastOpTimeFetched: " << lastOpTimeFetched.toStringLong();
         }
 
         return true;
@@ -411,23 +409,22 @@ namespace {
             try {
                 BSONObj theirLastOp = r.getLastOp(rsoplog);
                 if (theirLastOp.isEmpty()) {
-                    log() << "replSet error empty query result from " << hn << " oplog" << rsLog;
+                    log() << "replSet error empty query result from " << hn << " oplog";
                     sleepsecs(2);
                     return true;
                 }
                 OpTime theirTS = theirLastOp["ts"]._opTime();
                 if (theirTS < _lastOpTimeFetched) {
-                    log() << "replSet we are ahead of the sync source, will try to roll back"
-                          << rsLog;
+                    log() << "replSet we are ahead of the sync source, will try to roll back";
                     syncRollback(txn, _replCoord->getMyLastOptime(), &r, _replCoord);
                     return true;
                 }
                 /* we're not ahead?  maybe our new query got fresher data.  best to come back and try again */
-                log() << "replSet syncTail condition 1" << rsLog;
+                log() << "replSet syncTail condition 1";
                 sleepsecs(1);
             }
             catch(DBException& e) {
-                log() << "replSet error querying " << hn << ' ' << e.toString() << rsLog;
+                log() << "replSet error querying " << hn << ' ' << e.toString();
                 sleepsecs(2);
             }
             return true;
@@ -437,8 +434,8 @@ namespace {
         OpTime ts = o["ts"]._opTime();
         long long hash = o["h"].numberLong();
         if( ts != _lastOpTimeFetched || hash != _lastFetchedHash ) {
-            log() << "replSet our last op time fetched: " << _lastOpTimeFetched.toStringPretty() << rsLog;
-            log() << "replset source's GTE: " << ts.toStringPretty() << rsLog;
+            log() << "replSet our last op time fetched: " << _lastOpTimeFetched.toStringPretty();
+            log() << "replset source's GTE: " << ts.toStringPretty();
             syncRollback(txn, _replCoord->getMyLastOptime(), &r, _replCoord);
             return true;
         }
@@ -480,7 +477,7 @@ namespace {
         _lastFetchedHash = _lastAppliedHash;
 
         LOG(1) << "replset bgsync fetch queue set to: " << _lastOpTimeFetched << 
-            " " << _lastFetchedHash << rsLog;
+            " " << _lastFetchedHash;
     }
 
     bool BackgroundSync::isAssumingPrimary_inlock() {
diff --git a/src/mongo/db/repl/initial_sync.cpp b/src/mongo/db/repl/initial_sync.cpp
index d53fa12026f..ee2433f2a6b 100644
--- a/src/mongo/db/repl/initial_sync.cpp
+++ b/src/mongo/db/repl/initial_sync.cpp
@@ -35,7 +35,6 @@
 #include "mongo/db/operation_context_impl.h"
 #include "mongo/db/repl/oplog.h"
 #include "mongo/db/repl/replset_commands.h"
-#include "mongo/db/repl/rslog.h"
 #include "mongo/util/log.h"
 
 
@@ -52,7 +51,7 @@ namespace repl {
     void InitialSync::oplogApplication(OperationContext* txn, const OpTime& endOpTime) {
         if (replSetForceInitialSyncFailure > 0) {
             log() << "replSet test code invoked, forced InitialSync failure: "
-                  << replSetForceInitialSyncFailure << rsLog;
+                  << replSetForceInitialSyncFailure;
             replSetForceInitialSyncFailure--;
             throw DBException("forced error",0);
         }
diff --git a/src/mongo/db/repl/oplogreader.cpp b/src/mongo/db/repl/oplogreader.cpp
index a057236e139..caaf881ec36 100644
--- a/src/mongo/db/repl/oplogreader.cpp
+++ b/src/mongo/db/repl/oplogreader.cpp
@@ -47,7 +47,6 @@
 #include "mongo/db/repl/minvalid.h"
 #include "mongo/db/repl/oplog.h"
 #include "mongo/db/repl/repl_coordinator.h"
-#include "mongo/db/repl/rslog.h"
 #include "mongo/util/assert_util.h"
 #include "mongo/util/log.h"
 
@@ -162,13 +161,11 @@ namespace repl {
 
                 // Connected to at least one member, but in all cases we were too stale to use them
                 // as a sync source.
-                log() << "replSet error RS102 too stale to catch up" << rsLog;
-                log() << "replSet our last optime : " << lastOpTimeFetched.toStringLong() << rsLog;
-                log() << "replSet oldest available is " << oldestOpTimeSeen.toStringLong() <<
-                    rsLog;
+                log() << "replSet error RS102 too stale to catch up";
+                log() << "replSet our last optime : " << lastOpTimeFetched.toStringLong();
+                log() << "replSet oldest available is " << oldestOpTimeSeen.toStringLong();
                 log() << "replSet "
-                    "See http://dochub.mongodb.org/core/resyncingaverystalereplicasetmember" 
-                      << rsLog;
+                    "See http://dochub.mongodb.org/core/resyncingaverystalereplicasetmember";
                 setMinValid(txn, oldestOpTimeSeen);
                 bool worked = replCoord->setFollowerMode(MemberState::RS_RECOVERING);
                 if (!worked) {
@@ -181,7 +178,7 @@ namespace repl {
 
             if (!connect(candidate)) {
                 LOG(2) << "replSet can't connect to " << candidate.toString() << 
-                    " to read operations" << rsLog;
+                    " to read operations";
                 resetConnection();
                 replCoord->blacklistSyncSource(candidate, Date_t(curTimeMillis64() + 10*1000));
                 continue;
diff --git a/src/mongo/db/repl/repl_coordinator_impl.cpp b/src/mongo/db/repl/repl_coordinator_impl.cpp
index ca95291f26e..217d7c69000 100644
--- a/src/mongo/db/repl/repl_coordinator_impl.cpp
+++ b/src/mongo/db/repl/repl_coordinator_impl.cpp
@@ -539,7 +539,7 @@ namespace {
         _canAcceptNonLocalWrites = true;
         lk.unlock();
         _externalState->dropAllTempCollections(txn.get());
-        log() << "transition to primary complete; database writes are now permitted";
+        log() << "transition to primary complete; database writes are now permitted" << rsLog;
     }
 
     void ReplicationCoordinatorImpl::signalUpstreamUpdater() {
@@ -1520,8 +1520,8 @@ namespace {
 
             _topCoord->adjustMaintenanceCountBy(-1);
 
-            log() << "leaving maintenance mode (" << curMaintenanceCalls-1 << " other maintenance "
-                    "mode tasks ongoing)" << rsLog;
+            log() << "leaving maintenance mode (" << curMaintenanceCalls-1
+                  << " other maintenance mode tasks ongoing)" << rsLog;
         } else {
             warning() << "Attempted to leave maintenance mode but it is not currently active";
             *result = Status(ErrorCodes::OperationFailed, "already out of maintenance mode");
@@ -1659,7 +1659,7 @@ namespace {
                                                               const ReplSetReconfigArgs& args,
                                                               BSONObjBuilder* resultObj) {
 
-        log() << "replSetReconfig admin command received from client" << rsLog;
+        log() << "replSetReconfig admin command received from client";
 
         boost::unique_lock<boost::mutex> lk(_mutex);
 
@@ -1713,8 +1713,7 @@ namespace {
         }
         Status status = newConfig.initialize(newConfigObj);
         if (!status.isOK()) {
-            error() << "replSetReconfig got " << status << " while parsing " << newConfigObj <<
-                rsLog;
+            error() << "replSetReconfig got " << status << " while parsing " << newConfigObj;
             return Status(ErrorCodes::InvalidReplicaSetConfig, status.reason());;
         }
         if (newConfig.getReplSetName() != _settings.ourSetName()) {
@@ -1733,20 +1732,20 @@ namespace {
                 args.force);
         if (!myIndex.isOK()) {
             error() << "replSetReconfig got " << myIndex.getStatus() << " while validating " <<
-                newConfigObj << rsLog;
+                newConfigObj;
             return Status(ErrorCodes::NewReplicaSetConfigurationIncompatible,
                           myIndex.getStatus().reason());
         }
 
         log() << "replSetReconfig config object with " << newConfig.getNumMembers() <<
-            " members parses ok" << rsLog;
+            " members parses ok";
 
         if (!args.force) {
             status = checkQuorumForReconfig(&_replExecutor,
                                             newConfig,
                                             myIndex.getValue());
             if (!status.isOK()) {
-                error() << "replSetReconfig failed; " << status << rsLog;
+                error() << "replSetReconfig failed; " << status;
                 return status;
             }
         }
@@ -1796,7 +1795,7 @@ namespace {
     Status ReplicationCoordinatorImpl::processReplSetInitiate(OperationContext* txn,
                                                               const BSONObj& configObj,
                                                               BSONObjBuilder* resultObj) {
-        log() << "replSetInitiate admin command received from client" << rsLog;
+        log() << "replSetInitiate admin command received from client";
 
         boost::unique_lock<boost::mutex> lk(_mutex);
         if (!_settings.usingReplSets()) {
@@ -1825,7 +1824,7 @@ namespace {
         ReplicaSetConfig newConfig;
         Status status = newConfig.initialize(configObj);
         if (!status.isOK()) {
-            error() << "replSet initiate got " << status << " while parsing " << configObj << rsLog;
+            error() << "replSet initiate got " << status << " while parsing " << configObj;
             return Status(ErrorCodes::InvalidReplicaSetConfig, status.reason());;
         }
         if (newConfig.getReplSetName() != _settings.ourSetName()) {
@@ -1840,12 +1839,12 @@ namespace {
         StatusWith<int> myIndex = validateConfigForInitiate(_externalState.get(), newConfig);
         if (!myIndex.isOK()) {
             error() << "replSet initiate got " << myIndex.getStatus() << " while validating " <<
-                configObj << rsLog;
+                configObj;
             return Status(ErrorCodes::InvalidReplicaSetConfig, myIndex.getStatus().reason());
         }
 
         log() << "replSet replSetInitiate config object with " << newConfig.getNumMembers() <<
-            " members parses ok" << rsLog;
+            " members parses ok";
 
         status = checkQuorumForInitiate(
                 &_replExecutor,
@@ -1935,7 +1934,7 @@ namespace {
             result = kActionChooseNewSyncSource;
         }
         _currentState = newState;
-        log() << "transition to " << newState.toString();
+        log() << "transition to " << newState.toString() << rsLog;
         return result;
     }
 
@@ -2048,6 +2047,7 @@ namespace {
                  _replExecutor.now(),
                  myOptime);
          _rsConfig = newConfig;
+         log() << "new replica set config in use: " << _rsConfig.toBSON() << rsLog;
          _thisMembersConfigIndex = myIndex;
 
          if (_topCoord->getRole() == TopologyCoordinator::Role::candidate) {
diff --git a/src/mongo/db/repl/replset_commands.cpp b/src/mongo/db/repl/replset_commands.cpp
index 40fc8f8b095..23f281a45bb 100644
--- a/src/mongo/db/repl/replset_commands.cpp
+++ b/src/mongo/db/repl/replset_commands.cpp
@@ -47,7 +47,6 @@
 #include "mongo/db/repl/repl_set_heartbeat_response.h"
 #include "mongo/db/repl/repl_set_seed_list.h"
 #include "mongo/db/repl/replset_commands.h"
-#include "mongo/db/repl/rslog.h"
 #include "mongo/db/repl/scoped_conn.h"
 #include "mongo/db/repl/update_position_args.h"
 #include "mongo/db/storage/storage_engine.h"
@@ -71,7 +70,7 @@ namespace repl {
                                            std::vector<Privilege>* out) {}
         CmdReplSetTest() : ReplSetCommand("replSetTest") { }
         virtual bool run(OperationContext* txn, const string& , BSONObj& cmdObj, int, string& errmsg, BSONObjBuilder& result, bool fromRepl) {
-            log() << "replSet replSetTest command received: " << cmdObj.toString() << rsLog;
+            log() << "replSet replSetTest command received: " << cmdObj.toString();
 
             if( cmdObj.hasElement("forceInitialSyncFailure") ) {
                 replSetForceInitialSyncFailure = (unsigned) cmdObj["forceInitialSyncFailure"].Number();
@@ -238,7 +237,7 @@ namespace {
             if (configObj.isEmpty()) {
                 result.append("info2", "no configuration explicitly specified -- making one");
                 log() << "replSet info initiate : no configuration specified.  "
-                    "Using a default configuration for the set" << rsLog;
+                    "Using a default configuration for the set";
 
                 ReplicationCoordinatorExternalStateImpl externalState;
                 std::string name;
@@ -265,7 +264,7 @@ namespace {
                 b.appendArray("members", members.obj());
                 configObj = b.obj();
                 log() << "replSet created this configuration for initiation : " <<
-                        configObj.toString() << rsLog;
+                        configObj.toString();
             }
 
             if (configObj.getField("version").eoo()) {
@@ -695,8 +694,8 @@ namespace {
                          string& errmsg,
                          BSONObjBuilder& result,
                          bool fromRepl) {
-            DEV log() << "replSet received elect msg " << cmdObj.toString() << rsLog;
-            else LOG(2) << "replSet received elect msg " << cmdObj.toString() << rsLog;
+            DEV log() << "replSet received elect msg " << cmdObj.toString();
+            else LOG(2) << "replSet received elect msg " << cmdObj.toString();
 
             Status status = getGlobalReplicationCoordinator()->checkReplEnabledForCommand(&result);
             if (!status.isOK())
diff --git a/src/mongo/db/repl/rs_initialsync.cpp b/src/mongo/db/repl/rs_initialsync.cpp
index efdf411bc4c..32743b73964 100644
--- a/src/mongo/db/repl/rs_initialsync.cpp
+++ b/src/mongo/db/repl/rs_initialsync.cpp
@@ -47,7 +47,6 @@
 #include "mongo/db/repl/oplog.h"
 #include "mongo/db/repl/oplogreader.h"
 #include "mongo/db/repl/repl_coordinator_global.h"
-#include "mongo/db/repl/rslog.h"
 #include "mongo/util/log.h"
 #include "mongo/util/mongoutils/str.h"
 
@@ -183,8 +182,7 @@ namespace {
             syncer.oplogApplication(ctx, stopOpTime);
         }
         catch (const DBException&) {
-            log() << "replSet initial sync failed during oplog application phase, and will retry"
-                  << rsLog;
+            log() << "replSet initial sync failed during oplog application phase, and will retry";
 
             getGlobalReplicationCoordinator()->setMyLastOptime(ctx, OpTime());
             BackgroundSync::get()->setLastAppliedHash(0);
@@ -293,7 +291,7 @@ namespace {
         }
 
         if (getGlobalReplicationCoordinator()->getSettings().fastsync) {
-            log() << "fastsync: skipping database clone" << rsLog;
+            log() << "fastsync: skipping database clone";
 
             // prime oplog
             try {
@@ -377,7 +375,7 @@ namespace {
         {
             AutoGetDb autodb(&txn, "local", MODE_X);
             OpTime lastOpTimeWritten(getGlobalReplicationCoordinator()->getMyLastOptime());
-            log() << "replSet set minValid=" << lastOpTimeWritten << rsLog;
+            log() << "replSet set minValid=" << lastOpTimeWritten;
 
             // Initial sync is now complete.  Flag this by setting minValid to the last thing
             // we synced.
diff --git a/src/mongo/db/repl/rs_rollback.cpp b/src/mongo/db/repl/rs_rollback.cpp
index 424f3108ffe..7a602df6304 100644
--- a/src/mongo/db/repl/rs_rollback.cpp
+++ b/src/mongo/db/repl/rs_rollback.cpp
@@ -161,13 +161,13 @@ namespace {
         doc.ns = doc.ownedObj.getStringField("ns");
         if (*doc.ns == '\0') {
             warning() << "replSet WARNING ignoring op on rollback no ns TODO : "
-                  << doc.ownedObj.toString() << rsLog;
+                  << doc.ownedObj.toString();
             return;
         }
 
         BSONObj obj = doc.ownedObj.getObjectField(*op=='u' ? "o2" : "o");
         if (obj.isEmpty()) {
-            warning() << "replSet warning ignoring op on rollback : " << doc.ownedObj.toString() << rsLog;
+            warning() << "replSet warning ignoring op on rollback : " << doc.ownedObj.toString();
             return;
         }
 
@@ -196,7 +196,7 @@ namespace {
                 // TODO: this is bad.  we simply full resync the collection here,
                 //       which could be very slow.
                 warning() << "replSet info rollback of dropIndexes is slow in this version of "
-                          << "mongod" << rsLog;
+                          << "mongod";
                 string ns = nss.db().toString() + '.' + first.valuestr();
                 fixUpInfo.collectionsToResync.insert(ns);
                 return;
@@ -204,7 +204,7 @@ namespace {
             else if (cmdname == "renameCollection") {
                 // TODO: slow.
                 warning() << "replSet info rollback of renameCollection is slow in this version of "
-                          << "mongod" << rsLog;
+                          << "mongod";
                 string from = first.valuestr();
                 string to = obj["to"].String();
                 fixUpInfo.collectionsToResync.insert(from);
@@ -213,8 +213,8 @@ namespace {
             }
             else if (cmdname == "dropDatabase") {
                 severe() << "replSet error rollback : can't rollback drop database full resync "
-                         << "will be required" << rsLog;
-                log() << "replSet " << obj.toString() << rsLog;
+                         << "will be required";
+                log() << "replSet " << obj.toString();
                 throw RSFatalException();
             }
             else if (cmdname == "collMod") {
@@ -228,8 +228,8 @@ namespace {
             }
             else {
                 severe() << "replSet error can't rollback this command yet: "
-                         << obj.toString() << rsLog;
-                log() << "replSet cmdname=" << cmdname << rsLog;
+                         << obj.toString();
+                log() << "replSet cmdname=" << cmdname;
                 throw RSFatalException();
             }
         }
@@ -237,7 +237,7 @@ namespace {
         doc._id = obj["_id"];
         if (doc._id.eoo()) {
             warning() << "replSet WARNING ignoring op on rollback no _id TODO : " << doc.ns << ' '
-                      << doc.ownedObj.toString() << rsLog;
+                      << doc.ownedObj.toString();
             return;
         }
 
@@ -280,11 +280,11 @@ namespace {
         long long diff = static_cast<long long>(ourTime.getSecs())
                                - static_cast<long long>(theirTime.getSecs());
         // diff could be positive, negative, or zero
-        log() << "replSet info rollback our last optime:   " << ourTime.toStringPretty() << rsLog;
-        log() << "replSet info rollback their last optime: " << theirTime.toStringPretty() << rsLog;
-        log() << "replSet info rollback diff in end of log times: " << diff << " seconds" << rsLog;
+        log() << "replSet info rollback our last optime:   " << ourTime.toStringPretty();
+        log() << "replSet info rollback their last optime: " << theirTime.toStringPretty();
+        log() << "replSet info rollback diff in end of log times: " << diff << " seconds";
         if (diff > 1800) {
-            log() << "replSet rollback too long a time period for a rollback." << rsLog;
+            log() << "replSet rollback too long a time period for a rollback.";
             throw RSFatalException("rollback error: not willing to roll back "
                                    "more than 30 minutes of data");
         }
@@ -298,8 +298,8 @@ namespace {
                     // found the point back in time where we match.
                     // todo : check a few more just to be careful about hash collisions.
                     log() << "replSet rollback found matching events at "
-                          << ourTime.toStringPretty() << rsLog;
-                    log() << "replSet rollback findcommonpoint scanned : " << scanned << rsLog;
+                          << ourTime.toStringPretty();
+                    log() << "replSet rollback findcommonpoint scanned : " << scanned;
                     fixUpInfo.commonPoint = ourTime;
                     fixUpInfo.commonPointOurDiskloc = ourLoc;
                     return;
@@ -308,36 +308,31 @@ namespace {
                 refetch(fixUpInfo, ourObj);
 
                 if (!oplogCursor->more()) {
-                    log() << "replSet rollback error RS100 reached beginning of remote oplog"
-                          << rsLog;
-                    log() << "replSet   them:      " << them->toString() << " scanned: "
-                          << scanned << rsLog;
-                    log() << "replSet   theirTime: " << theirTime.toStringLong() << rsLog;
-                    log() << "replSet   ourTime:   " << ourTime.toStringLong() << rsLog;
+                    log() << "replSet rollback error RS100 reached beginning of remote oplog";
+                    log() << "replSet   them:      " << them->toString() << " scanned: " << scanned;
+                    log() << "replSet   theirTime: " << theirTime.toStringLong();
+                    log() << "replSet   ourTime:   " << ourTime.toStringLong();
                     throw RSFatalException("RS100 reached beginning of remote oplog [2]");
                 }
                 theirObj = oplogCursor->nextSafe();
                 theirTime = theirObj["ts"]._opTime();
 
                 if (PlanExecutor::ADVANCED != exec->getNext(&ourObj, &ourLoc)) {
-                    log() << "replSet rollback error RS101 reached beginning of local oplog"
-                          << rsLog;
-                    log() << "replSet   them:      " << them->toString() << " scanned: "
-                          << scanned << rsLog;
-                    log() << "replSet   theirTime: " << theirTime.toStringLong() << rsLog;
-                    log() << "replSet   ourTime:   " << ourTime.toStringLong() << rsLog;
+                    log() << "replSet rollback error RS101 reached beginning of local oplog";
+                    log() << "replSet   them:      " << them->toString() << " scanned: " << scanned;
+                    log() << "replSet   theirTime: " << theirTime.toStringLong();
+                    log() << "replSet   ourTime:   " << ourTime.toStringLong();
                     throw RSFatalException("RS101 reached beginning of local oplog [1]");
                 }
                 ourTime = ourObj["ts"]._opTime();
             }
             else if (theirTime > ourTime) {
                 if (!oplogCursor->more()) {
-                    log() << "replSet rollback error RS100 reached beginning of remote oplog"
-                          << rsLog;
+                    log() << "replSet rollback error RS100 reached beginning of remote oplog";
                     log() << "replSet   them:      " << them->toString() << " scanned: "
-                          << scanned << rsLog;
-                    log() << "replSet   theirTime: " << theirTime.toStringLong() << rsLog;
-                    log() << "replSet   ourTime:   " << ourTime.toStringLong() << rsLog;
+                          << scanned;
+                    log() << "replSet   theirTime: " << theirTime.toStringLong();
+                    log() << "replSet   ourTime:   " << ourTime.toStringLong();
                     throw RSFatalException("RS100 reached beginning of remote oplog [1]");
                 }
                 theirObj = oplogCursor->nextSafe();
@@ -347,12 +342,10 @@ namespace {
                 // theirTime < ourTime
                 refetch(fixUpInfo, ourObj);
                 if (PlanExecutor::ADVANCED != exec->getNext(&ourObj, &ourLoc)) {
-                    log() << "replSet rollback error RS101 reached beginning of local oplog"
-                          << rsLog;
-                    log() << "replSet   them:      " << them->toString() << " scanned: "
-                          << scanned << rsLog;
-                    log() << "replSet   theirTime: " << theirTime.toStringLong() << rsLog;
-                    log() << "replSet   ourTime:   " << ourTime.toStringLong() << rsLog;
+                    log() << "replSet rollback error RS101 reached beginning of local oplog";
+                    log() << "replSet   them:      " << them->toString() << " scanned: " << scanned;
+                    log() << "replSet   theirTime: " << theirTime.toStringLong();
+                    log() << "replSet   ourTime:   " << ourTime.toStringLong();
                     throw RSFatalException("RS101 reached beginning of local oplog [2]");
                 }
                 ourTime = ourObj["ts"]._opTime();
@@ -422,7 +415,7 @@ namespace {
         catch (DBException& e) {
             LOG(1) << "rollback re-get objects: " << e.toString();
             error() << "rollback couldn't re-get ns:" << doc.ns << " _id:" << doc._id << ' '
-                    << numFetched << '/' << fixUpInfo.toRefetch.size() << rsLog;
+                    << numFetched << '/' << fixUpInfo.toRefetch.size();
             throw e;
         }
 
@@ -444,7 +437,7 @@ namespace {
         // we have items we are writing that aren't from a point-in-time.  thus best not to come
         // online until we get to that point in freshness.
         OpTime minValid = newMinValid["ts"]._opTime();
-        log() << "replSet minvalid=" << minValid.toStringLong() << rsLog;
+        log() << "replSet minvalid=" << minValid.toStringLong();
         setMinValid(txn, minValid);
 
         // any full collection resyncs required?
@@ -494,8 +487,7 @@ namespace {
                 }
                 else {
                     OpTime minValid = newMinValid["ts"]._opTime();
-                    log() << "replSet minvalid=" << minValid.toStringLong()
-                          << rsLog;
+                    log() << "replSet minvalid=" << minValid.toStringLong();
                     setMinValid(txn, minValid);
                 }
             }
@@ -510,7 +502,7 @@ namespace {
             }
             if (!err.empty()) {
                 error() << "replSet error rolling back : " << err
-                        << ". A full resync will be necessary." << rsLog;
+                        << ". A full resync will be necessary.";
                 // TODO: reset minvalid so that we are permanently in fatal state
                 // TODO: don't be fatal, but rather, get all the data first.
                 throw RSFatalException();
@@ -524,7 +516,7 @@ namespace {
         for (set<string>::iterator it = fixUpInfo.toDrop.begin();
                 it != fixUpInfo.toDrop.end();
                 it++) {
-            log() << "replSet rollback drop: " << *it << rsLog;
+            log() << "replSet rollback drop: " << *it;
 
             Database* db = dbHolder().get(txn, nsToDatabaseSubstring(*it));
             if (db) {
@@ -600,7 +592,7 @@ namespace {
                                 DiskLoc loc = Helpers::findOne(txn, collection, pattern, false);
                                 if (Listener::getElapsedTimeMillis() - start > 200)
                                     log() << "replSet warning roll back slow no _id index for "
-                                          << doc.ns << " perhaps?" << rsLog;
+                                          << doc.ns << " perhaps?";
                                 // would be faster but requires index:
                                 // DiskLoc loc = Helpers::findById(nsd, pattern);
                                 if (!loc.isNull()) {
@@ -622,7 +614,7 @@ namespace {
                             }
                             catch (DBException& e) {
                                 log() << "replSet error rolling back capped collection rec "
-                                      << doc.ns << ' ' << e.toString() << rsLog;
+                                      << doc.ns << ' ' << e.toString();
                             }
                         }
                         else {
@@ -652,7 +644,7 @@ namespace {
                             catch (DBException&) {
                                 // this isn't *that* big a deal, but is bad.
                                 log() << "replSet warning rollback error querying for existence of "
-                                      << doc.ns << " at the primary, ignoring" << rsLog;
+                                      << doc.ns << " at the primary, ignoring";
                             }
                         }
                     }
@@ -678,7 +670,7 @@ namespace {
             }
             catch (DBException& e) {
                 log() << "replSet exception in rollback ns:" << doc.ns << ' ' << pattern.toString()
-                      << ' ' << e.toString() << " ndeletes:" << deletes << rsLog;
+                      << ' ' << e.toString() << " ndeletes:" << deletes;
                 warn = true;
             }
         }
@@ -688,8 +680,8 @@ namespace {
         log() << "rollback 6";
 
         // clean up oplog
-        LOG(2) << "replSet rollback truncate oplog after " << fixUpInfo.commonPoint.toStringPretty()
-               << rsLog;
+        LOG(2) << "replSet rollback truncate oplog after " <<
+                fixUpInfo.commonPoint.toStringPretty();
         // TODO: fatal error if this throws?
         oplogCollection->temp_cappedTruncateAfter(txn, fixUpInfo.commonPointOurDiskloc, false);
 
@@ -809,9 +801,13 @@ namespace {
             }
         }
 
+        log() << "beginning rollback" << rsLog;
+
         unsigned s = _syncRollback(txn, oplogreader, replCoord);
         if (s)
             sleepsecs(s);
+        
+        log() << "rollback finished" << rsLog;
     }
 
 } // namespace repl
diff --git a/src/mongo/db/repl/rs_sync.cpp b/src/mongo/db/repl/rs_sync.cpp
index 33a0a296075..fc7a67f16e7 100644
--- a/src/mongo/db/repl/rs_sync.cpp
+++ b/src/mongo/db/repl/rs_sync.cpp
@@ -50,7 +50,6 @@
 #include "mongo/db/repl/repl_settings.h"
 #include "mongo/db/repl/repl_coordinator_global.h"
 #include "mongo/db/repl/rs_initialsync.h"
-#include "mongo/db/repl/rslog.h"
 #include "mongo/db/repl/sync_tail.h"
 #include "mongo/db/server_parameters.h"
 #include "mongo/db/stats/timer_stats.h"
@@ -91,8 +90,7 @@ namespace repl {
             // trying to sync with other replicas.
             // TODO(spencer): Use a condition variable to await loading a config
             if (replCoord->getReplicationMode() != ReplicationCoordinator::modeReplSet) {
-                log() << "replSet warning did not receive a valid config yet, sleeping 5 seconds "
-                      << rsLog;
+                log() << "replSet warning did not receive a valid config yet, sleeping 5 seconds ";
                 sleepsecs(5);
                 continue;
             }
diff --git a/src/mongo/db/repl/scoped_conn.cpp b/src/mongo/db/repl/scoped_conn.cpp
index cd81fc24d1b..e01cabbea7b 100644
--- a/src/mongo/db/repl/scoped_conn.cpp
+++ b/src/mongo/db/repl/scoped_conn.cpp
@@ -34,7 +34,6 @@
 
 #include "mongo/db/repl/scoped_conn.h"
 
-#include "mongo/db/repl/rslog.h"
 #include "mongo/util/log.h"
 
 namespace mongo {
@@ -60,7 +59,7 @@ namespace repl {
     bool ScopedConn::connect() {
         std::string err;
         if (!connInfo->cc->connect(HostAndPort(_hostport), err)) {
-            log() << "couldn't connect to " << _hostport << ": " << err << rsLog;
+            log() << "couldn't connect to " << _hostport << ": " << err;
             return false;
         }
         connInfo->connected = true;
diff --git a/src/mongo/db/repl/sync_source_feedback.cpp b/src/mongo/db/repl/sync_source_feedback.cpp
index 677cb8c7e2c..7b2faf93326 100644
--- a/src/mongo/db/repl/sync_source_feedback.cpp
+++ b/src/mongo/db/repl/sync_source_feedback.cpp
@@ -43,7 +43,6 @@
 #include "mongo/db/operation_context_impl.h"
 #include "mongo/db/repl/bgsync.h"
 #include "mongo/db/repl/repl_coordinator_global.h"
-#include "mongo/db/repl/rslog.h"
 #include "mongo/db/operation_context.h"
 #include "mongo/util/log.h"
 #include "mongo/util/net/hostandport.h"
@@ -160,7 +159,7 @@ namespace repl {
         if (hasConnection()) {
             return true;
         }
-        log() << "replset setting syncSourceFeedback to " << host.toString() << rsLog;
+        log() << "replset setting syncSourceFeedback to " << host.toString();
         _connection.reset(new DBClientConnection(false, 0, OplogReader::tcp_timeout));
         string errmsg;
         try {
diff --git a/src/mongo/db/repl/sync_tail.cpp b/src/mongo/db/repl/sync_tail.cpp
index e191f96c1b1..f233769b6e3 100644
--- a/src/mongo/db/repl/sync_tail.cpp
+++ b/src/mongo/db/repl/sync_tail.cpp
@@ -51,7 +51,6 @@
 #include "mongo/db/repl/minvalid.h"
 #include "mongo/db/repl/oplog.h"
 #include "mongo/db/repl/repl_coordinator_global.h"
-#include "mongo/db/repl/rslog.h"
 #include "mongo/db/stats/timer_stats.h"
 #include "mongo/db/operation_context_impl.h"
 #include "mongo/util/exit.h"
@@ -230,7 +229,7 @@ namespace repl {
             // this is often a no-op
             // but can't be 100% sure
             if( *op.getStringField("op") != 'n' ) {
-                error() << "replSet skipping bad op in oplog: " << op.toString() << rsLog;
+                error() << "replSet skipping bad op in oplog: " << op.toString();
             }
             return true;
         }
@@ -438,7 +437,7 @@ namespace repl {
                 }
                 else if (currentOpTime > endOpTime) {
                     severe() << "Applied past expected end " << endOpTime << " to " << currentOpTime
-                            << " without seeing it. Rollback?" << rsLog;
+                            << " without seeing it. Rollback?";
                     fassertFailedNoTrace(18693);
                 }
 
@@ -686,7 +685,7 @@ namespace {
                 }
                 else {
                     warning() << "replSet slavedelay causing a long sleep of " << sleeptime
-                              << " seconds" << rsLog;
+                              << " seconds";
                     // sleep(hours) would prevent reconfigs from taking effect & such!
                     long long waitUntil = b + sleeptime;
                     while(time(0) < waitUntil) {
diff --git a/src/mongo/db/repl/topology_coordinator_impl.cpp b/src/mongo/db/repl/topology_coordinator_impl.cpp
index 280c6802b23..8b0a14f078d 100644
--- a/src/mongo/db/repl/topology_coordinator_impl.cpp
+++ b/src/mongo/db/repl/topology_coordinator_impl.cpp
@@ -404,8 +404,7 @@ namespace {
         if (hbdata.getOpTime().getSecs()+10 < lastOpApplied.getSecs()) {
             warning() << "attempting to sync from " << target
                       << ", but its latest opTime is " << hbdata.getOpTime().getSecs()
-                      << " and ours is " << lastOpApplied.getSecs() << " so this may not work"
-                      << rsLog;
+                      << " and ours is " << lastOpApplied.getSecs() << " so this may not work";
             response->append("warning",
                              str::stream() << "requested member \"" << target.toString() <<
                                      "\" is more than 10 seconds behind us");