void ReplicationRecoveryImpl::_recoverFromUnstableCheckpoint(OperationContext* opCtx,
OpTime appliedThrough,
OpTime topOfOplog) {
invariant(!topOfOplog.isNull());
log() << "Recovering from an unstable checkpoint (top of oplog: " << topOfOplog
<< ", appliedThrough: " << appliedThrough << ")";
if (appliedThrough.isNull()) {
// The appliedThrough would be null if we shut down cleanly or crashed as a primary. Either
// way we are consistent at the top of the oplog.
log() << "No oplog entries to apply for recovery. appliedThrough is null.";
} else {
// If the appliedThrough is not null, then we shut down uncleanly during secondary oplog
// application and must apply from the appliedThrough to the top of the oplog.
log() << "Starting recovery oplog application at the appliedThrough: " << appliedThrough
<< ", through the top of the oplog: " << topOfOplog;
// When `recoverFromOplog` truncates the oplog, that also happens to set the "oldest
// timestamp" to the truncation point[1]. `_applyToEndOfOplog` will then perform writes
// before the truncation point. Doing so violates the constraint that all updates must be
// timestamped newer than the "oldest timestamp". This call will move the "oldest
// timestamp" back to the `startPoint`.
//
// [1] This is arguably incorrect. On rollback for nodes that are not keeping history to
// the "majority point", the "oldest timestamp" likely needs to go back in time. The
// oplog's `cappedTruncateAfter` method was a convenient location for this logic, which,
// unfortunately, conflicts with the usage above.
opCtx->getServiceContext()->getStorageEngine()->setOldestTimestamp(
appliedThrough.getTimestamp());
_applyToEndOfOplog(opCtx, appliedThrough.getTimestamp(), topOfOplog.getTimestamp());
}
// `_recoverFromUnstableCheckpoint` is only expected to be called on startup.
_storageInterface->setInitialDataTimestamp(opCtx->getServiceContext(),
topOfOplog.getTimestamp());
// Ensure the `appliedThrough` is set to the top of oplog, specifically if the node was
// previously running as a primary. If a crash happens before the first stable checkpoint on
// upgrade, replication recovery will know it must apply from this point and not assume the
// datafiles contain any writes that were taken before the crash.
_consistencyMarkers->setAppliedThrough(opCtx, topOfOplog);
// Force the set `appliedThrough` to become durable on disk in a checkpoint. This method would
// typically take a stable checkpoint, but because we're starting up from a checkpoint that
// has no checkpoint timestamp, the stable checkpoint "degrades" into an unstable checkpoint.
//
// Not waiting for checkpoint durability here can result in a scenario where the node takes
// writes and persists them to the oplog, but crashes before a stable checkpoint persists a
// "recovery timestamp". The typical startup path for data-bearing nodes with 4.0 is to use
// the recovery timestamp to determine where to play oplog forward from. As this method shows,
// when a recovery timestamp does not exist, the applied through is used to determine where to
// start playing oplog entries from.
opCtx->recoveryUnit()->waitUntilUnjournaledWritesDurable();
}
Status SyncSourceResolver::_chooseAndProbeNextSyncSource(OpTime earliestOpTimeSeen) {
auto candidateResult = _chooseNewSyncSource();
if (!candidateResult.isOK()) {
return _finishCallback(candidateResult);
}
if (candidateResult.getValue().empty()) {
if (earliestOpTimeSeen.isNull()) {
return _finishCallback(candidateResult);
}
SyncSourceResolverResponse response;
response.syncSourceStatus = {ErrorCodes::OplogStartMissing, "too stale to catch up"};
response.earliestOpTimeSeen = earliestOpTimeSeen;
return _finishCallback(response);
}
auto status = _scheduleFetcher(
_makeFirstOplogEntryFetcher(candidateResult.getValue(), earliestOpTimeSeen));
if (!status.isOK()) {
return _finishCallback(status);
}
return Status::OK();
}
Status waitForWriteConcern(OperationContext* txn,
const OpTime& replOpTime,
const WriteConcernOptions& writeConcern,
WriteConcernResult* result) {
// We assume all options have been validated earlier, if not, programming error
dassert(validateWriteConcern(writeConcern).isOK());
// Next handle blocking on disk
Timer syncTimer;
switch (writeConcern.syncMode) {
case WriteConcernOptions::NONE:
break;
case WriteConcernOptions::FSYNC: {
StorageEngine* storageEngine = getGlobalServiceContext()->getGlobalStorageEngine();
if (!storageEngine->isDurable()) {
result->fsyncFiles = storageEngine->flushAllFiles(true);
} else {
// We only need to commit the journal if we're durable
txn->recoveryUnit()->waitUntilDurable();
}
break;
}
case WriteConcernOptions::JOURNAL:
txn->recoveryUnit()->waitUntilDurable();
break;
}
result->syncMillis = syncTimer.millis();
// Now wait for replication
if (replOpTime.isNull()) {
// no write happened for this client yet
return Status::OK();
}
// needed to avoid incrementing gleWtimeStats SERVER-9005
if (writeConcern.wNumNodes <= 1 && writeConcern.wMode.empty()) {
// no desired replication check
return Status::OK();
}
// Now we wait for replication
// Note that replica set stepdowns and gle mode changes are thrown as errors
repl::ReplicationCoordinator::StatusAndDuration replStatus =
repl::getGlobalReplicationCoordinator()->awaitReplication(txn, replOpTime, writeConcern);
if (replStatus.status == ErrorCodes::WriteConcernFailed) {
gleWtimeouts.increment();
result->err = "timeout";
result->wTimedOut = true;
}
// Add stats
result->writtenTo = repl::getGlobalReplicationCoordinator()->getHostsWrittenTo(replOpTime);
gleWtimeStats.recordMillis(durationCount<Milliseconds>(replStatus.duration));
result->wTime = durationCount<Milliseconds>(replStatus.duration);
return replStatus.status;
}
/**
* Replays the sync target's oplog from lastOp to the latest op on the sync target.
*
* @param syncer either initial sync (can reclone missing docs) or "normal" sync (no recloning)
* @param r the oplog reader
* @param source the sync target
* @param lastOp the op to start syncing at. replset::InitialSync writes this and then moves to
* the queue. replset::SyncTail does not write this, it moves directly to the
* queue.
* @param minValid populated by this function. The most recent op on the sync target's oplog,
* this function syncs to this value (inclusive)
* @return if applying the oplog succeeded
*/
bool ReplSetImpl::_syncDoInitialSync_applyToHead( replset::SyncTail& syncer, OplogReader* r,
const Member* source, const BSONObj& lastOp ,
BSONObj& minValid ) {
/* our cloned copy will be strange until we apply oplog events that occurred
through the process. we note that time point here. */
try {
// It may have been a long time since we last used this connection to
// query the oplog, depending on the size of the databases we needed to clone.
// A common problem is that TCP keepalives are set too infrequent, and thus
// our connection here is terminated by a firewall due to inactivity.
// Solution is to increase the TCP keepalive frequency.
minValid = r->getLastOp(rsoplog);
} catch ( SocketException & ) {
log() << "connection lost to " << source->h().toString() << "; is your tcp keepalive interval set appropriately?";
if( !r->connect(source->h().toString()) ) {
sethbmsg( str::stream() << "initial sync couldn't connect to " << source->h().toString() , 0);
throw;
}
// retry
minValid = r->getLastOp(rsoplog);
}
isyncassert( "getLastOp is empty ", !minValid.isEmpty() );
OpTime mvoptime = minValid["ts"]._opTime();
verify( !mvoptime.isNull() );
OpTime startingTS = lastOp["ts"]._opTime();
verify( mvoptime >= startingTS );
// apply startingTS..mvoptime portion of the oplog
{
try {
minValid = syncer.oplogApplication(lastOp, minValid);
}
catch (const DBException&) {
log() << "replSet initial sync failed during oplog application phase" << rsLog;
emptyOplog(); // otherwise we'll be up!
lastOpTimeWritten = OpTime();
lastH = 0;
log() << "replSet cleaning up [1]" << rsLog;
{
Client::WriteContext cx( "local." );
cx.ctx().db()->flushFiles(true);
}
log() << "replSet cleaning up [2]" << rsLog;
log() << "replSet initial sync failed will try again" << endl;
sleepsecs(5);
return false;
}
}
return true;
}
/* Do we have the newest data of them all?
@param allUp - set to true if all members are up. Only set if true returned.
@return true if we are freshest. Note we may tie.
*/
bool Consensus::_weAreFreshest(bool& allUp, int& nTies) {
const OpTime ord = theReplSet->lastOpTimeWritten;
nTies = 0;
verify( !ord.isNull() );
BSONObj cmd = BSON(
"replSetFresh" << 1 <<
"set" << rs.name() <<
"opTime" << Date_t(ord.asDate()) <<
"who" << rs._self->fullName() <<
"cfgver" << rs._cfg->version <<
"id" << rs._self->id());
list<Target> L;
int ver;
/* the following queries arbiters, even though they are never fresh. wonder if that makes sense.
it doesn't, but it could, if they "know" what freshness it one day. so consider removing
arbiters from getTargets() here. although getTargets is used elsewhere for elections; there
arbiters are certainly targets - so a "includeArbs" bool would be necessary if we want to make
not fetching them herein happen.
*/
rs.getTargets(L, ver);
_multiCommand(cmd, L);
int nok = 0;
allUp = true;
for( list<Target>::iterator i = L.begin(); i != L.end(); i++ ) {
if( i->ok ) {
nok++;
if( i->result["fresher"].trueValue() ) {
log() << "not electing self, we are not freshest" << rsLog;
return false;
}
OpTime remoteOrd( i->result["opTime"].Date() );
if( remoteOrd == ord )
nTies++;
verify( remoteOrd <= ord );
if( i->result["veto"].trueValue() ) {
BSONElement msg = i->result["errmsg"];
if (!msg.eoo()) {
log() << "not electing self, " << i->toHost << " would veto with '" <<
msg.String() << "'" << rsLog;
}
else {
log() << "not electing self, " << i->toHost << " would veto" << rsLog;
}
return false;
}
}
else {
DEV log() << "replSet freshest returns " << i->result.toString() << rsLog;
allUp = false;
}
}
LOG(1) << "replSet dev we are freshest of up nodes, nok:" << nok << " nTies:" << nTies << rsLog;
verify( ord <= theReplSet->lastOpTimeWritten ); // <= as this may change while we are working...
return true;
}
void ReplSetImpl::loadLastOpTimeWritten(OperationContext* txn, bool quiet) {
Lock::DBRead lk(txn->lockState(), rsoplog);
BSONObj o;
if (Helpers::getLast(txn, rsoplog, o)) {
OpTime lastOpTime = o["ts"]._opTime();
uassert(13290, "bad replSet oplog entry?", quiet || !lastOpTime.isNull());
getGlobalReplicationCoordinator()->setMyLastOptime(txn, lastOpTime);
}
else {
getGlobalReplicationCoordinator()->setMyLastOptime(txn, OpTime());
}
}
void updateSlaveLocation( CurOp& curop, const char * ns , OpTime lastOp ){
if ( lastOp.isNull() )
return;
assert( strstr( ns , "local.oplog.$" ) == ns );
BSONObj rid = curop.getClient()->getRemoteID();
if ( rid.isEmpty() )
return;
slaveTracking.update( rid , curop.getRemoteString( false ) , ns , lastOp );
}
/**
* Replays the sync target's oplog from lastOp to the latest op on the sync target.
*
* @param syncer either initial sync (can reclone missing docs) or "normal" sync (no recloning)
* @param r the oplog reader
* @param source the sync target
* @return if applying the oplog succeeded
*/
bool ReplSetImpl::_initialSyncApplyOplog( OperationContext* ctx,
repl::SyncTail& syncer,
OplogReader* r,
const Member* source) {
const OpTime startOpTime = lastOpTimeWritten;
BSONObj lastOp;
try {
// It may have been a long time since we last used this connection to
// query the oplog, depending on the size of the databases we needed to clone.
// A common problem is that TCP keepalives are set too infrequent, and thus
// our connection here is terminated by a firewall due to inactivity.
// Solution is to increase the TCP keepalive frequency.
lastOp = r->getLastOp(rsoplog);
} catch ( SocketException & ) {
log() << "connection lost to " << source->h().toString() << "; is your tcp keepalive interval set appropriately?";
if( !r->connect(source->h()) ) {
sethbmsg( str::stream() << "initial sync couldn't connect to " << source->h().toString() , 0);
throw;
}
// retry
lastOp = r->getLastOp(rsoplog);
}
isyncassert( "lastOp is empty ", !lastOp.isEmpty() );
OpTime stopOpTime = lastOp["ts"]._opTime();
// If we already have what we need then return.
if (stopOpTime == startOpTime)
return true;
verify( !stopOpTime.isNull() );
verify( stopOpTime > startOpTime );
// apply till stopOpTime
try {
syncer.oplogApplication(ctx, stopOpTime);
}
catch (const DBException&) {
log() << "replSet initial sync failed during oplog application phase, and will retry"
<< rsLog;
lastOpTimeWritten = OpTime();
lastH = 0;
sleepsecs(5);
return false;
}
return true;
}
void ReplicationRecoveryImpl::_recoverFromStableTimestamp(OperationContext* opCtx,
Timestamp stableTimestamp,
OpTime appliedThrough,
OpTime topOfOplog) {
invariant(!stableTimestamp.isNull());
invariant(!topOfOplog.isNull());
const auto truncateAfterPoint = _consistencyMarkers->getOplogTruncateAfterPoint(opCtx);
log() << "Recovering from stable timestamp: " << stableTimestamp
<< " (top of oplog: " << topOfOplog << ", appliedThrough: " << appliedThrough
<< ", TruncateAfter: " << truncateAfterPoint << ")";
log() << "Starting recovery oplog application at the stable timestamp: " << stableTimestamp;
_applyToEndOfOplog(opCtx, stableTimestamp, topOfOplog.getTimestamp());
}
/**
* Run a query with a cursor provided by the query optimizer, or FindingStartCursor.
* @yields the db lock.
*/
string queryWithQueryOptimizer( int queryOptions, const string& ns,
const BSONObj &jsobj, CurOp& curop,
const BSONObj &query, const BSONObj &order,
const shared_ptr<ParsedQuery> &pq_shared,
const BSONObj &oldPlan,
const ChunkVersion &shardingVersionAtStart,
scoped_ptr<PageFaultRetryableSection>& parentPageFaultSection,
scoped_ptr<NoPageFaultsAllowed>& noPageFault,
Message &result ) {
const ParsedQuery &pq( *pq_shared );
shared_ptr<Cursor> cursor;
QueryPlanSummary queryPlan;
if ( pq.hasOption( QueryOption_OplogReplay ) ) {
cursor = FindingStartCursor::getCursor( ns.c_str(), query, order );
}
else {
cursor = getOptimizedCursor( ns.c_str(),
query,
order,
QueryPlanSelectionPolicy::any(),
pq_shared,
false,
&queryPlan );
}
verify( cursor );
scoped_ptr<QueryResponseBuilder> queryResponseBuilder
( QueryResponseBuilder::make( pq, cursor, queryPlan, oldPlan ) );
bool saveClientCursor = false;
OpTime slaveReadTill;
ClientCursorHolder ccPointer( new ClientCursor( QueryOption_NoCursorTimeout, cursor,
ns ) );
for( ; cursor->ok(); cursor->advance() ) {
bool yielded = false;
if ( !ccPointer->yieldSometimes( ClientCursor::MaybeCovered, &yielded ) ||
!cursor->ok() ) {
cursor.reset();
queryResponseBuilder->noteYield();
// !!! TODO The queryResponseBuilder still holds cursor. Currently it will not do
// anything unsafe with the cursor in handoff(), but this is very fragile.
//
// We don't fail the query since we're fine with returning partial data if the
// collection was dropped.
// NOTE see SERVER-2454.
// TODO This is wrong. The cursor could be gone if the closeAllDatabases command
// just ran.
break;
}
if ( yielded ) {
queryResponseBuilder->noteYield();
}
if ( pq.getMaxScan() && cursor->nscanned() > pq.getMaxScan() ) {
break;
}
if ( !queryResponseBuilder->addMatch() ) {
continue;
}
// Note slave's position in the oplog.
if ( pq.hasOption( QueryOption_OplogReplay ) ) {
BSONObj current = cursor->current();
BSONElement e = current["ts"];
if ( e.type() == Date || e.type() == Timestamp ) {
slaveReadTill = e._opTime();
}
}
if ( !cursor->supportGetMore() || pq.isExplain() ) {
if ( queryResponseBuilder->enoughTotalResults() ) {
break;
}
}
else if ( queryResponseBuilder->enoughForFirstBatch() ) {
// if only 1 requested, no cursor saved for efficiency...we assume it is findOne()
if ( pq.wantMore() && pq.getNumToReturn() != 1 ) {
queryResponseBuilder->finishedFirstBatch();
if ( cursor->advance() ) {
saveClientCursor = true;
}
}
break;
}
}
if ( cursor ) {
if ( pq.hasOption( QueryOption_CursorTailable ) && pq.getNumToReturn() != 1 ) {
cursor->setTailable();
}
// If the tailing request succeeded.
if ( cursor->tailable() ) {
saveClientCursor = true;
}
}
if ( ! shardingState.getVersion( ns ).isWriteCompatibleWith( shardingVersionAtStart ) ) {
// if the version changed during the query
// we might be missing some data
// and its safe to send this as mongos can resend
// at this point
throw SendStaleConfigException(ns, "version changed during initial query",
shardingVersionAtStart,
shardingState.getVersion(ns));
}
parentPageFaultSection.reset(0);
noPageFault.reset( new NoPageFaultsAllowed() );
int nReturned = queryResponseBuilder->handoff( result );
ccPointer.reset();
long long cursorid = 0;
if ( saveClientCursor ) {
// Create a new ClientCursor, with a default timeout.
ccPointer.reset( new ClientCursor( queryOptions, cursor, ns,
jsobj.getOwned() ) );
cursorid = ccPointer->cursorid();
DEV { MONGO_TLOG(2) << "query has more, cursorid: " << cursorid << endl; }
if ( cursor->supportYields() ) {
ClientCursor::YieldData data;
ccPointer->prepareToYield( data );
}
else {
ccPointer->c()->noteLocation();
}
// Save slave's position in the oplog.
if ( pq.hasOption( QueryOption_OplogReplay ) && !slaveReadTill.isNull() ) {
ccPointer->slaveReadTill( slaveReadTill );
}
if ( !ccPointer->ok() && ccPointer->c()->tailable() ) {
DEV {
MONGO_TLOG(0) << "query has no more but tailable, cursorid: " << cursorid <<
endl;
}
}
if( queryOptions & QueryOption_Exhaust ) {
curop.debug().exhaust = true;
}
// Set attributes for getMore.
ccPointer->setCollMetadata( queryResponseBuilder->collMetadata() );
ccPointer->setPos( nReturned );
ccPointer->pq = pq_shared;
ccPointer->fields = pq.getFieldPtr();
// If the query had a time limit, remaining time is "rolled over" to the cursor (for
// use by future getmore ops).
ccPointer->setLeftoverMaxTimeMicros( curop.getRemainingMaxTimeMicros() );
ccPointer.release();
}
void OplogReader::connectToSyncSource(OperationContext* txn,
const OpTime& lastOpTimeFetched,
ReplicationCoordinator* replCoord) {
const Timestamp sentinelTimestamp(duration_cast<Seconds>(Milliseconds(curTimeMillis64())), 0);
const OpTime sentinel(sentinelTimestamp, std::numeric_limits<long long>::max());
OpTime oldestOpTimeSeen = sentinel;
invariant(conn() == NULL);
while (true) {
HostAndPort candidate = replCoord->chooseNewSyncSource(lastOpTimeFetched.getTimestamp());
if (candidate.empty()) {
if (oldestOpTimeSeen == sentinel) {
// If, in this invocation of connectToSyncSource(), we did not successfully
// connect to any node ahead of us,
// we apparently have no sync sources to connect to.
// This situation is common; e.g. if there are no writes to the primary at
// the moment.
return;
}
// Connected to at least one member, but in all cases we were too stale to use them
// as a sync source.
error() << "too stale to catch up";
log() << "our last optime : " << lastOpTimeFetched;
log() << "oldest available is " << oldestOpTimeSeen;
log() << "See http://dochub.mongodb.org/core/resyncingaverystalereplicasetmember";
setMinValid(txn, oldestOpTimeSeen);
bool worked = replCoord->setFollowerMode(MemberState::RS_RECOVERING);
if (!worked) {
warning() << "Failed to transition into " << MemberState(MemberState::RS_RECOVERING)
<< ". Current state: " << replCoord->getMemberState();
}
return;
}
if (!connect(candidate)) {
LOG(2) << "can't connect to " << candidate.toString() << " to read operations";
resetConnection();
replCoord->blacklistSyncSource(candidate, Date_t::now() + Seconds(10));
continue;
}
// Read the first (oldest) op and confirm that it's not newer than our last
// fetched op. Otherwise, we have fallen off the back of that source's oplog.
BSONObj remoteOldestOp(findOne(rsOplogName.c_str(), Query()));
OpTime remoteOldOpTime = fassertStatusOK(28776, OpTime::parseFromBSON(remoteOldestOp));
// remoteOldOpTime may come from a very old config, so we cannot compare their terms.
if (!lastOpTimeFetched.isNull() &&
lastOpTimeFetched.getTimestamp() < remoteOldOpTime.getTimestamp()) {
// We're too stale to use this sync source.
resetConnection();
replCoord->blacklistSyncSource(candidate, Date_t::now() + Minutes(1));
if (oldestOpTimeSeen.getTimestamp() > remoteOldOpTime.getTimestamp()) {
warning() << "we are too stale to use " << candidate.toString()
<< " as a sync source";
oldestOpTimeSeen = remoteOldOpTime;
}
continue;
}
// Got a valid sync source.
return;
} // while (true)
}
void OplogReader::connectToSyncSource(OperationContext* txn,
OpTime lastOpTimeFetched,
ReplicationCoordinator* replCoord) {
const OpTime sentinel(Milliseconds(curTimeMillis64()).total_seconds(), 0);
OpTime oldestOpTimeSeen = sentinel;
invariant(conn() == NULL);
while (true) {
HostAndPort candidate = replCoord->chooseNewSyncSource(lastOpTimeFetched);
if (candidate.empty()) {
if (oldestOpTimeSeen == sentinel) {
// If, in this invocation of connectToSyncSource(), we did not successfully
// connect to any node ahead of us,
// we apparently have no sync sources to connect to.
// This situation is common; e.g. if there are no writes to the primary at
// the moment.
return;
}
// 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";
log() << "replSet our last optime : " << lastOpTimeFetched.toStringLong();
log() << "replSet oldest available is " << oldestOpTimeSeen.toStringLong();
log() << "replSet "
"See http://dochub.mongodb.org/core/resyncingaverystalereplicasetmember";
setMinValid(txn, oldestOpTimeSeen);
bool worked = replCoord->setFollowerMode(MemberState::RS_RECOVERING);
if (!worked) {
warning() << "Failed to transition into " << MemberState(MemberState::RS_RECOVERING)
<< ". Current state: " << replCoord->getMemberState();
}
return;
}
if (!connect(candidate)) {
LOG(2) << "replSet can't connect to " << candidate.toString() << " to read operations";
resetConnection();
replCoord->blacklistSyncSource(candidate, Date_t(curTimeMillis64() + 10 * 1000));
continue;
}
// Read the first (oldest) op and confirm that it's not newer than our last
// fetched op. Otherwise, we have fallen off the back of that source's oplog.
BSONObj remoteOldestOp(findOne(rsoplog, Query()));
BSONElement tsElem(remoteOldestOp["ts"]);
if (tsElem.type() != Timestamp) {
// This member's got a bad op in its oplog.
warning() << "oplog invalid format on node " << candidate.toString();
resetConnection();
replCoord->blacklistSyncSource(candidate, Date_t(curTimeMillis64() + 600 * 1000));
continue;
}
OpTime remoteOldOpTime = tsElem._opTime();
if (!lastOpTimeFetched.isNull() && lastOpTimeFetched < remoteOldOpTime) {
// We're too stale to use this sync source.
resetConnection();
replCoord->blacklistSyncSource(candidate, Date_t(curTimeMillis64() + 600 * 1000));
if (oldestOpTimeSeen > remoteOldOpTime) {
warning() << "we are too stale to use " << candidate.toString()
<< " as a sync source";
oldestOpTimeSeen = remoteOldOpTime;
}
continue;
}
// Got a valid sync source.
return;
} // while (true)
}
void ReplSetImpl::_getOplogDiagsAsHtml(unsigned server_id, stringstream& ss) const {
const Member *m = findById(server_id);
if( m == 0 ) {
ss << "Error : can't find a member with id: " << server_id << '\n';
return;
}
ss << p("Server : " + m->fullName() + "<br>ns : " + rsoplog );
//const bo fields = BSON( "o" << false << "o2" << false );
const bo fields;
/** todo fix we might want an so timeout here */
DBClientConnection conn(false, 0, /*timeout*/ 20);
{
string errmsg;
if( !conn.connect(m->fullName(), errmsg) ) {
ss << "couldn't connect to " << m->fullName() << ' ' << errmsg;
return;
}
}
auto_ptr<DBClientCursor> c = conn.query(rsoplog, Query().sort("$natural",1), 20, 0, &fields);
if( c.get() == 0 ) {
ss << "couldn't query " << rsoplog;
return;
}
static const char *h[] = {"ts","optime", "h","op","ns","rest",0};
ss << "<style type=\"text/css\" media=\"screen\">"
"table { font-size:75% }\n"
// "th { background-color:#bbb; color:#000 }\n"
// "td,th { padding:.25em }\n"
"</style>\n";
ss << table(h, true);
//ss << "<pre>\n";
int n = 0;
// we save ts as a timestamp, so even though we don't really
// use OpTimes anymore, this code is fine
OpTime otFirst;
OpTime otLast;
OpTime otEnd;
while( c->more() ) {
bo o = c->next();
otLast = o["ts"]._opTime();
if( otFirst.isNull() )
otFirst = otLast;
say(ss, o);
n++;
}
if( n == 0 ) {
ss << rsoplog << " is empty\n";
}
else {
auto_ptr<DBClientCursor> c = conn.query(rsoplog, Query().sort("$natural",-1), 20, 0, &fields);
if( c.get() == 0 ) {
ss << "couldn't query [2] " << rsoplog;
return;
}
string x;
bo o = c->next();
otEnd = o["ts"]._opTime();
while( 1 ) {
stringstream z;
if( o["ts"]._opTime() == otLast )
break;
say(z, o);
x = z.str() + x;
if( !c->more() )
break;
o = c->next();
}
if( !x.empty() ) {
ss << "<tr><td>...</td><td>...</td><td>...</td><td>...</td><td>...</td></tr>\n" << x;
//ss << "\n...\n\n" << x;
}
}
ss << _table();
ss << p(time_t_to_String_short(time(0)) + " current time");
if( !otEnd.isNull() ) {
ss << "<p>Log length in time: ";
unsigned d = otEnd.getSecs() - otFirst.getSecs();
double h = d / 3600.0;
ss.precision(3);
if( h < 72 )
ss << h << " hours";
else
ss << h / 24.0 << " days";
ss << "</p>\n";
}
}
/**
* Called by db/instance.cpp. This is the getMore entry point.
*
* pass - when QueryOption_AwaitData is in use, the caller will make repeated calls
* when this method returns an empty result, incrementing pass on each call.
* Thus, pass == 0 indicates this is the first "attempt" before any 'awaiting'.
*/
QueryResult::View newGetMore(OperationContext* txn,
const char* ns,
int ntoreturn,
long long cursorid,
CurOp& curop,
int pass,
bool& exhaust,
bool* isCursorAuthorized,
bool fromDBDirectClient) {
// For testing, we may want to fail if we receive a getmore.
if (MONGO_FAIL_POINT(failReceivedGetmore)) {
invariant(0);
}
exhaust = false;
// This is a read lock.
const NamespaceString nss(ns);
scoped_ptr<AutoGetCollectionForRead> ctx(new AutoGetCollectionForRead(txn, nss));
Collection* collection = ctx->getCollection();
uassert( 17356, "collection dropped between getMore calls", collection );
QLOG() << "Running getMore, cursorid: " << cursorid << endl;
// This checks to make sure the operation is allowed on a replicated node. Since we are not
// passing in a query object (necessary to check SlaveOK query option), the only state where
// reads are allowed is PRIMARY (or master in master/slave). This function uasserts if
// reads are not okay.
Status status = repl::getGlobalReplicationCoordinator()->checkCanServeReadsFor(
txn,
nss,
true);
uassertStatusOK(status);
// A pin performs a CC lookup and if there is a CC, increments the CC's pin value so it
// doesn't time out. Also informs ClientCursor that there is somebody actively holding the
// CC, so don't delete it.
ClientCursorPin ccPin(collection, cursorid);
ClientCursor* cc = ccPin.c();
// If we're not being called from DBDirectClient we want to associate the RecoveryUnit
// used to create the execution machinery inside the cursor with our OperationContext.
// If we throw or otherwise exit this method in a disorderly fashion, we must ensure
// that further calls to getMore won't fail, and that the provided OperationContext
// has a valid RecoveryUnit. As such, we use RAII to accomplish this.
//
// This must be destroyed before the ClientCursor is destroyed.
std::auto_ptr<ScopedRecoveryUnitSwapper> ruSwapper;
// These are set in the QueryResult msg we return.
int resultFlags = ResultFlag_AwaitCapable;
int numResults = 0;
int startingResult = 0;
const int InitialBufSize =
512 + sizeof(QueryResult::Value) + MaxBytesToReturnToClientAtOnce;
BufBuilder bb(InitialBufSize);
bb.skip(sizeof(QueryResult::Value));
if (NULL == cc) {
cursorid = 0;
resultFlags = ResultFlag_CursorNotFound;
}
else {
// Quote: check for spoofing of the ns such that it does not match the one originally
// there for the cursor
uassert(17011, "auth error", str::equals(ns, cc->ns().c_str()));
*isCursorAuthorized = true;
// Restore the RecoveryUnit if we need to.
if (fromDBDirectClient) {
if (cc->hasRecoveryUnit())
invariant(txn->recoveryUnit() == cc->getUnownedRecoveryUnit());
}
else {
if (!cc->hasRecoveryUnit()) {
// Start using a new RecoveryUnit
cc->setOwnedRecoveryUnit(
getGlobalEnvironment()->getGlobalStorageEngine()->newRecoveryUnit(txn));
}
// Swap RecoveryUnit(s) between the ClientCursor and OperationContext.
ruSwapper.reset(new ScopedRecoveryUnitSwapper(cc, txn));
}
// Reset timeout timer on the cursor since the cursor is still in use.
cc->setIdleTime(0);
// TODO: fail point?
// If the operation that spawned this cursor had a time limit set, apply leftover
// time to this getmore.
curop.setMaxTimeMicros(cc->getLeftoverMaxTimeMicros());
txn->checkForInterrupt(); // May trigger maxTimeAlwaysTimeOut fail point.
if (0 == pass) {
cc->updateSlaveLocation(txn, curop);
}
if (cc->isAggCursor) {
// Agg cursors handle their own locking internally.
ctx.reset(); // unlocks
}
CollectionMetadataPtr collMetadata = cc->getCollMetadata();
// If we're replaying the oplog, we save the last time that we read.
OpTime slaveReadTill;
// What number result are we starting at? Used to fill out the reply.
startingResult = cc->pos();
// What gives us results.
PlanExecutor* exec = cc->getExecutor();
const int queryOptions = cc->queryOptions();
// Get results out of the executor.
exec->restoreState(txn);
BSONObj obj;
PlanExecutor::ExecState state;
while (PlanExecutor::ADVANCED == (state = exec->getNext(&obj, NULL))) {
// Add result to output buffer.
bb.appendBuf((void*)obj.objdata(), obj.objsize());
// Count the result.
++numResults;
// Possibly note slave's position in the oplog.
if (queryOptions & QueryOption_OplogReplay) {
BSONElement e = obj["ts"];
if (Date == e.type() || Timestamp == e.type()) {
slaveReadTill = e._opTime();
}
}
if ((ntoreturn && numResults >= ntoreturn)
|| bb.len() > MaxBytesToReturnToClientAtOnce) {
break;
}
}
// We save the client cursor when there might be more results, and hence we may receive
// another getmore. If we receive a EOF or an error, or 'exec' is dead, then we know
// that we will not be producing more results. We indicate that the cursor is closed by
// sending a cursorId of 0 back to the client.
//
// On the other hand, if we retrieve all results necessary for this batch, then
// 'saveClientCursor' is true and we send a valid cursorId back to the client. In
// this case, there may or may not actually be more results (for example, the next call
// to getNext(...) might just return EOF).
bool saveClientCursor = false;
if (PlanExecutor::DEAD == state || PlanExecutor::EXEC_ERROR == state) {
// Propagate this error to caller.
if (PlanExecutor::EXEC_ERROR == state) {
scoped_ptr<PlanStageStats> stats(exec->getStats());
error() << "Plan executor error, stats: "
<< Explain::statsToBSON(*stats);
uasserted(17406, "getMore executor error: " +
WorkingSetCommon::toStatusString(obj));
}
// If we're dead there's no way to get more results.
saveClientCursor = false;
// In the old system tailable capped cursors would be killed off at the
// cursorid level. If a tailable capped cursor is nuked the cursorid
// would vanish.
//
// In the new system they die and are cleaned up later (or time out).
// So this is where we get to remove the cursorid.
if (0 == numResults) {
resultFlags = ResultFlag_CursorNotFound;
}
}
else if (PlanExecutor::IS_EOF == state) {
// EOF is also end of the line unless it's tailable.
saveClientCursor = queryOptions & QueryOption_CursorTailable;
}
else {
verify(PlanExecutor::ADVANCED == state);
saveClientCursor = true;
}
if (!saveClientCursor) {
ruSwapper.reset();
ccPin.deleteUnderlying();
// cc is now invalid, as is the executor
cursorid = 0;
cc = NULL;
QLOG() << "getMore NOT saving client cursor, ended with state "
<< PlanExecutor::statestr(state)
<< endl;
}
else {
// Continue caching the ClientCursor.
cc->incPos(numResults);
exec->saveState();
QLOG() << "getMore saving client cursor ended with state "
<< PlanExecutor::statestr(state)
<< endl;
if (PlanExecutor::IS_EOF == state && (queryOptions & QueryOption_CursorTailable)) {
if (!fromDBDirectClient) {
// Don't stash the RU. Get a new one on the next getMore.
ruSwapper.reset();
delete cc->releaseOwnedRecoveryUnit();
}
if ((queryOptions & QueryOption_AwaitData)
&& (numResults == 0)
&& (pass < 1000)) {
// Bubble up to the AwaitData handling code in receivedGetMore which will
// try again.
return NULL;
}
}
// Possibly note slave's position in the oplog.
if ((queryOptions & QueryOption_OplogReplay) && !slaveReadTill.isNull()) {
cc->slaveReadTill(slaveReadTill);
}
exhaust = (queryOptions & QueryOption_Exhaust);
// If the getmore had a time limit, remaining time is "rolled over" back to the
// cursor (for use by future getmore ops).
cc->setLeftoverMaxTimeMicros( curop.getRemainingMaxTimeMicros() );
}
}
QueryResult::View qr = bb.buf();
qr.msgdata().setLen(bb.len());
qr.msgdata().setOperation(opReply);
qr.setResultFlags(resultFlags);
qr.setCursorId(cursorid);
qr.setStartingFrom(startingResult);
qr.setNReturned(numResults);
bb.decouple();
QLOG() << "getMore returned " << numResults << " results\n";
return qr;
}
/**
* Also called by db/ops/query.cpp. This is the new getMore entry point.
*/
QueryResult* newGetMore(const char* ns, int ntoreturn, long long cursorid, CurOp& curop,
int pass, bool& exhaust, bool* isCursorAuthorized) {
exhaust = false;
int bufSize = 512 + sizeof(QueryResult) + MaxBytesToReturnToClientAtOnce;
BufBuilder bb(bufSize);
bb.skip(sizeof(QueryResult));
// This is a read lock. TODO: There is a cursor flag for not needing this. Do we care?
Client::ReadContext ctx(ns);
QLOG() << "running getMore in new system, cursorid " << cursorid << endl;
// This checks to make sure the operation is allowed on a replicated node. Since we are not
// passing in a query object (necessary to check SlaveOK query option), the only state where
// reads are allowed is PRIMARY (or master in master/slave). This function uasserts if
// reads are not okay.
replVerifyReadsOk();
// A pin performs a CC lookup and if there is a CC, increments the CC's pin value so it
// doesn't time out. Also informs ClientCursor that there is somebody actively holding the
// CC, so don't delete it.
ClientCursorPin ccPin(cursorid);
ClientCursor* cc = ccPin.c();
// These are set in the QueryResult msg we return.
int resultFlags = ResultFlag_AwaitCapable;
int numResults = 0;
int startingResult = 0;
if (NULL == cc) {
cursorid = 0;
resultFlags = ResultFlag_CursorNotFound;
}
else {
// Quote: check for spoofing of the ns such that it does not match the one originally
// there for the cursor
uassert(17011, "auth error", str::equals(ns, cc->ns().c_str()));
*isCursorAuthorized = true;
// TODO: fail point?
// If the operation that spawned this cursor had a time limit set, apply leftover
// time to this getmore.
curop.setMaxTimeMicros(cc->getLeftoverMaxTimeMicros());
killCurrentOp.checkForInterrupt(); // May trigger maxTimeAlwaysTimeOut fail point.
// TODO:
// curop.debug().query = BSONForQuery
// curop.setQuery(curop.debug().query);
// TODO: What is pass?
if (0 == pass) { cc->updateSlaveLocation(curop); }
CollectionMetadataPtr collMetadata = cc->getCollMetadata();
// If we're replaying the oplog, we save the last time that we read.
OpTime slaveReadTill;
// What number result are we starting at? Used to fill out the reply.
startingResult = cc->pos();
// What gives us results.
Runner* runner = cc->getRunner();
const int queryOptions = cc->queryOptions();
// Get results out of the runner.
runner->restoreState();
BSONObj obj;
Runner::RunnerState state;
while (Runner::RUNNER_ADVANCED == (state = runner->getNext(&obj, NULL))) {
// Add result to output buffer.
bb.appendBuf((void*)obj.objdata(), obj.objsize());
// Count the result.
++numResults;
// Possibly note slave's position in the oplog.
if (queryOptions & QueryOption_OplogReplay) {
BSONElement e = obj["ts"];
if (Date == e.type() || Timestamp == e.type()) {
slaveReadTill = e._opTime();
}
}
if ((ntoreturn && numResults >= ntoreturn)
|| bb.len() > MaxBytesToReturnToClientAtOnce) {
break;
}
}
if (Runner::RUNNER_EOF == state && 0 == numResults
&& (queryOptions & QueryOption_CursorTailable)
&& (queryOptions & QueryOption_AwaitData) && (pass < 1000)) {
// If the cursor is tailable we don't kill it if it's eof. We let it try to get
// data some # of times first.
return 0;
}
bool saveClientCursor = false;
if (Runner::RUNNER_DEAD == state || Runner::RUNNER_ERROR == state) {
// If we're dead there's no way to get more results.
saveClientCursor = false;
// In the old system tailable capped cursors would be killed off at the
// cursorid level. If a tailable capped cursor is nuked the cursorid
// would vanish.
//
// In the new system they die and are cleaned up later (or time out).
// So this is where we get to remove the cursorid.
if (0 == numResults) {
resultFlags = ResultFlag_CursorNotFound;
}
}
else if (Runner::RUNNER_EOF == state) {
// EOF is also end of the line unless it's tailable.
saveClientCursor = queryOptions & QueryOption_CursorTailable;
}
else {
verify(Runner::RUNNER_ADVANCED == state);
saveClientCursor = true;
}
if (!saveClientCursor) {
ccPin.deleteUnderlying();
// cc is now invalid, as is the runner
cursorid = 0;
cc = NULL;
QLOG() << "getMore NOT saving client cursor, ended w/state "
<< Runner::statestr(state)
<< endl;
}
else {
// Continue caching the ClientCursor.
cc->incPos(numResults);
runner->saveState();
QLOG() << "getMore saving client cursor ended w/state "
<< Runner::statestr(state)
<< endl;
// Possibly note slave's position in the oplog.
if ((queryOptions & QueryOption_OplogReplay) && !slaveReadTill.isNull()) {
cc->slaveReadTill(slaveReadTill);
}
exhaust = (queryOptions & QueryOption_Exhaust);
// If the getmore had a time limit, remaining time is "rolled over" back to the
// cursor (for use by future getmore ops).
cc->setLeftoverMaxTimeMicros( curop.getRemainingMaxTimeMicros() );
}
}
QueryResult* qr = reinterpret_cast<QueryResult*>(bb.buf());
qr->len = bb.len();
qr->setOperation(opReply);
qr->_resultFlags() = resultFlags;
qr->cursorId = cursorid;
qr->startingFrom = startingResult;
qr->nReturned = numResults;
bb.decouple();
QLOG() << "getMore returned " << numResults << " results\n";
return qr;
}
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;
}
bool replset::InitialSync::oplogApplication(OplogReader& r, const Member* source,
const OpTime& applyGTE, const OpTime& minValid) {
const string hn = source->fullName();
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;
int fails = 0;
while( ts < minValid ) {
try {
// There are some special cases with initial sync (see the catch block), so we
// don't want to break out of this while until we've reached minvalid. Thus, we'll
// keep trying to requery.
if( !r.more() ) {
OCCASIONALLY log() << "replSet initial sync oplog: no more records" << endl;
sleepsecs(1);
r.resetCursor();
r.tailingQueryGTE(rsoplog, theReplSet->lastOpTimeWritten);
if ( !r.haveCursor() ) {
if (fails++ > 30) {
log() << "replSet initial sync tried to query oplog 30 times, giving up" << endl;
return false;
}
}
continue;
}
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);
}
applyOp(o, applyGTE);
}
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.
// These are relatively common on initial sync: if a document is inserted
// early in the clone step, the insert will be replayed but the document
// will probably already have been cloned over.
if( e.getCode() == 11000 || e.getCode() == 11001 || e.getCode() == 12582) {
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, we'll break out of the loop and catch
// anything that's really wrong in syncTail
}
}
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;
}
/**
* This is called by db/ops/query.cpp. This is the entry point for answering a query.
*/
string newRunQuery(Message& m, QueryMessage& q, CurOp& curop, Message &result) {
log() << "Running query on new system: " << q.query.toString() << endl;
// This is a read lock.
Client::ReadContext ctx(q.ns, dbpath);
// Parse, canonicalize, plan, transcribe, and get a runner.
Runner* rawRunner;
CanonicalQuery* cq;
Status status = getRunner(q, &rawRunner, &cq);
if (!status.isOK()) {
uasserted(17007, "Couldn't process query " + q.query.toString()
+ " why: " + status.reason());
}
verify(NULL != rawRunner);
auto_ptr<Runner> runner(rawRunner);
// We freak out later if this changes before we're done with the query.
const ChunkVersion shardingVersionAtStart = shardingState.getVersion(q.ns);
// We use this a lot below.
const LiteParsedQuery& pq = cq->getParsed();
// TODO: Document why we do this.
// TODO: do this when we can pass in our own parsed query
//replVerifyReadsOk(&pq);
// If this exists, the collection is sharded.
// If it doesn't exist, we can assume we're not sharded.
// If we're sharded, we might encounter data that is not consistent with our sharding state.
// We must ignore this data.
CollectionMetadataPtr collMetadata;
if (!shardingState.needCollectionMetadata(pq.ns())) {
collMetadata = CollectionMetadataPtr();
}
else {
collMetadata = shardingState.getCollectionMetadata(pq.ns());
}
// Run the query.
BufBuilder bb(32768);
bb.skip(sizeof(QueryResult));
// How many results have we obtained from the runner?
int numResults = 0;
// If we're replaying the oplog, we save the last time that we read.
OpTime slaveReadTill;
// Do we save the Runner in a ClientCursor for getMore calls later?
bool saveClientCursor = false;
// We turn on auto-yielding for the runner here, so we must register it with the active
// runners list in ClientCursor.
ClientCursor::registerRunner(runner.get());
runner->setYieldPolicy(Runner::YIELD_AUTO);
BSONObj obj;
Runner::RunnerState state;
while (Runner::RUNNER_ADVANCED == (state = runner->getNext(&obj, NULL))) {
// If we're sharded make sure that we don't return any data that hasn't been migrated
// off of our shared yet.
if (collMetadata) {
// This information can change if we yield and as such we must make sure to re-fetch
// it if we yield.
KeyPattern kp(collMetadata->getKeyPattern());
// This performs excessive BSONObj creation but that's OK for now.
if (!collMetadata->keyBelongsToMe(kp.extractSingleKey(obj))) { continue; }
}
// Add result to output buffer.
bb.appendBuf((void*)obj.objdata(), obj.objsize());
// Count the result.
++numResults;
// Possibly note slave's position in the oplog.
if (pq.hasOption(QueryOption_OplogReplay)) {
BSONElement e = obj["ts"];
if (Date == e.type() || Timestamp == e.type()) {
slaveReadTill = e._opTime();
}
}
// TODO: only one type of 2d search doesn't support this. We need a way to pull it out
// of CanonicalQuery. :(
const bool supportsGetMore = true;
const bool isExplain = pq.isExplain();
if (isExplain && enoughForExplain(pq, numResults)) {
break;
}
else if (!supportsGetMore && (enough(pq, numResults)
|| bb.len() >= MaxBytesToReturnToClientAtOnce)) {
break;
}
else if (enoughForFirstBatch(pq, numResults, bb.len())) {
// If only one result requested assume it's a findOne() and don't save the cursor.
if (pq.wantMore() && 1 != pq.getNumToReturn()) {
saveClientCursor = true;
}
break;
}
}
// If we cache the runner later, we want to deregister it as it receives notifications
// anyway by virtue of being cached.
//
// If we don't cache the runner later, we are deleting it, so it must be deregistered.
//
// So, no matter what, deregister the runner.
ClientCursor::deregisterRunner(runner.get());
// Why save a dead runner?
if (Runner::RUNNER_DEAD == state) { saveClientCursor = false; }
// TODO: Stage creation can set tailable depending on what's in the parsed query. We have
// the full parsed query available during planning...set it there.
//
// TODO: If we're tailable we want to save the client cursor. Make sure we do this later.
//if (pq.hasOption(QueryOption_CursorTailable) && pq.getNumToReturn() != 1) { ... }
// TODO(greg): This will go away soon.
if (!shardingState.getVersion(pq.ns()).isWriteCompatibleWith(shardingVersionAtStart)) {
// if the version changed during the query we might be missing some data and its safe to
// send this as mongos can resend at this point
throw SendStaleConfigException(pq.ns(), "version changed during initial query",
shardingVersionAtStart,
shardingState.getVersion(pq.ns()));
}
long long ccId = 0;
if (saveClientCursor) {
// We won't use the runner until it's getMore'd.
runner->saveState();
// Allocate a new ClientCursor. We don't have to worry about leaking it as it's
// inserted into a global map by its ctor.
ClientCursor* cc = new ClientCursor(runner.get(), cq->getParsed().getOptions(),
cq->getParsed().getFilter());
ccId = cc->cursorid();
log() << "caching runner with cursorid " << ccId << endl;
// ClientCursor takes ownership of runner. Release to make sure it's not deleted.
runner.release();
// TODO document
if (pq.hasOption(QueryOption_OplogReplay) && !slaveReadTill.isNull()) {
cc->slaveReadTill(slaveReadTill);
}
// TODO document
if (pq.hasOption(QueryOption_Exhaust)) {
curop.debug().exhaust = true;
}
// Set attributes for getMore.
cc->setCollMetadata(collMetadata);
cc->setPos(numResults);
// If the query had a time limit, remaining time is "rolled over" to the cursor (for
// use by future getmore ops).
cc->setLeftoverMaxTimeMicros(curop.getRemainingMaxTimeMicros());
}
// Add the results from the query into the output buffer.
result.appendData(bb.buf(), bb.len());
bb.decouple();
// Fill out the output buffer's header.
QueryResult* qr = static_cast<QueryResult*>(result.header());
qr->cursorId = ccId;
curop.debug().cursorid = (0 == ccId ? -1 : ccId);
qr->setResultFlagsToOk();
qr->setOperation(opReply);
qr->startingFrom = 0;
qr->nReturned = numResults;
// TODO: nscanned is bogus.
// curop.debug().nscanned = ( cursor ? cursor->nscanned() : 0LL );
curop.debug().ntoskip = pq.getSkip();
curop.debug().nreturned = numResults;
// curop.debug().exhaust is set above.
return curop.debug().exhaust ? pq.ns() : "";
}
/**
* Also called by db/ops/query.cpp. This is the new getMore entry point.
*/
QueryResult* newGetMore(const char* ns, int ntoreturn, long long cursorid, CurOp& curop,
int pass, bool& exhaust, bool* isCursorAuthorized) {
exhaust = false;
int bufSize = 512 + sizeof(QueryResult) + MaxBytesToReturnToClientAtOnce;
BufBuilder bb(bufSize);
bb.skip(sizeof(QueryResult));
// This is a read lock. TODO: There is a cursor flag for not needing this. Do we care?
Client::ReadContext ctx(ns);
log() << "running getMore in new system, cursorid " << cursorid << endl;
// TODO: Document.
// TODO: do this when we can pass in our own parsed query
//replVerifyReadsOk();
// A pin performs a CC lookup and if there is a CC, increments the CC's pin value so it
// doesn't time out. Also informs ClientCursor that there is somebody actively holding the
// CC, so don't delete it.
ClientCursorPin ccPin(cursorid);
ClientCursor* cc = ccPin.c();
// These are set in the QueryResult msg we return.
int resultFlags = ResultFlag_AwaitCapable;
int numResults = 0;
int startingResult = 0;
if (NULL == cc) {
cursorid = 0;
resultFlags = ResultFlag_CursorNotFound;
}
else {
// Quote: check for spoofing of the ns such that it does not match the one originally
// there for the cursor
uassert(17011, "auth error", str::equals(ns, cc->ns().c_str()));
*isCursorAuthorized = true;
// TODO: fail point?
// If the operation that spawned this cursor had a time limit set, apply leftover
// time to this getmore.
curop.setMaxTimeMicros(cc->getLeftoverMaxTimeMicros());
// TODO:
// curop.debug().query = BSONForQuery
// curop.setQuery(curop.debug().query);
// TODO: What is pass?
if (0 == pass) { cc->updateSlaveLocation(curop); }
CollectionMetadataPtr collMetadata = cc->getCollMetadata();
// If we're replaying the oplog, we save the last time that we read.
OpTime slaveReadTill;
// What number result are we starting at? Used to fill out the reply.
startingResult = cc->pos();
// What gives us results.
Runner* runner = cc->getRunner();
const int queryOptions = cc->queryOptions();
// Get results out of the runner.
// TODO: There may be special handling required for tailable cursors?
runner->restoreState();
BSONObj obj;
Runner::RunnerState state;
while (Runner::RUNNER_ADVANCED == (state = runner->getNext(&obj, NULL))) {
// If we're sharded make sure that we don't return any data that hasn't been
// migrated off of our shard yet.
if (collMetadata) {
KeyPattern kp(collMetadata->getKeyPattern());
if (!collMetadata->keyBelongsToMe(kp.extractSingleKey(obj))) { continue; }
}
// Add result to output buffer.
bb.appendBuf((void*)obj.objdata(), obj.objsize());
// Count the result.
++numResults;
// Possibly note slave's position in the oplog.
if (queryOptions & QueryOption_OplogReplay) {
BSONElement e = obj["ts"];
if (Date == e.type() || Timestamp == e.type()) {
slaveReadTill = e._opTime();
}
}
if ((numResults && numResults >= ntoreturn)
|| bb.len() > MaxBytesToReturnToClientAtOnce) {
break;
}
}
if (Runner::RUNNER_DEAD == state || Runner::RUNNER_EOF == state) {
log() << "getMore(): runner with id " << cursorid << " EOF/DEAD, state = "
<< static_cast<int>(state) << endl;
// TODO: If the cursor is tailable we don't kill it if it's eof.
ccPin.free();
// cc is now invalid, as is the runner
cursorid = 0;
cc = NULL;
}
else {
// Continue caching the ClientCursor.
cc->incPos(numResults);
runner->saveState();
// Possibly note slave's position in the oplog.
if ((queryOptions & QueryOption_OplogReplay) && !slaveReadTill.isNull()) {
cc->slaveReadTill(slaveReadTill);
}
exhaust = (queryOptions & QueryOption_Exhaust);
// If the getmore had a time limit, remaining time is "rolled over" back to the
// cursor (for use by future getmore ops).
cc->setLeftoverMaxTimeMicros( curop.getRemainingMaxTimeMicros() );
}
}
QueryResult* qr = reinterpret_cast<QueryResult*>(bb.buf());
qr->len = bb.len();
qr->setOperation(opReply);
qr->_resultFlags() = resultFlags;
qr->cursorId = cursorid;
qr->startingFrom = startingResult;
qr->nReturned = numResults;
bb.decouple();
return qr;
}
bool run(OperationContext* txn, const string& dbname,
BSONObj& cmdObj,
int,
string& errmsg,
BSONObjBuilder& result,
bool fromRepl ) {
//
// Correct behavior here is very finicky.
//
// 1. The first step is to append the error that occurred on the previous operation.
// This adds an "err" field to the command, which is *not* the command failing.
//
// 2. Next we parse and validate write concern options. If these options are invalid
// the command fails no matter what, even if we actually had an error earlier. The
// reason for checking here is to match legacy behavior on these kind of failures -
// we'll still get an "err" field for the write error.
//
// 3. If we had an error on the previous operation, we then return immediately.
//
// 4. Finally, we actually enforce the write concern. All errors *except* timeout are
// reported with ok : 0.0, to match legacy behavior.
//
// There is a special case when "wOpTime" and "wElectionId" are explicitly provided by
// the client (mongos) - in this case we *only* enforce the write concern if it is
// valid.
//
// We always need to either report "err" (if ok : 1) or "errmsg" (if ok : 0), even if
// err is null.
//
LastError *le = lastError.disableForCommand();
// Always append lastOp and connectionId
Client& c = *txn->getClient();
if (repl::getGlobalReplicationCoordinator()->getReplicationMode() ==
repl::ReplicationCoordinator::modeReplSet) {
const OpTime lastOp = repl::ReplClientInfo::forClient(c).getLastOp();
if (!lastOp.isNull()) {
result.append("lastOp", lastOp);
}
}
// for sharding; also useful in general for debugging
result.appendNumber( "connectionId" , c.getConnectionId() );
OpTime lastOpTime;
BSONField<OpTime> wOpTimeField("wOpTime");
FieldParser::FieldState extracted = FieldParser::extract(cmdObj, wOpTimeField,
&lastOpTime, &errmsg);
if (!extracted) {
result.append("badGLE", cmdObj);
appendCommandStatus(result, false, errmsg);
return false;
}
bool lastOpTimePresent = extracted != FieldParser::FIELD_NONE;
if (!lastOpTimePresent) {
// Use the client opTime if no wOpTime is specified
lastOpTime = repl::ReplClientInfo::forClient(c).getLastOp();
}
OID electionId;
BSONField<OID> wElectionIdField("wElectionId");
extracted = FieldParser::extract(cmdObj, wElectionIdField,
&electionId, &errmsg);
if (!extracted) {
result.append("badGLE", cmdObj);
appendCommandStatus(result, false, errmsg);
return false;
}
bool electionIdPresent = extracted != FieldParser::FIELD_NONE;
bool errorOccurred = false;
// Errors aren't reported when wOpTime is used
if ( !lastOpTimePresent ) {
if ( le->nPrev != 1 ) {
errorOccurred = LastError::noError.appendSelf( result, false );
le->appendSelfStatus( result );
}
else {
errorOccurred = le->appendSelf( result, false );
}
}
BSONObj writeConcernDoc = cmdObj;
// Use the default options if we have no gle options aside from wOpTime/wElectionId
const int nFields = cmdObj.nFields();
bool useDefaultGLEOptions = (nFields == 1) ||
(nFields == 2 && lastOpTimePresent) ||
(nFields == 3 && lastOpTimePresent && electionIdPresent);
WriteConcernOptions writeConcern;
if (useDefaultGLEOptions) {
writeConcern = repl::getGlobalReplicationCoordinator()->getGetLastErrorDefault();
}
Status status = writeConcern.parse( writeConcernDoc );
//
// Validate write concern no matter what, this matches 2.4 behavior
//
if ( status.isOK() ) {
// Ensure options are valid for this host
status = validateWriteConcern( writeConcern );
}
if ( !status.isOK() ) {
result.append( "badGLE", writeConcernDoc );
return appendCommandStatus( result, status );
}
// Don't wait for replication if there was an error reported - this matches 2.4 behavior
if ( errorOccurred ) {
dassert( !lastOpTimePresent );
return true;
}
// No error occurred, so we won't duplicate these fields with write concern errors
dassert( result.asTempObj()["err"].eoo() );
dassert( result.asTempObj()["code"].eoo() );
// If we got an electionId, make sure it matches
if (electionIdPresent) {
if (repl::getGlobalReplicationCoordinator()->getReplicationMode() !=
repl::ReplicationCoordinator::modeReplSet) {
// Ignore electionIds of 0 from mongos.
if (electionId != OID()) {
errmsg = "wElectionId passed but no replication active";
result.append("code", ErrorCodes::BadValue);
return false;
}
}
else {
if (electionId != repl::getGlobalReplicationCoordinator()->getElectionId()) {
LOG(3) << "oid passed in is " << electionId
<< ", but our id is "
<< repl::getGlobalReplicationCoordinator()->getElectionId();
errmsg = "election occurred after write";
result.append("code", ErrorCodes::WriteConcernFailed);
return false;
}
}
}
txn->setWriteConcern(writeConcern);
txn->setMessage( "waiting for write concern" );
WriteConcernResult wcResult;
status = waitForWriteConcern( txn, lastOpTime, &wcResult );
wcResult.appendTo( writeConcern, &result );
// For backward compatibility with 2.4, wtimeout returns ok : 1.0
if ( wcResult.wTimedOut ) {
dassert( !wcResult.err.empty() ); // so we always report err
dassert( !status.isOK() );
result.append( "errmsg", "timed out waiting for slaves" );
result.append( "code", status.code() );
return true;
}
return appendCommandStatus( result, status );
}
void SyncSourceResolver::_firstOplogEntryFetcherCallback(
const StatusWith<Fetcher::QueryResponse>& queryResult,
HostAndPort candidate,
OpTime earliestOpTimeSeen) {
if (_isShuttingDown()) {
_finishCallback(Status(ErrorCodes::CallbackCanceled,
str::stream()
<< "sync source resolver shut down while probing candidate: "
<< candidate));
return;
}
if (ErrorCodes::CallbackCanceled == queryResult.getStatus()) {
_finishCallback(queryResult.getStatus());
return;
}
if (!queryResult.isOK()) {
// We got an error.
const auto until = _taskExecutor->now() + kFetcherErrorBlacklistDuration;
log() << "Blacklisting " << candidate << " due to error: '" << queryResult.getStatus()
<< "' for " << kFetcherErrorBlacklistDuration << " until: " << until;
_syncSourceSelector->blacklistSyncSource(candidate, until);
_chooseAndProbeNextSyncSource(earliestOpTimeSeen);
return;
}
const auto& queryResponse = queryResult.getValue();
const auto remoteEarliestOpTime = _parseRemoteEarliestOpTime(candidate, queryResponse);
if (remoteEarliestOpTime.isNull()) {
_chooseAndProbeNextSyncSource(earliestOpTimeSeen);
return;
}
// remoteEarliestOpTime may come from a very old config, so we cannot compare their terms.
if (_lastOpTimeFetched.getTimestamp() < remoteEarliestOpTime.getTimestamp()) {
// We're too stale to use this sync source.
const auto blacklistDuration = kTooStaleBlacklistDuration;
const auto until = _taskExecutor->now() + Minutes(1);
log() << "We are too stale to use " << candidate << " as a sync source. "
<< "Blacklisting this sync source"
<< " because our last fetched timestamp: " << _lastOpTimeFetched.getTimestamp()
<< " is before their earliest timestamp: " << remoteEarliestOpTime.getTimestamp()
<< " for " << blacklistDuration << " until: " << until;
_syncSourceSelector->blacklistSyncSource(candidate, until);
// If all the viable sync sources are too far ahead of us (i.e. we are "too stale" relative
// each sync source), we will want to return the starting timestamp of the sync source
// candidate that is closest to us. See SyncSourceResolverResponse::earliestOpTimeSeen.
// We use "earliestOpTimeSeen" to keep track of the current minimum starting timestamp.
if (earliestOpTimeSeen.isNull() ||
earliestOpTimeSeen.getTimestamp() > remoteEarliestOpTime.getTimestamp()) {
earliestOpTimeSeen = remoteEarliestOpTime;
}
_chooseAndProbeNextSyncSource(earliestOpTimeSeen);
return;
}
// Schedules fetcher to look for '_requiredOpTime' in the remote oplog.
if (!_requiredOpTime.isNull()) {
auto status = _scheduleFetcher(_makeRequiredOpTimeFetcher(candidate, earliestOpTimeSeen));
if (!status.isOK()) {
_finishCallback(status);
}
return;
}
_finishCallback(candidate);
}
/**
* Also called by db/ops/query.cpp. This is the new getMore entry point.
*/
QueryResult* newGetMore(const char* ns, int ntoreturn, long long cursorid, CurOp& curop,
int pass, bool& exhaust, bool* isCursorAuthorized) {
exhaust = false;
int bufSize = 512 + sizeof(QueryResult) + MaxBytesToReturnToClientAtOnce;
BufBuilder bb(bufSize);
bb.skip(sizeof(QueryResult));
// This is a read lock. TODO: There is a cursor flag for not needing this. Do we care?
Client::ReadContext ctx(ns);
// TODO: Document.
replVerifyReadsOk();
ClientCursorPin ccPin(cursorid);
ClientCursor* cc = ccPin.c();
// These are set in the QueryResult msg we return.
int resultFlags = ResultFlag_AwaitCapable;
int numResults = 0;
int startingResult = 0;
if (NULL == cc) {
cursorid = 0;
resultFlags = ResultFlag_CursorNotFound;
}
else {
// Quote: check for spoofing of the ns such that it does not match the one originally
// there for the cursor
uassert(17011, "auth error", str::equals(ns, cc->ns().c_str()));
*isCursorAuthorized = true;
// TODO: fail point?
// If the operation that spawned this cursor had a time limit set, apply leftover
// time to this getmore.
curop.setMaxTimeMicros(cc->getLeftoverMaxTimeMicros());
// TODO:
// curop.debug().query = BSONForQuery
// curop.setQuery(curop.debug().query);
// TODO: What is pass?
if (0 == pass) { cc->updateSlaveLocation(curop); }
CollectionMetadataPtr collMetadata = cc->getCollMetadata();
// If we're replaying the oplog, we save the last time that we read.
OpTime slaveReadTill;
startingResult = cc->pos();
Runner* runner = cc->getRunner();
const ParsedQuery& pq = runner->getQuery().getParsed();
// Get results out of the runner.
// TODO: There may be special handling required for tailable cursors?
runner->restoreState();
BSONObj obj;
// TODO: Differentiate EOF from error.
while (runner->getNext(&obj)) {
// If we're sharded make sure that we don't return any data that hasn't been
// migrated off of our shard yet.
if (collMetadata) {
KeyPattern kp(collMetadata->getKeyPattern());
if (!collMetadata->keyBelongsToMe(kp.extractSingleKey(obj))) { continue; }
}
// Add result to output buffer.
bb.appendBuf((void*)obj.objdata(), obj.objsize());
// Count the result.
++numResults;
// Possibly note slave's position in the oplog.
if (pq.hasOption(QueryOption_OplogReplay)) {
BSONElement e = obj["ts"];
if (Date == e.type() || Timestamp == e.type()) {
slaveReadTill = e._opTime();
}
}
if ((numResults && numResults >= ntoreturn)
|| bb.len() > MaxBytesToReturnToClientAtOnce) {
break;
}
}
cc->incPos(numResults);
runner->saveState();
// Possibly note slave's position in the oplog.
if (pq.hasOption(QueryOption_OplogReplay) && !slaveReadTill.isNull()) {
cc->slaveReadTill(slaveReadTill);
}
exhaust = pq.hasOption(QueryOption_Exhaust);
// If the getmore had a time limit, remaining time is "rolled over" back to the
// cursor (for use by future getmore ops).
cc->setLeftoverMaxTimeMicros( curop.getRemainingMaxTimeMicros() );
}
QueryResult* qr = reinterpret_cast<QueryResult*>(bb.buf());
qr->len = bb.len();
qr->setOperation(opReply);
qr->_resultFlags() = resultFlags;
qr->cursorId = cursorid;
qr->startingFrom = startingResult;
qr->nReturned = numResults;
bb.decouple();
return qr;
}
/**
* Do the initial sync for this member.
*/
void ReplSetImpl::_syncDoInitialSync() {
sethbmsg("initial sync pending",0);
// if this is the first node, it may have already become primary
if ( box.getState().primary() ) {
sethbmsg("I'm already primary, no need for initial sync",0);
return;
}
const Member *source = getMemberToSyncTo();
if (!source) {
sethbmsg("initial sync need a member to be primary or secondary to do our initial sync", 0);
sleepsecs(15);
return;
}
string sourceHostname = source->h().toString();
OplogReader r;
if( !r.connect(sourceHostname) ) {
sethbmsg( str::stream() << "initial sync couldn't connect to " << source->h().toString() , 0);
sleepsecs(15);
return;
}
BSONObj lastOp = r.getLastOp(rsoplog);
if( lastOp.isEmpty() ) {
sethbmsg("initial sync couldn't read remote oplog", 0);
sleepsecs(15);
return;
}
OpTime startingTS = lastOp["ts"]._opTime();
if (replSettings.fastsync) {
log() << "fastsync: skipping database clone" << rsLog;
}
else {
sethbmsg("initial sync drop all databases", 0);
dropAllDatabasesExceptLocal();
sethbmsg("initial sync clone all databases", 0);
list<string> dbs = r.conn()->getDatabaseNames();
for( list<string>::iterator i = dbs.begin(); i != dbs.end(); i++ ) {
string db = *i;
if( db != "local" ) {
sethbmsg( str::stream() << "initial sync cloning db: " << db , 0);
bool ok;
{
writelock lk(db);
Client::Context ctx(db);
ok = clone(sourceHostname.c_str(), db);
}
if( !ok ) {
sethbmsg( str::stream() << "initial sync error clone of " << db << " failed sleeping 5 minutes" ,0);
sleepsecs(300);
return;
}
}
}
}
sethbmsg("initial sync query minValid",0);
isyncassert( "initial sync source must remain readable throughout our initial sync", source->state().readable() );
/* our cloned copy will be strange until we apply oplog events that occurred
through the process. we note that time point here. */
BSONObj minValid = r.getLastOp(rsoplog);
isyncassert( "getLastOp is empty ", !minValid.isEmpty() );
OpTime mvoptime = minValid["ts"]._opTime();
assert( !mvoptime.isNull() );
/* apply relevant portion of the oplog
*/
{
isyncassert( str::stream() << "initial sync source must remain readable throughout our initial sync [2] state now: " << source->state().toString() , source->state().readable() );
if( ! initialSyncOplogApplication(source, /*applyGTE*/startingTS, /*minValid*/mvoptime) ) { // note we assume here that this call does not throw
log() << "replSet initial sync failed during applyoplog" << rsLog;
emptyOplog(); // otherwise we'll be up!
lastOpTimeWritten = OpTime();
lastH = 0;
log() << "replSet cleaning up [1]" << rsLog;
{
writelock lk("local.");
Client::Context cx( "local." );
cx.db()->flushFiles(true);
}
log() << "replSet cleaning up [2]" << rsLog;
sleepsecs(5);
return;
}
}
sethbmsg("initial sync finishing up",0);
assert( !box.getState().primary() ); // wouldn't make sense if we were.
{
writelock lk("local.");
Client::Context cx( "local." );
cx.db()->flushFiles(true);
try {
log() << "replSet set minValid=" << minValid["ts"]._opTime().toString() << rsLog;
}
catch(...) { }
Helpers::putSingleton("local.replset.minvalid", minValid);
cx.db()->flushFiles(true);
}
sethbmsg("initial sync done",0);
}
/**
* This is called by db/ops/query.cpp. This is the entry point for answering a query.
*/
std::string newRunQuery(CanonicalQuery* cq, CurOp& curop, Message &result) {
QLOG() << "Running query on new system: " << cq->toString();
// This is a read lock.
Client::ReadContext ctx(cq->ns(), storageGlobalParams.dbpath);
// Parse, canonicalize, plan, transcribe, and get a runner.
Runner* rawRunner = NULL;
// We use this a lot below.
const LiteParsedQuery& pq = cq->getParsed();
// Need to call cq->toString() now, since upon error getRunner doesn't guarantee
// cq is in a consistent state.
string cqStr = cq->toString();
// We'll now try to get the query runner that will execute this query for us. There
// are a few cases in which we know upfront which runner we should get and, therefore,
// we shortcut the selection process here.
//
// (a) If the query is over a collection that doesn't exist, we get a special runner
// that's is so (a runner) which doesn't return results, the EOFRunner.
//
// (b) if the query is a replication's initial sync one, we get a SingleSolutinRunner
// that uses a specifically designed stage that skips extents faster (see details in
// exec/oplogstart.h)
//
// Otherwise we go through the selection of which runner is most suited to the
// query + run-time context at hand.
Status status = Status::OK();
if (ctx.ctx().db()->getCollection(cq->ns()) == NULL) {
rawRunner = new EOFRunner(cq, cq->ns());
}
else if (pq.hasOption(QueryOption_OplogReplay)) {
status = getOplogStartHack(cq, &rawRunner);
}
else {
// Takes ownership of cq.
size_t options = QueryPlannerParams::DEFAULT;
if (shardingState.needCollectionMetadata(pq.ns())) {
options |= QueryPlannerParams::INCLUDE_SHARD_FILTER;
}
status = getRunner(cq, &rawRunner, options);
}
if (!status.isOK()) {
uasserted(17007, "Couldn't get runner for query because: " + status.reason() + " query is " + cqStr);
}
verify(NULL != rawRunner);
auto_ptr<Runner> runner(rawRunner);
// We freak out later if this changes before we're done with the query.
const ChunkVersion shardingVersionAtStart = shardingState.getVersion(cq->ns());
// Handle query option $maxTimeMS (not used with commands).
curop.setMaxTimeMicros(static_cast<unsigned long long>(pq.getMaxTimeMS()) * 1000);
killCurrentOp.checkForInterrupt(); // May trigger maxTimeAlwaysTimeOut fail point.
// uassert if we are not on a primary, and not a secondary with SlaveOk query parameter set.
replVerifyReadsOk(&pq);
// If this exists, the collection is sharded.
// If it doesn't exist, we can assume we're not sharded.
// If we're sharded, we might encounter data that is not consistent with our sharding state.
// We must ignore this data.
CollectionMetadataPtr collMetadata;
if (!shardingState.needCollectionMetadata(pq.ns())) {
collMetadata = CollectionMetadataPtr();
}
else {
collMetadata = shardingState.getCollectionMetadata(pq.ns());
}
// Run the query.
// bb is used to hold query results
// this buffer should contain either requested documents per query or
// explain information, but not both
BufBuilder bb(32768);
bb.skip(sizeof(QueryResult));
// How many results have we obtained from the runner?
int numResults = 0;
// If we're replaying the oplog, we save the last time that we read.
OpTime slaveReadTill;
// Do we save the Runner in a ClientCursor for getMore calls later?
bool saveClientCursor = false;
// We turn on auto-yielding for the runner here. The runner registers itself with the
// active runners list in ClientCursor.
ClientCursor::registerRunner(runner.get());
runner->setYieldPolicy(Runner::YIELD_AUTO);
auto_ptr<DeregisterEvenIfUnderlyingCodeThrows> safety(
new DeregisterEvenIfUnderlyingCodeThrows(runner.get()));
BSONObj obj;
Runner::RunnerState state;
// uint64_t numMisplacedDocs = 0;
// set this outside loop. we will need to use this both within loop and when deciding
// to fill in explain information
const bool isExplain = pq.isExplain();
while (Runner::RUNNER_ADVANCED == (state = runner->getNext(&obj, NULL))) {
// Add result to output buffer. This is unnecessary if explain info is requested
if (!isExplain) {
bb.appendBuf((void*)obj.objdata(), obj.objsize());
}
// Count the result.
++numResults;
// Possibly note slave's position in the oplog.
if (pq.hasOption(QueryOption_OplogReplay)) {
BSONElement e = obj["ts"];
if (Date == e.type() || Timestamp == e.type()) {
slaveReadTill = e._opTime();
}
}
// TODO: only one type of 2d search doesn't support this. We need a way to pull it out
// of CanonicalQuery. :(
const bool supportsGetMore = true;
if (isExplain) {
if (enoughForExplain(pq, numResults)) {
break;
}
}
else if (!supportsGetMore && (enough(pq, numResults)
|| bb.len() >= MaxBytesToReturnToClientAtOnce)) {
break;
}
else if (enoughForFirstBatch(pq, numResults, bb.len())) {
QLOG() << "Enough for first batch, wantMore=" << pq.wantMore()
<< " numToReturn=" << pq.getNumToReturn()
<< " numResults=" << numResults
<< endl;
// If only one result requested assume it's a findOne() and don't save the cursor.
if (pq.wantMore() && 1 != pq.getNumToReturn()) {
QLOG() << " runner EOF=" << runner->isEOF() << endl;
saveClientCursor = !runner->isEOF();
}
break;
}
}
// If we cache the runner later, we want to deregister it as it receives notifications
// anyway by virtue of being cached.
//
// If we don't cache the runner later, we are deleting it, so it must be deregistered.
//
// So, no matter what, deregister the runner.
safety.reset();
// Caller expects exceptions thrown in certain cases:
// * in-memory sort using too much RAM.
if (Runner::RUNNER_ERROR == state) {
uasserted(17144, "Runner error, memory limit for sort probably exceeded");
}
// Why save a dead runner?
if (Runner::RUNNER_DEAD == state) {
saveClientCursor = false;
}
else if (pq.hasOption(QueryOption_CursorTailable)) {
// If we're tailing a capped collection, we don't bother saving the cursor if the
// collection is empty. Otherwise, the semantics of the tailable cursor is that the
// client will keep trying to read from it. So we'll keep it around.
Collection* collection = ctx.ctx().db()->getCollection(cq->ns());
if (collection && collection->numRecords() != 0 && pq.getNumToReturn() != 1) {
saveClientCursor = true;
}
}
// TODO(greg): This will go away soon.
if (!shardingState.getVersion(pq.ns()).isWriteCompatibleWith(shardingVersionAtStart)) {
// if the version changed during the query we might be missing some data and its safe to
// send this as mongos can resend at this point
throw SendStaleConfigException(pq.ns(), "version changed during initial query",
shardingVersionAtStart,
shardingState.getVersion(pq.ns()));
}
// Append explain information to query results by asking the runner to produce them.
if (isExplain) {
TypeExplain* bareExplain;
Status res = runner->getExplainPlan(&bareExplain);
if (!res.isOK()) {
error() << "could not produce explain of query '" << pq.getFilter()
<< "', error: " << res.reason();
// If numResults and the data in bb don't correspond, we'll crash later when rooting
// through the reply msg.
BSONObj emptyObj;
bb.appendBuf((void*)emptyObj.objdata(), emptyObj.objsize());
// The explain output is actually a result.
numResults = 1;
// TODO: we can fill out millis etc. here just fine even if the plan screwed up.
}
else {
boost::scoped_ptr<TypeExplain> explain(bareExplain);
// Fill in the missing run-time fields in explain, starting with propeties of
// the process running the query.
std::string server = mongoutils::str::stream()
<< getHostNameCached() << ":" << serverGlobalParams.port;
explain->setServer(server);
// We might have skipped some results due to chunk migration etc. so our count is
// correct.
explain->setN(numResults);
// Clock the whole operation.
explain->setMillis(curop.elapsedMillis());
BSONObj explainObj = explain->toBSON();
bb.appendBuf((void*)explainObj.objdata(), explainObj.objsize());
// The explain output is actually a result.
numResults = 1;
}
}
long long ccId = 0;
if (saveClientCursor) {
// We won't use the runner until it's getMore'd.
runner->saveState();
// Allocate a new ClientCursor. We don't have to worry about leaking it as it's
// inserted into a global map by its ctor.
ClientCursor* cc = new ClientCursor(runner.get(), cq->getParsed().getOptions(),
cq->getParsed().getFilter());
ccId = cc->cursorid();
QLOG() << "caching runner with cursorid " << ccId
<< " after returning " << numResults << " results" << endl;
// ClientCursor takes ownership of runner. Release to make sure it's not deleted.
runner.release();
// TODO document
if (pq.hasOption(QueryOption_OplogReplay) && !slaveReadTill.isNull()) {
cc->slaveReadTill(slaveReadTill);
}
// TODO document
if (pq.hasOption(QueryOption_Exhaust)) {
curop.debug().exhaust = true;
}
// Set attributes for getMore.
cc->setCollMetadata(collMetadata);
cc->setPos(numResults);
// If the query had a time limit, remaining time is "rolled over" to the cursor (for
// use by future getmore ops).
cc->setLeftoverMaxTimeMicros(curop.getRemainingMaxTimeMicros());
}
else {
QLOG() << "not caching runner but returning " << numResults << " results\n";
}
// Add the results from the query into the output buffer.
result.appendData(bb.buf(), bb.len());
bb.decouple();
// Fill out the output buffer's header.
QueryResult* qr = static_cast<QueryResult*>(result.header());
qr->cursorId = ccId;
curop.debug().cursorid = (0 == ccId ? -1 : ccId);
qr->setResultFlagsToOk();
qr->setOperation(opReply);
qr->startingFrom = 0;
qr->nReturned = numResults;
curop.debug().ntoskip = pq.getSkip();
curop.debug().nreturned = numResults;
// curop.debug().exhaust is set above.
return curop.debug().exhaust ? pq.ns() : "";
}
virtual int doRun() {
// authenticate
enum Auth::Level authLevel = Auth::NONE;
auth("", &authLevel);
uassert(15935, "user does not have write access", authLevel == Auth::WRITE);
boost::filesystem::path root = getParam("dir");
// check if we're actually talking to a machine that can write
if (!isMaster()) {
return -1;
}
if (isMongos() && _db == "" && exists(root / "config")) {
log() << "Cannot do a full restore on a sharded system" << endl;
return -1;
}
_drop = hasParam( "drop" );
_keepIndexVersion = hasParam("keepIndexVersion");
_restoreOptions = !hasParam("noOptionsRestore");
_restoreIndexes = !hasParam("noIndexRestore");
_w = getParam( "w" , 1 );
bool doOplog = hasParam( "oplogReplay" );
if (doOplog) {
// fail early if errors
if (_db != "") {
log() << "Can only replay oplog on full restore" << endl;
return -1;
}
if ( ! exists(root / "oplog.bson") ) {
log() << "No oplog file to replay. Make sure you run mongodump with --oplog." << endl;
return -1;
}
BSONObj out;
if (! conn().simpleCommand("admin", &out, "buildinfo")) {
log() << "buildinfo command failed: " << out["errmsg"].String() << endl;
return -1;
}
StringData version = out["version"].valuestr();
if (versionCmp(version, "1.7.4-pre-") < 0) {
log() << "Can only replay oplog to server version >= 1.7.4" << endl;
return -1;
}
string oplogLimit = getParam( "oplogLimit", "" );
string oplogInc = "0";
if(!oplogLimit.empty()) {
size_t i = oplogLimit.find_first_of(':');
if ( i != string::npos ) {
if ( i + 1 < oplogLimit.length() ) {
oplogInc = oplogLimit.substr(i + 1);
}
oplogLimit = oplogLimit.substr(0, i);
}
try {
_oplogLimitTS.reset(new OpTime(
boost::lexical_cast<unsigned long>(oplogLimit.c_str()),
boost::lexical_cast<unsigned long>(oplogInc.c_str())));
} catch( const boost::bad_lexical_cast& error) {
log() << "Could not parse oplogLimit into Timestamp from values ( "
<< oplogLimit << " , " << oplogInc << " )"
<< endl;
return -1;
}
if (!oplogLimit.empty()) {
// Only for a replica set as master will have no-op entries so we would need to
// skip them all to find the real op
scoped_ptr<DBClientCursor> cursor(
conn().query("local.oplog.rs", Query().sort(BSON("$natural" << -1)),
1 /*return first*/));
OpTime tsOptime;
// get newest oplog entry and make sure it is older than the limit to apply.
if (cursor->more()) {
tsOptime = cursor->next().getField("ts")._opTime();
if (tsOptime > *_oplogLimitTS.get()) {
log() << "The oplogLimit is not newer than"
<< " the last oplog entry on the server."
<< endl;
return -1;
}
}
BSONObjBuilder tsRestrictBldr;
if (!tsOptime.isNull())
tsRestrictBldr.appendTimestamp("$gt", tsOptime.asDate());
tsRestrictBldr.appendTimestamp("$lt", _oplogLimitTS->asDate());
BSONObj query = BSON("ts" << tsRestrictBldr.obj());
if (!tsOptime.isNull()) {
log() << "Latest oplog entry on the server is " << tsOptime.getSecs()
<< ":" << tsOptime.getInc() << endl;
log() << "Only applying oplog entries matching this criteria: "
<< query.jsonString() << endl;
}
_opmatcher.reset(new Matcher(query));
}
}
}
/* If _db is not "" then the user specified a db name to restore as.
*
* In that case we better be given either a root directory that
* contains only .bson files or a single .bson file (a db).
*
* In the case where a collection name is specified we better be
* given either a root directory that contains only a single
* .bson file, or a single .bson file itself (a collection).
*/
drillDown(root, _db != "", _coll != "", !(_oplogLimitTS.get() == NULL), true);
// should this happen for oplog replay as well?
conn().getLastError(_db == "" ? "admin" : _db);
if (doOplog) {
log() << "\t Replaying oplog" << endl;
_curns = OPLOG_SENTINEL;
processFile( root / "oplog.bson" );
log() << "Applied " << _oplogEntryApplies << " oplog entries out of "
<< _oplogEntryApplies + _oplogEntrySkips << " (" << _oplogEntrySkips
<< " skipped)." << endl;
}
return EXIT_CLEAN;
}
std::string newRunQuery(OperationContext* txn,
Message& m,
QueryMessage& q,
CurOp& curop,
Message &result,
bool fromDBDirectClient) {
// Validate the namespace.
const char *ns = q.ns;
uassert(16332, "can't have an empty ns", ns[0]);
const NamespaceString nsString(ns);
uassert(16256, str::stream() << "Invalid ns [" << ns << "]", nsString.isValid());
// Set curop information.
curop.debug().ns = ns;
curop.debug().ntoreturn = q.ntoreturn;
curop.debug().query = q.query;
curop.setQuery(q.query);
// If the query is really a command, run it.
if (nsString.isCommand()) {
int nToReturn = q.ntoreturn;
uassert(16979, str::stream() << "bad numberToReturn (" << nToReturn
<< ") for $cmd type ns - can only be 1 or -1",
nToReturn == 1 || nToReturn == -1);
curop.markCommand();
BufBuilder bb;
bb.skip(sizeof(QueryResult::Value));
BSONObjBuilder cmdResBuf;
if (!runCommands(txn, ns, q.query, curop, bb, cmdResBuf, false, q.queryOptions)) {
uasserted(13530, "bad or malformed command request?");
}
curop.debug().iscommand = true;
// TODO: Does this get overwritten/do we really need to set this twice?
curop.debug().query = q.query;
QueryResult::View qr = bb.buf();
bb.decouple();
qr.setResultFlagsToOk();
qr.msgdata().setLen(bb.len());
curop.debug().responseLength = bb.len();
qr.msgdata().setOperation(opReply);
qr.setCursorId(0);
qr.setStartingFrom(0);
qr.setNReturned(1);
result.setData(qr.view2ptr(), true);
return "";
}
const NamespaceString nss(q.ns);
// Parse the qm into a CanonicalQuery.
CanonicalQuery* cq;
Status canonStatus = CanonicalQuery::canonicalize(
q, &cq, WhereCallbackReal(txn, StringData(nss.db())));
if (!canonStatus.isOK()) {
uasserted(17287, str::stream() << "Can't canonicalize query: " << canonStatus.toString());
}
QLOG() << "Running query:\n" << cq->toString();
LOG(2) << "Running query: " << cq->toStringShort();
// Parse, canonicalize, plan, transcribe, and get a plan executor.
PlanExecutor* rawExec = NULL;
// We use this a lot below.
const LiteParsedQuery& pq = cq->getParsed();
AutoGetCollectionForRead ctx(txn, nss);
const int dbProfilingLevel = (ctx.getDb() != NULL) ? ctx.getDb()->getProfilingLevel() :
serverGlobalParams.defaultProfile;
Collection* collection = ctx.getCollection();
// We'll now try to get the query executor that will execute this query for us. There
// are a few cases in which we know upfront which executor we should get and, therefore,
// we shortcut the selection process here.
//
// (a) If the query is over a collection that doesn't exist, we use an EOFStage.
//
// (b) if the query is a replication's initial sync one, we use a specifically designed
// stage that skips extents faster (see details in exec/oplogstart.h).
//
// Otherwise we go through the selection of which executor is most suited to the
// query + run-time context at hand.
Status status = Status::OK();
if (NULL != collection && pq.getOptions().oplogReplay) {
// Takes ownership of 'cq'.
status = getOplogStartHack(txn, collection, cq, &rawExec);
}
else {
size_t options = QueryPlannerParams::DEFAULT;
if (shardingState.needCollectionMetadata(pq.ns())) {
options |= QueryPlannerParams::INCLUDE_SHARD_FILTER;
}
// Takes ownership of 'cq'.
status = getExecutor(txn, collection, cq, PlanExecutor::YIELD_AUTO, &rawExec, options);
}
if (!status.isOK()) {
// NOTE: Do not access cq as getExecutor has deleted it.
uasserted(17007, "Unable to execute query: " + status.reason());
}
verify(NULL != rawExec);
auto_ptr<PlanExecutor> exec(rawExec);
// If it's actually an explain, do the explain and return rather than falling through
// to the normal query execution loop.
if (pq.isExplain()) {
BufBuilder bb;
bb.skip(sizeof(QueryResult::Value));
BSONObjBuilder explainBob;
Explain::explainStages(exec.get(), ExplainCommon::EXEC_ALL_PLANS, &explainBob);
// Add the resulting object to the return buffer.
BSONObj explainObj = explainBob.obj();
bb.appendBuf((void*)explainObj.objdata(), explainObj.objsize());
curop.debug().iscommand = true;
// TODO: Does this get overwritten/do we really need to set this twice?
curop.debug().query = q.query;
// Set query result fields.
QueryResult::View qr = bb.buf();
bb.decouple();
qr.setResultFlagsToOk();
qr.msgdata().setLen(bb.len());
curop.debug().responseLength = bb.len();
qr.msgdata().setOperation(opReply);
qr.setCursorId(0);
qr.setStartingFrom(0);
qr.setNReturned(1);
result.setData(qr.view2ptr(), true);
return "";
}
// We freak out later if this changes before we're done with the query.
const ChunkVersion shardingVersionAtStart = shardingState.getVersion(cq->ns());
// Handle query option $maxTimeMS (not used with commands).
curop.setMaxTimeMicros(static_cast<unsigned long long>(pq.getMaxTimeMS()) * 1000);
txn->checkForInterrupt(); // May trigger maxTimeAlwaysTimeOut fail point.
// uassert if we are not on a primary, and not a secondary with SlaveOk query parameter set.
bool slaveOK = pq.getOptions().slaveOk || pq.hasReadPref();
status = repl::getGlobalReplicationCoordinator()->checkCanServeReadsFor(
txn,
NamespaceString(cq->ns()),
slaveOK);
uassertStatusOK(status);
// If this exists, the collection is sharded.
// If it doesn't exist, we can assume we're not sharded.
// If we're sharded, we might encounter data that is not consistent with our sharding state.
// We must ignore this data.
CollectionMetadataPtr collMetadata;
if (!shardingState.needCollectionMetadata(pq.ns())) {
collMetadata = CollectionMetadataPtr();
}
else {
collMetadata = shardingState.getCollectionMetadata(pq.ns());
}
// Run the query.
// bb is used to hold query results
// this buffer should contain either requested documents per query or
// explain information, but not both
BufBuilder bb(32768);
bb.skip(sizeof(QueryResult::Value));
// How many results have we obtained from the executor?
int numResults = 0;
// If we're replaying the oplog, we save the last time that we read.
OpTime slaveReadTill;
// Do we save the PlanExecutor in a ClientCursor for getMore calls later?
bool saveClientCursor = false;
BSONObj obj;
PlanExecutor::ExecState state;
// uint64_t numMisplacedDocs = 0;
// Get summary info about which plan the executor is using.
curop.debug().planSummary = Explain::getPlanSummary(exec.get());
while (PlanExecutor::ADVANCED == (state = exec->getNext(&obj, NULL))) {
// Add result to output buffer.
bb.appendBuf((void*)obj.objdata(), obj.objsize());
// Count the result.
++numResults;
// Possibly note slave's position in the oplog.
if (pq.getOptions().oplogReplay) {
BSONElement e = obj["ts"];
if (Date == e.type() || Timestamp == e.type()) {
slaveReadTill = e._opTime();
}
}
// TODO: only one type of 2d search doesn't support this. We need a way to pull it out
// of CanonicalQuery. :(
const bool supportsGetMore = true;
if (!supportsGetMore && (enough(pq, numResults)
|| bb.len() >= MaxBytesToReturnToClientAtOnce)) {
break;
}
else if (enoughForFirstBatch(pq, numResults, bb.len())) {
QLOG() << "Enough for first batch, wantMore=" << pq.wantMore()
<< " numToReturn=" << pq.getNumToReturn()
<< " numResults=" << numResults
<< endl;
// If only one result requested assume it's a findOne() and don't save the cursor.
if (pq.wantMore() && 1 != pq.getNumToReturn()) {
QLOG() << " executor EOF=" << exec->isEOF() << endl;
saveClientCursor = !exec->isEOF();
}
break;
}
}
// If we cache the executor later, we want to deregister it as it receives notifications
// anyway by virtue of being cached.
//
// If we don't cache the executor later, we are deleting it, so it must be deregistered.
//
// So, no matter what, deregister the executor.
exec->deregisterExec();
// Caller expects exceptions thrown in certain cases.
if (PlanExecutor::EXEC_ERROR == state) {
scoped_ptr<PlanStageStats> stats(exec->getStats());
error() << "Plan executor error, stats: "
<< Explain::statsToBSON(*stats);
uasserted(17144, "Executor error: " + WorkingSetCommon::toStatusString(obj));
}
// Why save a dead executor?
if (PlanExecutor::DEAD == state) {
saveClientCursor = false;
}
else if (pq.getOptions().tailable) {
// If we're tailing a capped collection, we don't bother saving the cursor if the
// collection is empty. Otherwise, the semantics of the tailable cursor is that the
// client will keep trying to read from it. So we'll keep it around.
if (collection && collection->numRecords(txn) != 0 && pq.getNumToReturn() != 1) {
saveClientCursor = true;
}
}
// TODO(greg): This will go away soon.
if (!shardingState.getVersion(pq.ns()).isWriteCompatibleWith(shardingVersionAtStart)) {
// if the version changed during the query we might be missing some data and its safe to
// send this as mongos can resend at this point
throw SendStaleConfigException(pq.ns(), "version changed during initial query",
shardingVersionAtStart,
shardingState.getVersion(pq.ns()));
}
const logger::LogComponent queryLogComponent = logger::LogComponent::kQuery;
const logger::LogSeverity logLevelOne = logger::LogSeverity::Debug(1);
PlanSummaryStats summaryStats;
Explain::getSummaryStats(exec.get(), &summaryStats);
curop.debug().ntoskip = pq.getSkip();
curop.debug().nreturned = numResults;
curop.debug().scanAndOrder = summaryStats.hasSortStage;
curop.debug().nscanned = summaryStats.totalKeysExamined;
curop.debug().nscannedObjects = summaryStats.totalDocsExamined;
curop.debug().idhack = summaryStats.isIdhack;
// Set debug information for consumption by the profiler.
if (dbProfilingLevel > 0 ||
curop.elapsedMillis() > serverGlobalParams.slowMS ||
logger::globalLogDomain()->shouldLog(queryLogComponent, logLevelOne)) {
// Get BSON stats.
scoped_ptr<PlanStageStats> execStats(exec->getStats());
BSONObjBuilder statsBob;
Explain::statsToBSON(*execStats, &statsBob);
curop.debug().execStats.set(statsBob.obj());
// Replace exec stats with plan summary if stats cannot fit into CachedBSONObj.
if (curop.debug().execStats.tooBig() && !curop.debug().planSummary.empty()) {
BSONObjBuilder bob;
bob.append("summary", curop.debug().planSummary.toString());
curop.debug().execStats.set(bob.done());
}
}
long long ccId = 0;
if (saveClientCursor) {
// We won't use the executor until it's getMore'd.
exec->saveState();
// Allocate a new ClientCursor. We don't have to worry about leaking it as it's
// inserted into a global map by its ctor.
ClientCursor* cc = new ClientCursor(collection, exec.get(),
cq->getParsed().getOptions().toInt(),
cq->getParsed().getFilter());
ccId = cc->cursorid();
if (fromDBDirectClient) {
cc->setUnownedRecoveryUnit(txn->recoveryUnit());
}
else if (state == PlanExecutor::IS_EOF && pq.getOptions().tailable) {
// Don't stash the RU for tailable cursors at EOF, let them get a new RU on their
// next getMore.
}
else {
// We stash away the RecoveryUnit in the ClientCursor. It's used for subsequent
// getMore requests. The calling OpCtx gets a fresh RecoveryUnit.
cc->setOwnedRecoveryUnit(txn->releaseRecoveryUnit());
StorageEngine* storageEngine = getGlobalEnvironment()->getGlobalStorageEngine();
txn->setRecoveryUnit(storageEngine->newRecoveryUnit(txn));
}
QLOG() << "caching executor with cursorid " << ccId
<< " after returning " << numResults << " results" << endl;
// ClientCursor takes ownership of executor. Release to make sure it's not deleted.
exec.release();
// TODO document
if (pq.getOptions().oplogReplay && !slaveReadTill.isNull()) {
cc->slaveReadTill(slaveReadTill);
}
// TODO document
if (pq.getOptions().exhaust) {
curop.debug().exhaust = true;
}
// Set attributes for getMore.
cc->setCollMetadata(collMetadata);
cc->setPos(numResults);
// If the query had a time limit, remaining time is "rolled over" to the cursor (for
// use by future getmore ops).
cc->setLeftoverMaxTimeMicros(curop.getRemainingMaxTimeMicros());
}
else {
QLOG() << "Not caching executor but returning " << numResults << " results.\n";
}
// Add the results from the query into the output buffer.
result.appendData(bb.buf(), bb.len());
bb.decouple();
// Fill out the output buffer's header.
QueryResult::View qr = result.header().view2ptr();
qr.setCursorId(ccId);
curop.debug().cursorid = (0 == ccId ? -1 : ccId);
qr.setResultFlagsToOk();
qr.msgdata().setOperation(opReply);
qr.setStartingFrom(0);
qr.setNReturned(numResults);
// curop.debug().exhaust is set above.
return curop.debug().exhaust ? pq.ns() : "";
}
/* 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;
}
/**
* Run a query with a cursor provided by the query optimizer, or FindingStartCursor.
* @yields the db lock.
*/
const char *queryWithQueryOptimizer( Message &m, int queryOptions, const char *ns,
const BSONObj &jsobj, CurOp& curop,
const BSONObj &query, const BSONObj &order,
const shared_ptr<ParsedQuery> &pq_shared,
const BSONObj &oldPlan,
const ConfigVersion &shardingVersionAtStart,
Message &result ) {
const ParsedQuery &pq( *pq_shared );
shared_ptr<Cursor> cursor;
QueryPlanSummary queryPlan;
if ( pq.hasOption( QueryOption_OplogReplay ) ) {
cursor = FindingStartCursor::getCursor( ns, query, order );
}
else {
cursor =
NamespaceDetailsTransient::getCursor( ns, query, order, QueryPlanSelectionPolicy::any(),
0, pq_shared, &queryPlan );
}
verify( cursor );
QueryResponseBuilder queryResponseBuilder( pq, cursor, queryPlan, oldPlan );
bool saveClientCursor = false;
const char *exhaust = 0;
OpTime slaveReadTill;
ClientCursor::CleanupPointer ccPointer;
ccPointer.reset( new ClientCursor( QueryOption_NoCursorTimeout, cursor, ns ) );
for( ; cursor->ok(); cursor->advance() ) {
bool yielded = false;
if ( !ccPointer->yieldSometimes( ClientCursor::MaybeCovered, &yielded ) ||
!cursor->ok() ) {
cursor.reset();
queryResponseBuilder.noteYield();
// !!! TODO The queryResponseBuilder still holds cursor. Currently it will not do
// anything unsafe with the cursor in handoff(), but this is very fragile.
//
// We don't fail the query since we're fine with returning partial data if the
// collection was dropped.
// NOTE see SERVER-2454.
// TODO This is wrong. The cursor could be gone if the closeAllDatabases command
// just ran.
break;
}
if ( yielded ) {
queryResponseBuilder.noteYield();
}
if ( pq.getMaxScan() && cursor->nscanned() > pq.getMaxScan() ) {
break;
}
if ( !queryResponseBuilder.addMatch() ) {
continue;
}
// Note slave's position in the oplog.
if ( pq.hasOption( QueryOption_OplogReplay ) ) {
BSONObj current = cursor->current();
BSONElement e = current["ts"];
if ( e.type() == Date || e.type() == Timestamp ) {
slaveReadTill = e._opTime();
}
}
if ( !cursor->supportGetMore() || pq.isExplain() ) {
if ( queryResponseBuilder.enoughTotalResults() ) {
break;
}
}
else if ( queryResponseBuilder.enoughForFirstBatch() ) {
// if only 1 requested, no cursor saved for efficiency...we assume it is findOne()
if ( pq.wantMore() && pq.getNumToReturn() != 1 ) {
queryResponseBuilder.finishedFirstBatch();
if ( cursor->advance() ) {
saveClientCursor = true;
}
}
break;
}
}
if ( cursor ) {
if ( pq.hasOption( QueryOption_CursorTailable ) && pq.getNumToReturn() != 1 ) {
cursor->setTailable();
}
// If the tailing request succeeded.
if ( cursor->tailable() ) {
saveClientCursor = true;
}
}
if ( shardingState.getVersion( ns ) != shardingVersionAtStart ) {
// if the version changed during the query
// we might be missing some data
// and its safe to send this as mongos can resend
// at this point
throw SendStaleConfigException( ns , "version changed during initial query", shardingVersionAtStart, shardingState.getVersion( ns ) );
}
int nReturned = queryResponseBuilder.handoff( result );
ccPointer.reset();
long long cursorid = 0;
if ( saveClientCursor ) {
// Create a new ClientCursor, with a default timeout.
ccPointer.reset( new ClientCursor( queryOptions, cursor, ns,
jsobj.getOwned() ) );
cursorid = ccPointer->cursorid();
DEV tlog(2) << "query has more, cursorid: " << cursorid << endl;
if ( cursor->supportYields() ) {
ClientCursor::YieldData data;
ccPointer->prepareToYield( data );
}
else {
ccPointer->c()->noteLocation();
}
// !!! Save the original message buffer, so it can be referenced in getMore.
ccPointer->originalMessage = m;
// Save slave's position in the oplog.
if ( pq.hasOption( QueryOption_OplogReplay ) && !slaveReadTill.isNull() ) {
ccPointer->slaveReadTill( slaveReadTill );
}
if ( !ccPointer->ok() && ccPointer->c()->tailable() ) {
DEV tlog() << "query has no more but tailable, cursorid: " << cursorid << endl;
}
if( queryOptions & QueryOption_Exhaust ) {
exhaust = ns;
curop.debug().exhaust = true;
}
// Set attributes for getMore.
ccPointer->setChunkManager( queryResponseBuilder.chunkManager() );
ccPointer->setPos( nReturned );
ccPointer->pq = pq_shared;
ccPointer->fields = pq.getFieldPtr();
ccPointer.release();
}
QueryResult *qr = (QueryResult *) result.header();
qr->cursorId = cursorid;
curop.debug().cursorid = ( cursorid == 0 ? -1 : qr->cursorId );
qr->setResultFlagsToOk();
// qr->len is updated automatically by appendData()
curop.debug().responseLength = qr->len;
qr->setOperation(opReply);
qr->startingFrom = 0;
qr->nReturned = nReturned;
int duration = curop.elapsedMillis();
bool dbprofile = curop.shouldDBProfile( duration );
if ( dbprofile || duration >= cmdLine.slowMS ) {
curop.debug().nscanned = (int)( cursor ? cursor->nscanned() : 0 );
curop.debug().ntoskip = pq.getSkip();
}
curop.debug().nreturned = nReturned;
return exhaust;
}
std::string newRunQuery(Message& m, QueryMessage& q, CurOp& curop, Message &result) {
// Validate the namespace.
const char *ns = q.ns;
uassert(16332, "can't have an empty ns", ns[0]);
const NamespaceString nsString(ns);
uassert(16256, str::stream() << "Invalid ns [" << ns << "]", nsString.isValid());
// Set curop information.
curop.debug().ns = ns;
curop.debug().ntoreturn = q.ntoreturn;
curop.debug().query = q.query;
curop.setQuery(q.query);
// If the query is really a command, run it.
if (nsString.isCommand()) {
int nToReturn = q.ntoreturn;
uassert(16979, str::stream() << "bad numberToReturn (" << nToReturn
<< ") for $cmd type ns - can only be 1 or -1",
nToReturn == 1 || nToReturn == -1);
curop.markCommand();
BufBuilder bb;
bb.skip(sizeof(QueryResult));
BSONObjBuilder cmdResBuf;
if (!runCommands(ns, q.query, curop, bb, cmdResBuf, false, q.queryOptions)) {
uasserted(13530, "bad or malformed command request?");
}
curop.debug().iscommand = true;
// TODO: Does this get overwritten/do we really need to set this twice?
curop.debug().query = q.query;
QueryResult* qr = reinterpret_cast<QueryResult*>(bb.buf());
bb.decouple();
qr->setResultFlagsToOk();
qr->len = bb.len();
curop.debug().responseLength = bb.len();
qr->setOperation(opReply);
qr->cursorId = 0;
qr->startingFrom = 0;
qr->nReturned = 1;
result.setData(qr, true);
return "";
}
// This is a read lock. We require this because if we're parsing a $where, the
// where-specific parsing code assumes we have a lock and creates execution machinery that
// requires it.
Client::ReadContext ctx(q.ns);
Collection* collection = ctx.ctx().db()->getCollection( ns );
// Parse the qm into a CanonicalQuery.
CanonicalQuery* cq;
Status canonStatus = CanonicalQuery::canonicalize(q, &cq);
if (!canonStatus.isOK()) {
uasserted(17287, str::stream() << "Can't canonicalize query: " << canonStatus.toString());
}
verify(cq);
QLOG() << "Running query:\n" << cq->toString();
LOG(2) << "Running query: " << cq->toStringShort();
// Parse, canonicalize, plan, transcribe, and get a runner.
Runner* rawRunner = NULL;
// We use this a lot below.
const LiteParsedQuery& pq = cq->getParsed();
// We'll now try to get the query runner that will execute this query for us. There
// are a few cases in which we know upfront which runner we should get and, therefore,
// we shortcut the selection process here.
//
// (a) If the query is over a collection that doesn't exist, we get a special runner
// that's is so (a runner) which doesn't return results, the EOFRunner.
//
// (b) if the query is a replication's initial sync one, we get a SingleSolutinRunner
// that uses a specifically designed stage that skips extents faster (see details in
// exec/oplogstart.h)
//
// Otherwise we go through the selection of which runner is most suited to the
// query + run-time context at hand.
Status status = Status::OK();
if (collection == NULL) {
rawRunner = new EOFRunner(cq, cq->ns());
}
else if (pq.hasOption(QueryOption_OplogReplay)) {
status = getOplogStartHack(collection, cq, &rawRunner);
}
else {
// Takes ownership of cq.
size_t options = QueryPlannerParams::DEFAULT;
if (shardingState.needCollectionMetadata(pq.ns())) {
options |= QueryPlannerParams::INCLUDE_SHARD_FILTER;
}
status = getRunner(cq, &rawRunner, options);
}
if (!status.isOK()) {
// NOTE: Do not access cq as getRunner has deleted it.
uasserted(17007, "Unable to execute query: " + status.reason());
}
verify(NULL != rawRunner);
auto_ptr<Runner> runner(rawRunner);
// We freak out later if this changes before we're done with the query.
const ChunkVersion shardingVersionAtStart = shardingState.getVersion(cq->ns());
// Handle query option $maxTimeMS (not used with commands).
curop.setMaxTimeMicros(static_cast<unsigned long long>(pq.getMaxTimeMS()) * 1000);
killCurrentOp.checkForInterrupt(); // May trigger maxTimeAlwaysTimeOut fail point.
// uassert if we are not on a primary, and not a secondary with SlaveOk query parameter set.
replVerifyReadsOk(&pq);
// If this exists, the collection is sharded.
// If it doesn't exist, we can assume we're not sharded.
// If we're sharded, we might encounter data that is not consistent with our sharding state.
// We must ignore this data.
CollectionMetadataPtr collMetadata;
if (!shardingState.needCollectionMetadata(pq.ns())) {
collMetadata = CollectionMetadataPtr();
}
else {
collMetadata = shardingState.getCollectionMetadata(pq.ns());
}
// Run the query.
// bb is used to hold query results
// this buffer should contain either requested documents per query or
// explain information, but not both
BufBuilder bb(32768);
bb.skip(sizeof(QueryResult));
// How many results have we obtained from the runner?
int numResults = 0;
// If we're replaying the oplog, we save the last time that we read.
OpTime slaveReadTill;
// Do we save the Runner in a ClientCursor for getMore calls later?
bool saveClientCursor = false;
// We turn on auto-yielding for the runner here. The runner registers itself with the
// active runners list in ClientCursor.
auto_ptr<ScopedRunnerRegistration> safety(new ScopedRunnerRegistration(runner.get()));
runner->setYieldPolicy(Runner::YIELD_AUTO);
BSONObj obj;
Runner::RunnerState state;
// uint64_t numMisplacedDocs = 0;
// set this outside loop. we will need to use this both within loop and when deciding
// to fill in explain information
const bool isExplain = pq.isExplain();
// Have we retrieved info about which plan the runner will
// use to execute the query yet?
bool gotPlanInfo = false;
PlanInfo* rawInfo;
boost::scoped_ptr<PlanInfo> planInfo;
while (Runner::RUNNER_ADVANCED == (state = runner->getNext(&obj, NULL))) {
// Add result to output buffer. This is unnecessary if explain info is requested
if (!isExplain) {
bb.appendBuf((void*)obj.objdata(), obj.objsize());
}
// Count the result.
++numResults;
// In the case of the multi plan runner, we may not be able to
// successfully retrieve plan info until after the query starts
// to run. This is because the multi plan runner doesn't know what
// plan it will end up using until it runs candidates and selects
// the best.
//
// TODO: Do we ever want to output what the MPR is comparing?
if (!gotPlanInfo) {
Status infoStatus = runner->getInfo(NULL, &rawInfo);
if (infoStatus.isOK()) {
gotPlanInfo = true;
planInfo.reset(rawInfo);
// planSummary is really a ThreadSafeString which copies the data from
// the provided pointer.
curop.debug().planSummary = planInfo->planSummary.c_str();
}
}
// Possibly note slave's position in the oplog.
if (pq.hasOption(QueryOption_OplogReplay)) {
BSONElement e = obj["ts"];
if (Date == e.type() || Timestamp == e.type()) {
slaveReadTill = e._opTime();
}
}
// TODO: only one type of 2d search doesn't support this. We need a way to pull it out
// of CanonicalQuery. :(
const bool supportsGetMore = true;
if (isExplain) {
if (enoughForExplain(pq, numResults)) {
break;
}
}
else if (!supportsGetMore && (enough(pq, numResults)
|| bb.len() >= MaxBytesToReturnToClientAtOnce)) {
break;
}
else if (enoughForFirstBatch(pq, numResults, bb.len())) {
QLOG() << "Enough for first batch, wantMore=" << pq.wantMore()
<< " numToReturn=" << pq.getNumToReturn()
<< " numResults=" << numResults
<< endl;
// If only one result requested assume it's a findOne() and don't save the cursor.
if (pq.wantMore() && 1 != pq.getNumToReturn()) {
QLOG() << " runner EOF=" << runner->isEOF() << endl;
saveClientCursor = !runner->isEOF();
}
break;
}
}
// Try to get information about the plan which the runner
// will use to execute the query, it we don't have it already.
if (!gotPlanInfo) {
Status infoStatus = runner->getInfo(NULL, &rawInfo);
if (infoStatus.isOK()) {
gotPlanInfo = true;
planInfo.reset(rawInfo);
// planSummary is really a ThreadSafeString which copies the data from
// the provided pointer.
curop.debug().planSummary = planInfo->planSummary.c_str();
}
}
// If we cache the runner later, we want to deregister it as it receives notifications
// anyway by virtue of being cached.
//
// If we don't cache the runner later, we are deleting it, so it must be deregistered.
//
// So, no matter what, deregister the runner.
safety.reset();
// Caller expects exceptions thrown in certain cases.
if (Runner::RUNNER_ERROR == state) {
TypeExplain* bareExplain;
Status res = runner->getInfo(&bareExplain, NULL);
if (res.isOK()) {
boost::scoped_ptr<TypeExplain> errorExplain(bareExplain);
error() << "Runner error, stats:\n"
<< errorExplain->stats.jsonString(Strict, true);
}
uasserted(17144, "Runner error: " + WorkingSetCommon::toStatusString(obj));
}
// Why save a dead runner?
if (Runner::RUNNER_DEAD == state) {
saveClientCursor = false;
}
else if (pq.hasOption(QueryOption_CursorTailable)) {
// If we're tailing a capped collection, we don't bother saving the cursor if the
// collection is empty. Otherwise, the semantics of the tailable cursor is that the
// client will keep trying to read from it. So we'll keep it around.
Collection* collection = ctx.ctx().db()->getCollection(cq->ns());
if (collection && collection->numRecords() != 0 && pq.getNumToReturn() != 1) {
saveClientCursor = true;
}
}
// TODO(greg): This will go away soon.
if (!shardingState.getVersion(pq.ns()).isWriteCompatibleWith(shardingVersionAtStart)) {
// if the version changed during the query we might be missing some data and its safe to
// send this as mongos can resend at this point
throw SendStaleConfigException(pq.ns(), "version changed during initial query",
shardingVersionAtStart,
shardingState.getVersion(pq.ns()));
}
// Used to fill in explain and to determine if the query is slow enough to be logged.
int elapsedMillis = curop.elapsedMillis();
// Get explain information if:
// 1) it is needed by an explain query;
// 2) profiling is enabled; or
// 3) profiling is disabled but we still need explain details to log a "slow" query.
// Producing explain information is expensive and should be done only if we are certain
// the information will be used.
boost::scoped_ptr<TypeExplain> explain(NULL);
if (isExplain ||
ctx.ctx().db()->getProfilingLevel() > 0 ||
elapsedMillis > serverGlobalParams.slowMS) {
// Ask the runner to produce explain information.
TypeExplain* bareExplain;
Status res = runner->getInfo(&bareExplain, NULL);
if (res.isOK()) {
explain.reset(bareExplain);
}
else if (isExplain) {
error() << "could not produce explain of query '" << pq.getFilter()
<< "', error: " << res.reason();
// If numResults and the data in bb don't correspond, we'll crash later when rooting
// through the reply msg.
BSONObj emptyObj;
bb.appendBuf((void*)emptyObj.objdata(), emptyObj.objsize());
// The explain output is actually a result.
numResults = 1;
// TODO: we can fill out millis etc. here just fine even if the plan screwed up.
}
}
// Fill in the missing run-time fields in explain, starting with propeties of
// the process running the query.
if (isExplain && NULL != explain.get()) {
std::string server = mongoutils::str::stream()
<< getHostNameCached() << ":" << serverGlobalParams.port;
explain->setServer(server);
// We might have skipped some results due to chunk migration etc. so our count is
// correct.
explain->setN(numResults);
// Clock the whole operation.
explain->setMillis(elapsedMillis);
BSONObj explainObj = explain->toBSON();
bb.appendBuf((void*)explainObj.objdata(), explainObj.objsize());
// The explain output is actually a result.
numResults = 1;
}
long long ccId = 0;
if (saveClientCursor) {
// We won't use the runner until it's getMore'd.
runner->saveState();
// Allocate a new ClientCursor. We don't have to worry about leaking it as it's
// inserted into a global map by its ctor.
ClientCursor* cc = new ClientCursor(collection, runner.get(),
cq->getParsed().getOptions(),
cq->getParsed().getFilter());
ccId = cc->cursorid();
QLOG() << "caching runner with cursorid " << ccId
<< " after returning " << numResults << " results" << endl;
// ClientCursor takes ownership of runner. Release to make sure it's not deleted.
runner.release();
// TODO document
if (pq.hasOption(QueryOption_OplogReplay) && !slaveReadTill.isNull()) {
cc->slaveReadTill(slaveReadTill);
}
// TODO document
if (pq.hasOption(QueryOption_Exhaust)) {
curop.debug().exhaust = true;
}
// Set attributes for getMore.
cc->setCollMetadata(collMetadata);
cc->setPos(numResults);
// If the query had a time limit, remaining time is "rolled over" to the cursor (for
// use by future getmore ops).
cc->setLeftoverMaxTimeMicros(curop.getRemainingMaxTimeMicros());
}
else {
QLOG() << "Not caching runner but returning " << numResults << " results.\n";
}
// Add the results from the query into the output buffer.
result.appendData(bb.buf(), bb.len());
bb.decouple();
// Fill out the output buffer's header.
QueryResult* qr = static_cast<QueryResult*>(result.header());
qr->cursorId = ccId;
curop.debug().cursorid = (0 == ccId ? -1 : ccId);
qr->setResultFlagsToOk();
qr->setOperation(opReply);
qr->startingFrom = 0;
qr->nReturned = numResults;
// Set debug information for consumption by the profiler.
curop.debug().ntoskip = pq.getSkip();
curop.debug().nreturned = numResults;
if (NULL != explain.get()) {
if (explain->isScanAndOrderSet()) {
curop.debug().scanAndOrder = explain->getScanAndOrder();
}
else {
curop.debug().scanAndOrder = false;
}
if (explain->isNScannedSet()) {
curop.debug().nscanned = explain->getNScanned();
}
if (explain->isNScannedObjectsSet()) {
curop.debug().nscannedObjects = explain->getNScannedObjects();
}
if (explain->isIDHackSet()) {
curop.debug().idhack = explain->getIDHack();
}
if (!explain->stats.isEmpty()) {
// execStats is a CachedBSONObj because it lives in the race-prone
// curop.
curop.debug().execStats.set(explain->stats);
// Replace exec stats with plan summary if stats cannot fit into CachedBSONObj.
if (curop.debug().execStats.tooBig() && !curop.debug().planSummary.empty()) {
BSONObjBuilder bob;
bob.append("summary", curop.debug().planSummary.toString());
curop.debug().execStats.set(bob.done());
}
}
}
// curop.debug().exhaust is set above.
return curop.debug().exhaust ? pq.ns() : "";
}