BSONObj CurOp::description() {
BSONObjBuilder bob;
bool a = _active && _start;
bob.append("active", a);
bob.append( "op" , opToString( _op ) );
bob.append("ns", _ns.toString());
if (_op == dbInsert) {
_query.append(bob, "insert");
}
else {
_query.append(bob, "query");
}
if( killPending() )
bob.append("killPending", true);
return bob.obj();
}
void profile(OperationContext* txn, const Client& c, int op, CurOp& currentOp) {
bool tryAgain = false;
while ( 1 ) {
try {
// initialize with 1kb to start, to avoid realloc later
// doing this outside the dblock to improve performance
BufBuilder profileBufBuilder(1024);
// NOTE: It's kind of weird that we lock the op's namespace, but have to for now
// since we're sometimes inside the lock already
const string dbname(nsToDatabase(currentOp.getNS()));
scoped_ptr<Lock::DBLock> lk;
// todo: this can be slow, perhaps can re-work
if ( !txn->lockState()->isDbLockedForMode( dbname, MODE_IX ) ) {
lk.reset( new Lock::DBLock( txn->lockState(),
dbname,
tryAgain ? MODE_X : MODE_IX) );
}
Database* db = dbHolder().get(txn, dbname);
if (db != NULL) {
Lock::CollectionLock clk(txn->lockState(), db->getProfilingNS(), MODE_X);
Client::Context cx(txn, currentOp.getNS(), false);
if ( !_profile(txn, c, cx.db(), currentOp, profileBufBuilder ) && lk.get() ) {
if ( tryAgain ) {
// we couldn't profile, but that's ok, we should have logged already
break;
}
// we took an IX lock, so now we try again with an X lock
tryAgain = true;
continue;
}
}
else {
mongo::log() << "note: not profiling because db went away - "
<< "probably a close on: " << currentOp.getNS();
}
return;
}
catch (const AssertionException& assertionEx) {
warning() << "Caught Assertion while trying to profile " << opToString(op)
<< " against " << currentOp.getNS()
<< ": " << assertionEx.toString() << endl;
return;
}
}
}
BSONObj CurOp::description() {
BSONObjBuilder bob;
bool a = _active && _start;
bob.append("active", a);
bob.append( "op" , opToString( _op ) );
// Fill out "ns" from our namespace member (and if it's not available, fall back to the
// OpDebug namespace member).
bob.append("ns", !_ns.empty() ? _ns.toString() : _debug.ns.toString());
if (_op == dbInsert) {
_query.append(bob, "insert");
}
else {
_query.append(bob, "query");
}
if( killPending() )
bob.append("killPending", true);
return bob.obj();
}
void KaluzaConstraintWriter::visit(Symbolic::IntegerBinaryOperation* integerbinaryoperation, void* args)
{
integerbinaryoperation->getLhs()->accept(this);
std::string lhs = mIdentifierStore;
recordType(lhs, Symbolic::INT);
integerbinaryoperation->getRhs()->accept(this);
std::string rhs = mIdentifierStore;
recordType(rhs, Symbolic::INT);
// construct temporary identifier
std::ostringstream strs;
strs << "tmp";
strs << mNextTemporaryIdentifier++;
mIdentifierStore = strs.str();
recordType(mIdentifierStore, Symbolic::opGetType(integerbinaryoperation->getOp()));
mOutput << mIdentifierStore << " := " << lhs << " " << opToString(integerbinaryoperation->getOp()) << " " << rhs << ";\n";
}
BSONObj CurOp::infoNoauth() {
BSONObjBuilder b;
b.append("opid", _opNum);
bool a = _active && _start;
b.append("active", a);
if ( _lockType )
b.append("lockType" , _lockType > 0 ? "write" : "read" );
b.append("waitingForLock" , _waitingForLock );
if( a ){
b.append("secs_running", elapsedSeconds() );
}
b.append( "op" , opToString( _op ) );
b.append("ns", _ns);
if( haveQuery() ) {
b.append("query", query());
}
// b.append("inLock", ??
stringstream clientStr;
clientStr << _remote.toString();
b.append("client", clientStr.str());
if ( _client )
b.append( "desc" , _client->desc() );
if ( ! _message.empty() ){
if ( _progressMeter.isActive() ){
StringBuilder buf(128);
buf << _message << " " << _progressMeter.toString();
b.append( "msg" , buf.str() );
}
else {
b.append( "msg" , _message );
}
}
return b.obj();
}
void profile(const Client& c, int op, CurOp& currentOp) {
// initialize with 1kb to start, to avoid realloc later
// doing this outside the dblock to improve performance
BufBuilder profileBufBuilder(1024);
try {
Lock::DBWrite lk( currentOp.getNS() );
if ( dbHolder()._isLoaded( nsToDatabase( currentOp.getNS() ) , dbpath ) ) {
Client::Context cx(currentOp.getNS(), dbpath);
_profile(c, currentOp, profileBufBuilder);
}
else {
mongo::log() << "note: not profiling because db went away - probably a close on: "
<< currentOp.getNS() << endl;
}
}
catch (const AssertionException& assertionEx) {
warning() << "Caught Assertion while trying to profile " << opToString(op)
<< " against " << currentOp.getNS()
<< ": " << assertionEx.toString() << endl;
}
}
bool handlePossibleShardedMessage( Message &m, DbResponse* dbresponse ) {
if ( ! shardingState.enabled() )
return false;
int op = m.operation();
if ( op < 2000
|| op >= 3000
|| op == dbGetMore // cursors are weird
)
return false;
DbMessage d(m);
const char *ns = d.getns();
string errmsg;
if ( shardVersionOk( ns , opIsWrite( op ) , errmsg ) ) {
return false;
}
log(1) << "connection meta data too old - will retry ns:(" << ns << ") op:(" << opToString(op) << ") " << errmsg << endl;
if ( doesOpGetAResponse( op ) ) {
assert( dbresponse );
BufBuilder b( 32768 );
b.skip( sizeof( QueryResult ) );
{
BSONObj obj = BSON( "$err" << errmsg );
b.appendBuf( obj.objdata() , obj.objsize() );
}
QueryResult *qr = (QueryResult*)b.buf();
qr->_resultFlags() = ResultFlag_ErrSet | ResultFlag_ShardConfigStale;
qr->len = b.len();
qr->setOperation( opReply );
qr->cursorId = 0;
qr->startingFrom = 0;
qr->nReturned = 1;
b.decouple();
Message * resp = new Message();
resp->setData( qr , true );
dbresponse->response = resp;
dbresponse->responseTo = m.header()->id;
return true;
}
OID writebackID;
writebackID.init();
lastError.getSafe()->writeback( writebackID );
const OID& clientID = ShardedConnectionInfo::get(false)->getID();
massert( 10422 , "write with bad shard config and no server id!" , clientID.isSet() );
log(1) << "got write with an old config - writing back ns: " << ns << endl;
if ( logLevel ) log(1) << debugString( m ) << endl;
BSONObjBuilder b;
b.appendBool( "writeBack" , true );
b.append( "ns" , ns );
b.append( "id" , writebackID );
b.append( "connectionId" , cc().getConnectionId() );
b.appendTimestamp( "version" , shardingState.getVersion( ns ) );
b.appendTimestamp( "yourVersion" , ShardedConnectionInfo::get( true )->getVersion( ns ) );
b.appendBinData( "msg" , m.header()->len , bdtCustom , (char*)(m.singleData()) );
log(2) << "writing back msg with len: " << m.header()->len << " op: " << m.operation() << endl;
writeBackManager.queueWriteBack( clientID.str() , b.obj() );
return true;
}
// Returns false when request includes 'end'
bool assembleResponse( Message &m, DbResponse &dbresponse, const SockAddr &client ) {
// before we lock...
int op = m.operation();
bool isCommand = false;
const char *ns = m.singleData()->_data + 4;
if ( op == dbQuery ) {
if( strstr(ns, ".$cmd") ) {
isCommand = true;
opwrite(m);
if( strstr(ns, ".$cmd.sys.") ) {
if( strstr(ns, "$cmd.sys.inprog") ) {
inProgCmd(m, dbresponse);
return true;
}
if( strstr(ns, "$cmd.sys.killop") ) {
killOp(m, dbresponse);
return true;
}
if( strstr(ns, "$cmd.sys.unlock") ) {
unlockFsync(ns, m, dbresponse);
return true;
}
}
}
else {
opread(m);
}
}
else if( op == dbGetMore ) {
opread(m);
}
else {
opwrite(m);
}
globalOpCounters.gotOp( op , isCommand );
Client& c = cc();
auto_ptr<CurOp> nestedOp;
CurOp* currentOpP = c.curop();
if ( currentOpP->active() ){
nestedOp.reset( new CurOp( &c , currentOpP ) );
currentOpP = nestedOp.get();
}
CurOp& currentOp = *currentOpP;
currentOp.reset(client,op);
OpDebug& debug = currentOp.debug();
StringBuilder& ss = debug.str;
ss << opToString( op ) << " ";
int logThreshold = cmdLine.slowMS;
bool log = logLevel >= 1;
if ( op == dbQuery ) {
if ( handlePossibleShardedMessage( m , &dbresponse ) )
return true;
receivedQuery(c , dbresponse, m );
}
else if ( op == dbGetMore ) {
if ( ! receivedGetMore(dbresponse, m, currentOp) )
log = true;
}
else if ( op == dbMsg ) {
// deprecated - replaced by commands
char *p = m.singleData()->_data;
int len = strlen(p);
if ( len > 400 )
out() << curTimeMillis() % 10000 <<
" long msg received, len:" << len << endl;
Message *resp = new Message();
if ( strcmp( "end" , p ) == 0 )
resp->setData( opReply , "dbMsg end no longer supported" );
else
resp->setData( opReply , "i am fine - dbMsg deprecated");
dbresponse.response = resp;
dbresponse.responseTo = m.header()->id;
}
else {
const char *ns = m.singleData()->_data + 4;
char cl[256];
nsToDatabase(ns, cl);
if( ! c.getAuthenticationInfo()->isAuthorized(cl) ) {
uassert_nothrow("unauthorized");
}
else {
try {
if ( op == dbInsert ) {
receivedInsert(m, currentOp);
}
else if ( op == dbUpdate ) {
receivedUpdate(m, currentOp);
}
else if ( op == dbDelete ) {
receivedDelete(m, currentOp);
}
else if ( op == dbKillCursors ) {
currentOp.ensureStarted();
logThreshold = 10;
ss << "killcursors ";
receivedKillCursors(m);
}
else {
mongo::log() << " operation isn't supported: " << op << endl;
currentOp.done();
log = true;
}
}
catch ( UserException& ue ) {
tlog(3) << " Caught Assertion in " << opToString(op) << ", continuing " << ue.toString() << endl;
ss << " exception " << ue.toString();
}
catch ( AssertionException& e ) {
tlog(3) << " Caught Assertion in " << opToString(op) << ", continuing " << e.toString() << endl;
ss << " exception " << e.toString();
log = true;
}
}
}
currentOp.ensureStarted();
currentOp.done();
int ms = currentOp.totalTimeMillis();
//DEV log = true;
if ( log || ms > logThreshold ) {
if( logLevel < 3 && op == dbGetMore && strstr(ns, ".oplog.") && ms < 3000 && !log ) {
/* it's normal for getMore on the oplog to be slow because of use of awaitdata flag. */
} else {
ss << ' ' << ms << "ms";
mongo::tlog() << ss.str() << endl;
}
}
if ( currentOp.shouldDBProfile( ms ) ){
// performance profiling is on
if ( dbMutex.getState() < 0 ){
mongo::log(1) << "note: not profiling because recursive read lock" << endl;
}
else {
writelock lk;
if ( dbHolder.isLoaded( nsToDatabase( currentOp.getNS() ) , dbpath ) ){
Client::Context c( currentOp.getNS() );
profile(ss.str().c_str(), ms);
}
else {
mongo::log() << "note: not profiling because db went away - probably a close on: " << currentOp.getNS() << endl;
}
}
}
return true;
} /* assembleResponse() */
bool OpDebug::append(const CurOp& curop, BSONObjBuilder& b, size_t maxSize) const {
b.append( "op" , iscommand ? "command" : opToString( op ) );
b.append( "ns" , ns.toString() );
int queryUpdateObjSize = 0;
if (!query.isEmpty()) {
queryUpdateObjSize += query.objsize();
}
else if (!iscommand && curop.haveQuery()) {
queryUpdateObjSize += curop.query()["query"].size();
}
if (!updateobj.isEmpty()) {
queryUpdateObjSize += updateobj.objsize();
}
if (static_cast<size_t>(queryUpdateObjSize) > maxSize) {
if (!query.isEmpty()) {
// Use 60 since BSONObj::toString can truncate strings into 150 chars
// and we want to have enough room for both query and updateobj when
// the entire document is going to be serialized into a string
const string abbreviated(query.toString(false, false), 0, 60);
b.append(iscommand ? "command" : "query", abbreviated + "...");
}
else if (!iscommand && curop.haveQuery()) {
const string abbreviated(curop.query()["query"].toString(false, false), 0, 60);
b.append("query", abbreviated + "...");
}
if (!updateobj.isEmpty()) {
const string abbreviated(updateobj.toString(false, false), 0, 60);
b.append("updateobj", abbreviated + "...");
}
return false;
}
if (!query.isEmpty()) {
b.append(iscommand ? "command" : "query", query);
}
else if (!iscommand && curop.haveQuery()) {
curop.appendQuery(b, "query");
}
if (!updateobj.isEmpty()) {
b.append("updateobj", updateobj);
}
const bool moved = (nmoved >= 1);
OPDEBUG_APPEND_NUMBER( cursorid );
OPDEBUG_APPEND_NUMBER( ntoreturn );
OPDEBUG_APPEND_NUMBER( ntoskip );
OPDEBUG_APPEND_BOOL( exhaust );
OPDEBUG_APPEND_NUMBER( nscanned );
OPDEBUG_APPEND_BOOL( idhack );
OPDEBUG_APPEND_BOOL( scanAndOrder );
OPDEBUG_APPEND_BOOL( moved );
OPDEBUG_APPEND_NUMBER( nmoved );
OPDEBUG_APPEND_NUMBER( nMatched );
OPDEBUG_APPEND_NUMBER( nModified );
OPDEBUG_APPEND_NUMBER( ninserted );
OPDEBUG_APPEND_NUMBER( ndeleted );
OPDEBUG_APPEND_BOOL( fastmod );
OPDEBUG_APPEND_BOOL( fastmodinsert );
OPDEBUG_APPEND_BOOL( upsert );
OPDEBUG_APPEND_NUMBER( keyUpdates );
b.appendNumber( "numYield" , curop.numYields() );
b.append( "lockStats" , curop.lockStat().report() );
if ( ! exceptionInfo.empty() )
exceptionInfo.append( b , "exception" , "exceptionCode" );
OPDEBUG_APPEND_NUMBER( nreturned );
OPDEBUG_APPEND_NUMBER( responseLength );
b.append( "millis" , executionTime );
execStats.append(b, "execStats");
return true;
}
string OpDebug::report( const CurOp& curop ) const {
StringBuilder s;
if ( iscommand )
s << "command ";
else
s << opToString( op ) << ' ';
s << ns.toString();
if ( ! query.isEmpty() ) {
if ( iscommand ) {
s << " command: ";
Command* curCommand = curop.getCommand();
if (curCommand) {
mutablebson::Document cmdToLog(curop.query(),
mutablebson::Document::kInPlaceDisabled);
curCommand->redactForLogging(&cmdToLog);
s << cmdToLog.toString();
}
else { // Should not happen but we need to handle curCommand == NULL gracefully
s << query.toString();
}
}
else {
s << " query: ";
s << query.toString();
}
}
if (!planSummary.empty()) {
s << " planSummary: " << planSummary.toString();
}
if ( ! updateobj.isEmpty() ) {
s << " update: ";
updateobj.toString( s );
}
OPDEBUG_TOSTRING_HELP( cursorid );
OPDEBUG_TOSTRING_HELP( ntoreturn );
OPDEBUG_TOSTRING_HELP( ntoskip );
OPDEBUG_TOSTRING_HELP_BOOL( exhaust );
OPDEBUG_TOSTRING_HELP( nscanned );
OPDEBUG_TOSTRING_HELP_BOOL( idhack );
OPDEBUG_TOSTRING_HELP_BOOL( scanAndOrder );
OPDEBUG_TOSTRING_HELP( nmoved );
OPDEBUG_TOSTRING_HELP( nMatched );
OPDEBUG_TOSTRING_HELP( nModified );
OPDEBUG_TOSTRING_HELP( ninserted );
OPDEBUG_TOSTRING_HELP( ndeleted );
OPDEBUG_TOSTRING_HELP_BOOL( fastmod );
OPDEBUG_TOSTRING_HELP_BOOL( fastmodinsert );
OPDEBUG_TOSTRING_HELP_BOOL( upsert );
OPDEBUG_TOSTRING_HELP( keyUpdates );
if ( extra.len() )
s << " " << extra.str();
if ( ! exceptionInfo.empty() ) {
s << " exception: " << exceptionInfo.msg;
if ( exceptionInfo.code )
s << " code:" << exceptionInfo.code;
}
s << " numYields:" << curop.numYields();
s << " ";
curop.lockStat().report( s );
OPDEBUG_TOSTRING_HELP( nreturned );
if ( responseLength > 0 )
s << " reslen:" << responseLength;
s << " " << executionTime << "ms";
return s.str();
}
// Returns false when request includes 'end'
void assembleResponse( Message &m, DbResponse &dbresponse, const HostAndPort& remote ) {
// before we lock...
int op = m.operation();
bool isCommand = false;
const char *ns = m.singleData()->_data + 4;
if ( op == dbQuery ) {
if( strstr(ns, ".$cmd") ) {
isCommand = true;
opwrite(m);
if( strstr(ns, ".$cmd.sys.") ) {
if( strstr(ns, "$cmd.sys.inprog") ) {
inProgCmd(m, dbresponse);
return;
}
if( strstr(ns, "$cmd.sys.killop") ) {
killOp(m, dbresponse);
return;
}
if( strstr(ns, "$cmd.sys.unlock") ) {
unlockFsync(ns, m, dbresponse);
return;
}
}
}
else {
opread(m);
}
}
else if( op == dbGetMore ) {
opread(m);
}
else {
opwrite(m);
}
globalOpCounters.gotOp( op , isCommand );
Client& c = cc();
c.getAuthorizationManager()->startRequest();
auto_ptr<CurOp> nestedOp;
CurOp* currentOpP = c.curop();
if ( currentOpP->active() ) {
nestedOp.reset( new CurOp( &c , currentOpP ) );
currentOpP = nestedOp.get();
}
else {
c.newTopLevelRequest();
}
CurOp& currentOp = *currentOpP;
currentOp.reset(remote,op);
OpDebug& debug = currentOp.debug();
debug.op = op;
long long logThreshold = cmdLine.slowMS;
bool shouldLog = logLevel >= 1;
if ( op == dbQuery ) {
if ( handlePossibleShardedMessage( m , &dbresponse ) )
return;
receivedQuery(c , dbresponse, m );
}
else if ( op == dbGetMore ) {
if ( ! receivedGetMore(dbresponse, m, currentOp) )
shouldLog = true;
}
else if ( op == dbMsg ) {
// deprecated - replaced by commands
char *p = m.singleData()->_data;
int len = strlen(p);
if ( len > 400 )
out() << curTimeMillis64() % 10000 <<
" long msg received, len:" << len << endl;
Message *resp = new Message();
if ( strcmp( "end" , p ) == 0 )
resp->setData( opReply , "dbMsg end no longer supported" );
else
resp->setData( opReply , "i am fine - dbMsg deprecated");
dbresponse.response = resp;
dbresponse.responseTo = m.header()->id;
}
else {
try {
const NamespaceString nsString( ns );
// The following operations all require authorization.
// dbInsert, dbUpdate and dbDelete can be easily pre-authorized,
// here, but dbKillCursors cannot.
if ( op == dbKillCursors ) {
currentOp.ensureStarted();
logThreshold = 10;
receivedKillCursors(m);
}
else if ( !nsString.isValid() ) {
// Only killCursors doesn't care about namespaces
uassert( 16257, str::stream() << "Invalid ns [" << ns << "]", false );
}
else if ( op == dbInsert ) {
receivedInsert(m, currentOp);
}
else if ( op == dbUpdate ) {
receivedUpdate(m, currentOp);
}
else if ( op == dbDelete ) {
receivedDelete(m, currentOp);
}
else {
mongo::log() << " operation isn't supported: " << op << endl;
currentOp.done();
shouldLog = true;
}
}
catch ( UserException& ue ) {
tlog(3) << " Caught Assertion in " << opToString(op) << ", continuing "
<< ue.toString() << endl;
debug.exceptionInfo = ue.getInfo();
}
catch ( AssertionException& e ) {
tlog(3) << " Caught Assertion in " << opToString(op) << ", continuing "
<< e.toString() << endl;
debug.exceptionInfo = e.getInfo();
shouldLog = true;
}
}
currentOp.ensureStarted();
currentOp.done();
debug.executionTime = currentOp.totalTimeMillis();
logThreshold += currentOp.getExpectedLatencyMs();
if ( shouldLog || debug.executionTime > logThreshold ) {
mongo::tlog() << debug.report( currentOp ) << endl;
}
if ( currentOp.shouldDBProfile( debug.executionTime ) ) {
// performance profiling is on
if ( Lock::isReadLocked() ) {
LOG(1) << "note: not profiling because recursive read lock" << endl;
}
else if ( lockedForWriting() ) {
LOG(1) << "note: not profiling because doing fsync+lock" << endl;
}
else {
profile(c, op, currentOp);
}
}
debug.recordStats();
debug.reset();
} /* assembleResponse() */
// Returns false when request includes 'end'
void assembleResponse( Message &m, DbResponse &dbresponse, const HostAndPort& remote ) {
// before we lock...
int op = m.operation();
bool isCommand = false;
const char *ns = m.singleData()->_data + 4;
if ( op == dbQuery ) {
if( strstr(ns, ".$cmd") ) {
isCommand = true;
opwrite(m);
if( strstr(ns, ".$cmd.sys.") ) {
if( strstr(ns, "$cmd.sys.inprog") ) {
inProgCmd(m, dbresponse);
return;
}
if( strstr(ns, "$cmd.sys.killop") ) {
killOp(m, dbresponse);
return;
}
if( strstr(ns, "$cmd.sys.unlock") ) {
unlockFsync(ns, m, dbresponse);
return;
}
}
}
else {
opread(m);
}
}
else if( op == dbGetMore ) {
opread(m);
}
else {
opwrite(m);
}
globalOpCounters.gotOp( op , isCommand );
Client& c = cc();
auto_ptr<CurOp> nestedOp;
CurOp* currentOpP = c.curop();
if ( currentOpP->active() ) {
nestedOp.reset( new CurOp( &c , currentOpP ) );
currentOpP = nestedOp.get();
}
else {
c.newTopLevelRequest();
}
CurOp& currentOp = *currentOpP;
currentOp.reset(remote,op);
OpDebug& debug = currentOp.debug();
debug.op = op;
int logThreshold = cmdLine.slowMS;
bool log = logLevel >= 1;
if ( op == dbQuery ) {
if ( handlePossibleShardedMessage( m , &dbresponse ) )
return;
receivedQuery(c , dbresponse, m );
}
else if ( op == dbGetMore ) {
if ( ! receivedGetMore(dbresponse, m, currentOp) )
log = true;
}
else if ( op == dbMsg ) {
// deprecated - replaced by commands
char *p = m.singleData()->_data;
int len = strlen(p);
if ( len > 400 )
out() << curTimeMillis64() % 10000 <<
" long msg received, len:" << len << endl;
Message *resp = new Message();
if ( strcmp( "end" , p ) == 0 )
resp->setData( opReply , "dbMsg end no longer supported" );
else
resp->setData( opReply , "i am fine - dbMsg deprecated");
dbresponse.response = resp;
dbresponse.responseTo = m.header()->id;
}
else {
try {
// The following operations all require authorization.
// dbInsert, dbUpdate and dbDelete can be easily pre-authorized,
// here, but dbKillCursors cannot.
if ( op == dbKillCursors ) {
currentOp.ensureStarted();
logThreshold = 10;
receivedKillCursors(m);
}
else if ( ! c.getAuthenticationInfo()->isAuthorized(
nsToDatabase( m.singleData()->_data + 4 ) ) ) {
uassert_nothrow("unauthorized");
}
else if ( op == dbInsert ) {
receivedInsert(m, currentOp);
}
else if ( op == dbUpdate ) {
receivedUpdate(m, currentOp);
}
else if ( op == dbDelete ) {
receivedDelete(m, currentOp);
}
else {
mongo::log() << " operation isn't supported: " << op << endl;
currentOp.done();
log = true;
}
}
catch ( UserException& ue ) {
tlog(3) << " Caught Assertion in " << opToString(op) << ", continuing "
<< ue.toString() << endl;
debug.exceptionInfo = ue.getInfo();
}
catch ( AssertionException& e ) {
tlog(3) << " Caught Assertion in " << opToString(op) << ", continuing "
<< e.toString() << endl;
debug.exceptionInfo = e.getInfo();
log = true;
}
}
currentOp.ensureStarted();
currentOp.done();
debug.executionTime = currentOp.totalTimeMillis();
//DEV log = true;
if ( log || debug.executionTime > logThreshold ) {
if( logLevel < 3 && op == dbGetMore && strstr(ns, ".oplog.") && debug.executionTime < 4300 && !log ) {
/* it's normal for getMore on the oplog to be slow because of use of awaitdata flag. */
}
else {
mongo::tlog() << debug << endl;
}
}
if ( currentOp.shouldDBProfile( debug.executionTime ) ) {
// performance profiling is on
if ( Lock::isReadLocked() ) {
mongo::log(1) << "note: not profiling because recursive read lock" << endl;
}
else if ( lockedForWriting() ) {
mongo::log(1) << "note: not profiling because doing fsync+lock" << endl;
}
else {
writelock lk;
if ( dbHolder()._isLoaded( nsToDatabase( currentOp.getNS() ) , dbpath ) ) {
Client::Context cx( currentOp.getNS(), dbpath, false );
profile(c , currentOp );
}
else {
mongo::log() << "note: not profiling because db went away - probably a close on: " << currentOp.getNS() << endl;
}
}
}
debug.reset();
} /* assembleResponse() */
bool _handlePossibleShardedMessage( Message &m, DbResponse* dbresponse ) {
DEV assert( shardingState.enabled() );
int op = m.operation();
if ( op < 2000
|| op >= 3000
|| op == dbGetMore // cursors are weird
)
return false;
DbMessage d(m);
const char *ns = d.getns();
string errmsg;
// We don't care about the version here, since we're returning it later in the writeback
ConfigVersion received, wanted;
if ( shardVersionOk( ns , errmsg, received, wanted ) ) {
return false;
}
LOG(1) << "connection meta data too old - will retry ns:(" << ns << ") op:(" << opToString(op) << ") " << errmsg << endl;
if ( doesOpGetAResponse( op ) ) {
assert( dbresponse );
BufBuilder b( 32768 );
b.skip( sizeof( QueryResult ) );
{
BSONObj obj = BSON( "$err" << errmsg << "ns" << ns );
b.appendBuf( obj.objdata() , obj.objsize() );
}
QueryResult *qr = (QueryResult*)b.buf();
qr->_resultFlags() = ResultFlag_ErrSet | ResultFlag_ShardConfigStale;
qr->len = b.len();
qr->setOperation( opReply );
qr->cursorId = 0;
qr->startingFrom = 0;
qr->nReturned = 1;
b.decouple();
Message * resp = new Message();
resp->setData( qr , true );
dbresponse->response = resp;
dbresponse->responseTo = m.header()->id;
return true;
}
uassert( 9517 , "writeback" , ( d.reservedField() & DbMessage::Reserved_FromWriteback ) == 0 );
OID writebackID;
writebackID.init();
lastError.getSafe()->writeback( writebackID );
const OID& clientID = ShardedConnectionInfo::get(false)->getID();
massert( 10422 , "write with bad shard config and no server id!" , clientID.isSet() );
LOG(1) << "got write with an old config - writing back ns: " << ns << endl;
LOG(1) << m.toString() << endl;
BSONObjBuilder b;
b.appendBool( "writeBack" , true );
b.append( "ns" , ns );
b.append( "id" , writebackID );
b.append( "connectionId" , cc().getConnectionId() );
b.append( "instanceIdent" , prettyHostName() );
b.appendTimestamp( "version" , shardingState.getVersion( ns ) );
ShardedConnectionInfo* info = ShardedConnectionInfo::get( false );
b.appendTimestamp( "yourVersion" , info ? info->getVersion(ns) : (ConfigVersion)0 );
b.appendBinData( "msg" , m.header()->len , bdtCustom , (char*)(m.singleData()) );
LOG(2) << "writing back msg with len: " << m.header()->len << " op: " << m.operation() << endl;
writeBackManager.queueWriteBack( clientID.str() , b.obj() );
return true;
}
void UnopNode::prettyPrint(ostream & os, int indent) const
{
os << opToString(op) << '(';
operand->prettyPrint(os);
os << ')';
}
BSONObj CurOp::info() {
BSONObjBuilder b;
b.append("opid", _opNum);
bool a = _active && _start;
b.append("active", a);
if( a ) {
b.append("secs_running", elapsedSeconds() );
}
b.append( "op" , opToString( _op ) );
b.append("ns", _ns);
if (_op == dbInsert) {
_query.append(b, "insert");
}
else {
_query.append(b , "query");
}
if ( !debug().planSummary.empty() ) {
b.append( "planSummary" , debug().planSummary.toString() );
}
if( !_remote.empty() ) {
b.append("client", _remote.toString());
}
if ( _client ) {
b.append( "desc" , _client->desc() );
if ( _client->_threadId.size() )
b.append( "threadId" , _client->_threadId );
if ( _client->_connectionId )
b.appendNumber( "connectionId" , _client->_connectionId );
_client->_ls.reportState(b);
}
if ( ! _message.empty() ) {
if ( _progressMeter.isActive() ) {
StringBuilder buf;
buf << _message.toString() << " " << _progressMeter.toString();
b.append( "msg" , buf.str() );
BSONObjBuilder sub( b.subobjStart( "progress" ) );
sub.appendNumber( "done" , (long long)_progressMeter.done() );
sub.appendNumber( "total" , (long long)_progressMeter.total() );
sub.done();
}
else {
b.append( "msg" , _message.toString() );
}
}
if( killPending() )
b.append("killPending", true);
b.append( "numYields" , _numYields );
b.append( "lockStats" , _lockStat.report() );
return b.obj();
}