/* initial oplog application, during initial sync, after cloning.
*/
BSONObj InitialSync::oplogApplication(const BSONObj& applyGTEObj, const BSONObj& minValidObj) {
if (replSetForceInitialSyncFailure > 0) {
log() << "replSet test code invoked, forced InitialSync failure: " << replSetForceInitialSyncFailure << rsLog;
replSetForceInitialSyncFailure--;
throw DBException("forced error",0);
}
// create the initial oplog entry
syncApply(applyGTEObj);
_logOpObjRS(applyGTEObj);
return oplogApplySegment(applyGTEObj, minValidObj, multiInitialSyncApply);
}
void SyncTail::applyOpsToOplog(std::deque<BSONObj>* ops) {
{
Lock::DBWrite lk("local");
while (!ops->empty()) {
const BSONObj& op = ops->front();
// this updates theReplSet->lastOpTimeWritten
_logOpObjRS(op);
ops->pop_front();
}
}
// Update write concern on primary
BackgroundSync::notify();
}
void replset::InitialSync::applyOp(const BSONObj& o, const OpTime& applyGTE) {
OpTime ts = o["ts"]._opTime();
// optimes before we started copying need not be applied.
if( ts >= applyGTE ) {
if (!syncApply(o)) {
if (shouldRetry(o)) {
uassert(15915, "replSet update still fails after adding missing object", syncApply(o));
}
}
}
// with repl sets we write the ops to our oplog, too
_logOpObjRS(o);
}
void SyncTail::applyOpsToOplog(std::deque<BSONObj>* ops) {
{
OperationContextImpl txn; // XXX?
Lock::DBWrite lk(txn.lockState(), "local");
while (!ops->empty()) {
const BSONObj& op = ops->front();
// this updates theReplSet->lastOpTimeWritten
_logOpObjRS(op);
ops->pop_front();
}
}
if (BackgroundSync::get()->isAssumingPrimary()) {
LOG(1) << "notifying BackgroundSync";
}
// Update write concern on primary
BackgroundSync::notify();
}
OpTime SyncTail::applyOpsToOplog(std::deque<BSONObj>* ops) {
OpTime lastOpTime;
{
OperationContextImpl txn; // XXX?
Lock::DBLock lk(txn.lockState(), "local", MODE_X);
WriteUnitOfWork wunit(&txn);
while (!ops->empty()) {
const BSONObj& op = ops->front();
// this updates lastOpTimeApplied
lastOpTime = _logOpObjRS(&txn, op);
ops->pop_front();
}
wunit.commit();
}
// Update write concern on primary
BackgroundSync::get()->notify();
return lastOpTime;
}
/* initial oplog application, during initial sync, after cloning.
@return false on failure.
this method returns an error and doesn't throw exceptions (i think).
*/
bool ReplSetImpl::initialSyncOplogApplication(
const Member *source,
OpTime applyGTE,
OpTime minValid)
{
if( source == 0 ) return false;
const string hn = source->h().toString();
OpTime ts;
try {
OplogReader r;
if( !r.connect(hn) ) {
log() << "replSet initial sync error can't connect to " << hn << " to read " << rsoplog << rsLog;
return false;
}
{
BSONObjBuilder q;
q.appendDate("$gte", applyGTE.asDate());
BSONObjBuilder query;
query.append("ts", q.done());
BSONObj queryObj = query.done();
r.query(rsoplog, queryObj);
}
assert( r.haveCursor() );
/* we lock outside the loop to avoid the overhead of locking on every operation. server isn't usable yet anyway! */
writelock lk("");
{
if( !r.more() ) {
sethbmsg("replSet initial sync error reading remote oplog");
log() << "replSet initial sync error remote oplog (" << rsoplog << ") on host " << hn << " is empty?" << rsLog;
return false;
}
bo op = r.next();
OpTime t = op["ts"]._opTime();
r.putBack(op);
if( op.firstElement().fieldName() == string("$err") ) {
log() << "replSet initial sync error querying " << rsoplog << " on " << hn << " : " << op.toString() << rsLog;
return false;
}
uassert( 13508 , str::stream() << "no 'ts' in first op in oplog: " << op , !t.isNull() );
if( t > applyGTE ) {
sethbmsg(str::stream() << "error " << hn << " oplog wrapped during initial sync");
log() << "replSet initial sync expected first optime of " << applyGTE << rsLog;
log() << "replSet initial sync but received a first optime of " << t << " from " << hn << rsLog;
return false;
}
}
// todo : use exhaust
unsigned long long n = 0;
while( 1 ) {
if( !r.more() )
break;
BSONObj o = r.nextSafe(); /* note we might get "not master" at some point */
{
ts = o["ts"]._opTime();
/* if we have become primary, we dont' want to apply things from elsewhere
anymore. assumePrimary is in the db lock so we are safe as long as
we check after we locked above. */
if( (source->state() != MemberState::RS_PRIMARY &&
source->state() != MemberState::RS_SECONDARY) ||
replSetForceInitialSyncFailure ) {
int f = replSetForceInitialSyncFailure;
if( f > 0 ) {
replSetForceInitialSyncFailure = f-1;
log() << "replSet test code invoked, replSetForceInitialSyncFailure" << rsLog;
throw DBException("forced error",0);
}
log() << "replSet we are now primary" << rsLog;
throw DBException("primary changed",0);
}
if( ts >= applyGTE ) {
// optimes before we started copying need not be applied.
syncApply(o);
}
_logOpObjRS(o); /* with repl sets we write the ops to our oplog too */
}
if( ++n % 100000 == 0 ) {
// simple progress metering
log() << "replSet initialSyncOplogApplication " << n << rsLog;
}
}
}
catch(DBException& e) {
if( ts <= minValid ) {
// didn't make it far enough
log() << "replSet initial sync failing, error applying oplog " << e.toString() << rsLog;
return false;
}
}
return true;
}
bool ReplSetImpl::_initialSyncOplogApplication(OplogReader& r, const Member *source,
const OpTime& applyGTE, const OpTime& minValid) {
const string hn = source->fullName();
OplogReader missingObjReader;
try {
r.tailingQueryGTE( rsoplog, applyGTE );
if ( !r.haveCursor() ) {
log() << "replSet initial sync oplog query error" << rsLog;
return false;
}
{
if( !r.more() ) {
sethbmsg("replSet initial sync error reading remote oplog");
log() << "replSet initial sync error remote oplog (" << rsoplog << ") on host " << hn << " is empty?" << rsLog;
return false;
}
bo op = r.next();
OpTime t = op["ts"]._opTime();
r.putBack(op);
if( op.firstElementFieldName() == string("$err") ) {
log() << "replSet initial sync error querying " << rsoplog << " on " << hn << " : " << op.toString() << rsLog;
return false;
}
uassert( 13508 , str::stream() << "no 'ts' in first op in oplog: " << op , !t.isNull() );
if( t > applyGTE ) {
sethbmsg(str::stream() << "error " << hn << " oplog wrapped during initial sync");
log() << "replSet initial sync expected first optime of " << applyGTE << rsLog;
log() << "replSet initial sync but received a first optime of " << t << " from " << hn << rsLog;
return false;
}
sethbmsg(str::stream() << "initial oplog application from " << hn << " starting at "
<< t.toStringPretty() << " to " << minValid.toStringPretty());
}
}
catch(DBException& e) {
log() << "replSet initial sync failing: " << e.toString() << rsLog;
return false;
}
/* we lock outside the loop to avoid the overhead of locking on every operation. */
writelock lk("");
// todo : use exhaust
OpTime ts;
time_t start = time(0);
unsigned long long n = 0;
while( 1 ) {
try {
if( !r.more() )
break;
BSONObj o = r.nextSafe(); /* note we might get "not master" at some point */
ts = o["ts"]._opTime();
{
if( (source->state() != MemberState::RS_PRIMARY &&
source->state() != MemberState::RS_SECONDARY) ||
replSetForceInitialSyncFailure ) {
int f = replSetForceInitialSyncFailure;
if( f > 0 ) {
replSetForceInitialSyncFailure = f-1;
log() << "replSet test code invoked, replSetForceInitialSyncFailure" << rsLog;
throw DBException("forced error",0);
}
log() << "replSet we are now primary" << rsLog;
throw DBException("primary changed",0);
}
if( ts >= applyGTE ) { // optimes before we started copying need not be applied.
bool failedUpdate = syncApply(o);
if( failedUpdate ) {
// we don't have the object yet, which is possible on initial sync. get it.
log() << "replSet info adding missing object" << endl; // rare enough we can log
if( !missingObjReader.connect(hn) ) { // ok to call more than once
log() << "replSet initial sync fails, couldn't connect to " << hn << endl;
return false;
}
const char *ns = o.getStringField("ns");
BSONObj query = BSONObjBuilder().append(o.getObjectField("o2")["_id"]).obj(); // might be more than just _id in the update criteria
BSONObj missingObj;
try {
missingObj = missingObjReader.findOne(
ns,
query );
} catch(...) {
log() << "replSet assertion fetching missing object" << endl;
throw;
}
if( missingObj.isEmpty() ) {
log() << "replSet missing object not found on source. presumably deleted later in oplog" << endl;
log() << "replSet o2: " << o.getObjectField("o2").toString() << endl;
log() << "replSet o firstfield: " << o.getObjectField("o").firstElementFieldName() << endl;
}
else {
Client::Context ctx(ns);
try {
DiskLoc d = theDataFileMgr.insert(ns, (void*) missingObj.objdata(), missingObj.objsize());
assert( !d.isNull() );
} catch(...) {
log() << "replSet assertion during insert of missing object" << endl;
throw;
}
// now reapply the update from above
bool failed = syncApply(o);
if( failed ) {
log() << "replSet update still fails after adding missing object " << ns << endl;
assert(false);
}
}
}
}
_logOpObjRS(o); /* with repl sets we write the ops to our oplog too */
}
if ( ++n % 1000 == 0 ) {
time_t now = time(0);
if (now - start > 10) {
// simple progress metering
log() << "replSet initialSyncOplogApplication applied " << n << " operations, synced to "
<< ts.toStringPretty() << rsLog;
start = now;
}
}
if ( ts > minValid ) {
break;
}
getDur().commitIfNeeded();
}
catch (DBException& e) {
// skip duplicate key exceptions
if( e.getCode() == 11000 || e.getCode() == 11001 ) {
continue;
}
// handle cursor not found (just requery)
if( e.getCode() == 13127 ) {
log() << "replSet requerying oplog after cursor not found condition, ts: " << ts.toStringPretty() << endl;
r.resetCursor();
r.tailingQueryGTE(rsoplog, ts);
if( r.haveCursor() ) {
continue;
}
}
// TODO: handle server restart
if( ts <= minValid ) {
// didn't make it far enough
log() << "replSet initial sync failing, error applying oplog : " << e.toString() << rsLog;
return false;
}
// otherwise, whatever
break;
}
}
return true;
}
/* initial oplog application, during initial sync, after cloning.
@return false on failure.
this method returns an error and doesn't throw exceptions (i think).
*/
bool ReplSetImpl::initialSyncOplogApplication(
const Member *source,
OpTime applyGTE,
OpTime minValid) {
if( source == 0 ) return false;
const string hn = source->h().toString();
OplogReader r;
try {
if( !r.connect(hn) ) {
log() << "replSet initial sync error can't connect to " << hn << " to read " << rsoplog << rsLog;
return false;
}
r.queryGTE( rsoplog, applyGTE );
assert( r.haveCursor() );
{
if( !r.more() ) {
sethbmsg("replSet initial sync error reading remote oplog");
log() << "replSet initial sync error remote oplog (" << rsoplog << ") on host " << hn << " is empty?" << rsLog;
return false;
}
bo op = r.next();
OpTime t = op["ts"]._opTime();
r.putBack(op);
if( op.firstElement().fieldName() == string("$err") ) {
log() << "replSet initial sync error querying " << rsoplog << " on " << hn << " : " << op.toString() << rsLog;
return false;
}
uassert( 13508 , str::stream() << "no 'ts' in first op in oplog: " << op , !t.isNull() );
if( t > applyGTE ) {
sethbmsg(str::stream() << "error " << hn << " oplog wrapped during initial sync");
log() << "replSet initial sync expected first optime of " << applyGTE << rsLog;
log() << "replSet initial sync but received a first optime of " << t << " from " << hn << rsLog;
return false;
}
sethbmsg(str::stream() << "initial oplog application from " << hn << " starting at "
<< t.toStringPretty() << " to " << minValid.toStringPretty());
}
}
catch(DBException& e) {
log() << "replSet initial sync failing: " << e.toString() << rsLog;
return false;
}
/* we lock outside the loop to avoid the overhead of locking on every operation. */
writelock lk("");
// todo : use exhaust
OpTime ts;
time_t start = time(0);
unsigned long long n = 0;
while( 1 ) {
try {
if( !r.more() )
break;
BSONObj o = r.nextSafe(); /* note we might get "not master" at some point */
{
ts = o["ts"]._opTime();
/* if we have become primary, we dont' want to apply things from elsewhere
anymore. assumePrimary is in the db lock so we are safe as long as
we check after we locked above. */
if( (source->state() != MemberState::RS_PRIMARY &&
source->state() != MemberState::RS_SECONDARY) ||
replSetForceInitialSyncFailure ) {
int f = replSetForceInitialSyncFailure;
if( f > 0 ) {
replSetForceInitialSyncFailure = f-1;
log() << "replSet test code invoked, replSetForceInitialSyncFailure" << rsLog;
throw DBException("forced error",0);
}
log() << "replSet we are now primary" << rsLog;
throw DBException("primary changed",0);
}
if( ts >= applyGTE ) {
// optimes before we started copying need not be applied.
syncApply(o);
}
_logOpObjRS(o); /* with repl sets we write the ops to our oplog too */
}
if ( ++n % 1000 == 0 ) {
time_t now = time(0);
if (now - start > 10) {
// simple progress metering
log() << "replSet initialSyncOplogApplication applied " << n << " operations, synced to "
<< ts.toStringPretty() << rsLog;
start = now;
}
}
getDur().commitIfNeeded();
}
catch (DBException& e) {
// skip duplicate key exceptions
if( e.getCode() == 11000 || e.getCode() == 11001 ) {
continue;
}
// handle cursor not found (just requery)
if( e.getCode() == 13127 ) {
r.resetCursor();
r.queryGTE(rsoplog, ts);
if( r.haveCursor() ) {
continue;
}
}
// TODO: handle server restart
if( ts <= minValid ) {
// didn't make it far enough
log() << "replSet initial sync failing, error applying oplog " << e.toString() << rsLog;
return false;
}
// otherwise, whatever
break;
}
}
return true;
}
