diff options
author | Charlie Swanson <charlie.swanson@mongodb.com> | 2018-03-07 12:29:22 -0500 |
---|---|---|
committer | Charlie Swanson <charlie.swanson@mongodb.com> | 2018-03-12 14:59:17 -0400 |
commit | 3f723beb10caf6bd809b7df05c34b6a97402dadb (patch) | |
tree | 170e3d1c38808281fb216f4e934abcd336b1743c | |
parent | b1102c617e04ff751d702435f9d4521727e579e1 (diff) | |
download | mongo-3f723beb10caf6bd809b7df05c34b6a97402dadb.tar.gz |
SERVER-33542 Avoid swallowing error codes from PlanExecutor errors
-rw-r--r-- | jstests/core/max_time_ms.js | 26 | ||||
-rw-r--r-- | jstests/noPassthrough/aggregation_cursor_invalidations.js | 2 | ||||
-rw-r--r-- | jstests/noPassthrough/commands_preserve_exec_error_code.js | 57 | ||||
-rw-r--r-- | src/mongo/client/dbclientcursor.cpp | 2 | ||||
-rw-r--r-- | src/mongo/db/commands/dbcommands.cpp | 10 | ||||
-rw-r--r-- | src/mongo/db/commands/distinct.cpp | 5 | ||||
-rw-r--r-- | src/mongo/db/commands/find_and_modify.cpp | 12 | ||||
-rw-r--r-- | src/mongo/db/commands/find_cmd.cpp | 5 | ||||
-rw-r--r-- | src/mongo/db/commands/geo_near_cmd.cpp | 5 | ||||
-rw-r--r-- | src/mongo/db/commands/group_cmd.cpp | 10 | ||||
-rw-r--r-- | src/mongo/db/exec/stagedebug_cmd.cpp | 6 | ||||
-rw-r--r-- | src/mongo/db/pipeline/document_source_cursor.cpp | 16 | ||||
-rw-r--r-- | src/mongo/db/query/find.cpp | 4 | ||||
-rw-r--r-- | src/mongo/db/query/plan_executor.cpp | 2 | ||||
-rw-r--r-- | src/mongo/db/s/check_sharding_index_command.cpp | 5 | ||||
-rw-r--r-- | src/mongo/db/s/migration_chunk_cloner_source_legacy.cpp | 5 | ||||
-rw-r--r-- | src/mongo/db/s/split_vector.cpp | 5 | ||||
-rw-r--r-- | src/mongo/dbtests/documentsourcetests.cpp | 6 |
18 files changed, 113 insertions, 70 deletions
diff --git a/jstests/core/max_time_ms.js b/jstests/core/max_time_ms.js index f10ffb0bce1..d7a99dae4f3 100644 --- a/jstests/core/max_time_ms.js +++ b/jstests/core/max_time_ms.js @@ -9,9 +9,9 @@ // ] var t = db.max_time_ms; -var exceededTimeLimit = 50; // ErrorCodes::ExceededTimeLimit var cursor; var res; +var error; // // Simple positive test for query: a ~300ms query with a 100ms time limit should be aborted. @@ -26,9 +26,12 @@ cursor = t.find({ } }); cursor.maxTimeMS(100); -assert.throws(function() { +error = assert.throws(function() { cursor.itcount(); }, [], "expected query to abort due to time limit"); +if (error.code !== ErrorCodes.CursorNotFound) { + assert.eq(ErrorCodes.ExceededTimeLimit, error.code); +} // // Simple negative test for query: a ~300ms query with a 10s time limit should not hit the time @@ -73,11 +76,14 @@ assert.doesNotThrow(function() { cursor.next(); cursor.next(); }, [], "expected batch 1 (query) to not hit the time limit"); -assert.throws(function() { +error = assert.throws(function() { cursor.next(); cursor.next(); cursor.next(); }, [], "expected batch 2 (getmore) to abort due to time limit"); +if (error.code !== ErrorCodes.CursorNotFound) { + assert.eq(ErrorCodes.ExceededTimeLimit, error.code); +} // // Simple negative test for getmore: @@ -130,9 +136,12 @@ cursor = t.find({ }).sort({_id: 1}); cursor.batchSize(3); cursor.maxTimeMS(6 * 1000); -assert.throws(function() { +error = assert.throws(function() { cursor.itcount(); }, [], "expected find() to abort due to time limit"); +if (error.code !== ErrorCodes.CursorNotFound) { + assert.eq(ErrorCodes.ExceededTimeLimit, error.code); +} // // Many-batch negative test for getmore: @@ -164,7 +173,7 @@ assert.doesNotThrow(function() { t.drop(); res = t.getDB().adminCommand({sleep: 1, millis: 300, maxTimeMS: 100}); -assert(res.ok == 0 && res.code == exceededTimeLimit, +assert(res.ok == 0 && res.code == ErrorCodes.ExceededTimeLimit, "expected sleep command to abort due to time limit, ok=" + res.ok + ", code=" + res.code); // @@ -292,7 +301,7 @@ t.drop(); assert.eq( 1, t.getDB().adminCommand({configureFailPoint: "maxTimeAlwaysTimeOut", mode: "alwaysOn"}).ok); res = t.getDB().runCommand({ping: 1, maxTimeMS: 10 * 1000}); -assert(res.ok == 0 && res.code == exceededTimeLimit, +assert(res.ok == 0 && res.code == ErrorCodes.ExceededTimeLimit, "expected command to trigger maxTimeAlwaysTimeOut fail point, ok=" + res.ok + ", code=" + res.code); assert.eq(1, t.getDB().adminCommand({configureFailPoint: "maxTimeAlwaysTimeOut", mode: "off"}).ok); @@ -402,9 +411,12 @@ assert.commandWorked(res); var cursor = new DBCommandCursor(t.getDB(), res.cursors[0], 5); assert.commandWorked( t.getDB().adminCommand({configureFailPoint: "maxTimeAlwaysTimeOut", mode: "alwaysOn"})); -assert.throws(function() { +error = assert.throws(function() { cursor.itcount(); }, [], "expected query to abort due to time limit"); +if (error.code !== ErrorCodes.CursorNotFound) { + assert.eq(ErrorCodes.ExceededTimeLimit, error.code); +} assert.commandWorked( t.getDB().adminCommand({configureFailPoint: "maxTimeAlwaysTimeOut", mode: "off"})); diff --git a/jstests/noPassthrough/aggregation_cursor_invalidations.js b/jstests/noPassthrough/aggregation_cursor_invalidations.js index 32f9ae72156..e35598dc2dd 100644 --- a/jstests/noPassthrough/aggregation_cursor_invalidations.js +++ b/jstests/noPassthrough/aggregation_cursor_invalidations.js @@ -282,7 +282,7 @@ assert.eq(maxNumDocs, sourceCollection.count()); assert.commandFailedWithCode( testDB.runCommand({getMore: res.cursor.id, collection: getMoreCollName}), - ErrorCodes.QueryPlanKilled, + ErrorCodes.CappedPositionLost, 'expected getMore to fail because the capped collection was truncated'); // Test that killing an aggregation's cursor via the killCursors command will cause a subsequent diff --git a/jstests/noPassthrough/commands_preserve_exec_error_code.js b/jstests/noPassthrough/commands_preserve_exec_error_code.js new file mode 100644 index 00000000000..b8bffb260ce --- /dev/null +++ b/jstests/noPassthrough/commands_preserve_exec_error_code.js @@ -0,0 +1,57 @@ +// Tests that an error encountered during PlanExecutor execution will be propagated back to the user +// with the original error code. This is important for retryable errors like +// 'InterruptedDueToReplStateChange', +// and also to ensure that the error is not swallowed and the diagnostic info is not lost. +(function() { + "use strict"; + + const mongod = MongoRunner.runMongod({}); + assert.neq(mongod, null, "mongod failed to start up"); + const db = mongod.getDB("test"); + const coll = db.commands_preserve_exec_error_code; + coll.drop(); + + assert.writeOK(coll.insert([{_id: 0}, {_id: 1}, {_id: 2}])); + assert.commandWorked(coll.createIndex({geo: "2d"})); + + assert.commandWorked( + db.adminCommand({configureFailPoint: "planExecutorAlwaysFails", mode: "alwaysOn"})); + + function assertFailsWithInternalError(fn) { + const error = assert.throws(fn); + assert.eq(error.code, ErrorCodes.InternalError, tojson(error)); + assert.neq(-1, + error.message.indexOf("planExecutorAlwaysFails"), + "Expected error message to be preserved"); + } + function assertCmdFailsWithInternalError(cmd) { + const res = + assert.commandFailedWithCode(db.runCommand(cmd), ErrorCodes.InternalError, tojson(cmd)); + assert.neq(-1, + res.errmsg.indexOf("planExecutorAlwaysFails"), + "Expected error message to be preserved"); + } + + assertFailsWithInternalError(() => coll.find().itcount()); + assertFailsWithInternalError(() => coll.updateOne({_id: 1}, {$set: {x: 2}})); + assertFailsWithInternalError(() => coll.deleteOne({_id: 1})); + assertFailsWithInternalError(() => coll.count({_id: 1})); + assertFailsWithInternalError(() => coll.group({ + key: "_id", + cond: {}, + reduce: () => { + result.total += 1; + }, + initial: {total: 0} + }) + .itcount()); + assertFailsWithInternalError(() => coll.aggregate([]).itcount()); + assertCmdFailsWithInternalError({distinct: coll.getName(), key: "_id"}); + assertCmdFailsWithInternalError({geoNear: coll.getName(), near: [0, 0]}); + assertCmdFailsWithInternalError( + {findAndModify: coll.getName(), query: {_id: 1}, update: {$set: {x: 2}}}); + + assert.commandWorked( + db.adminCommand({configureFailPoint: "planExecutorAlwaysFails", mode: "off"})); + MongoRunner.stopMongod(mongod); +}()); diff --git a/src/mongo/client/dbclientcursor.cpp b/src/mongo/client/dbclientcursor.cpp index a275f984ae5..399d6cb9143 100644 --- a/src/mongo/client/dbclientcursor.cpp +++ b/src/mongo/client/dbclientcursor.cpp @@ -305,7 +305,7 @@ void DBClientCursor::dataReceived(const Message& reply, bool& retry, string& hos invariant(qr.getCursorId() == 0); if (!(opts & QueryOption_CursorTailable)) { - uasserted(13127, + uasserted(ErrorCodes::CursorNotFound, str::stream() << "cursor id " << cursorId << " didn't exist on server."); } diff --git a/src/mongo/db/commands/dbcommands.cpp b/src/mongo/db/commands/dbcommands.cpp index f4950c06d5b..10954efc526 100644 --- a/src/mongo/db/commands/dbcommands.cpp +++ b/src/mongo/db/commands/dbcommands.cpp @@ -709,9 +709,8 @@ public: if (PlanExecutor::DEAD == state || PlanExecutor::FAILURE == state) { return CommandHelpers::appendCommandStatus( result, - Status(ErrorCodes::OperationFailed, - str::stream() << "Executor error during filemd5 command: " - << WorkingSetCommon::toStatusString(obj))); + WorkingSetCommon::getMemberObjectStatus(obj).withContext( + "Executor error during filemd5 command")); } if (partialOk) @@ -877,9 +876,8 @@ public: warning() << "Internal error while reading " << ns; return CommandHelpers::appendCommandStatus( result, - Status(ErrorCodes::OperationFailed, - str::stream() << "Executor error while reading during dataSize command: " - << WorkingSetCommon::toStatusString(obj))); + WorkingSetCommon::getMemberObjectStatus(obj).withContext( + "Executor error while reading during dataSize command")); } ostringstream os; diff --git a/src/mongo/db/commands/distinct.cpp b/src/mongo/db/commands/distinct.cpp index ae99b5a2332..e97d9ee1933 100644 --- a/src/mongo/db/commands/distinct.cpp +++ b/src/mongo/db/commands/distinct.cpp @@ -245,9 +245,8 @@ public: return CommandHelpers::appendCommandStatus( result, - Status(ErrorCodes::OperationFailed, - str::stream() << "Executor error during distinct command: " - << WorkingSetCommon::toStatusString(obj))); + WorkingSetCommon::getMemberObjectStatus(obj).withContext( + "Executor error during distinct command")); } diff --git a/src/mongo/db/commands/find_and_modify.cpp b/src/mongo/db/commands/find_and_modify.cpp index 9757e8e450d..da0f6bfc9a8 100644 --- a/src/mongo/db/commands/find_and_modify.cpp +++ b/src/mongo/db/commands/find_and_modify.cpp @@ -120,15 +120,9 @@ boost::optional<BSONObj> advanceExecutor(OperationContext* opCtx, error() << "Plan executor error during findAndModify: " << PlanExecutor::statestr(state) << ", stats: " << redact(Explain::getWinningPlanStats(exec)); - if (WorkingSetCommon::isValidStatusMemberObject(value)) { - uassertStatusOK(WorkingSetCommon::getMemberObjectStatus(value)); - MONGO_UNREACHABLE; - } - - uasserted(ErrorCodes::OperationFailed, - str::stream() << "executor returned " << PlanExecutor::statestr(state) - << " while executing " - << (isRemove ? "delete" : "update")); + uassertStatusOKWithContext(WorkingSetCommon::getMemberObjectStatus(value), + "Plan executor error during findAndModify"); + MONGO_UNREACHABLE; } invariant(state == PlanExecutor::IS_EOF); diff --git a/src/mongo/db/commands/find_cmd.cpp b/src/mongo/db/commands/find_cmd.cpp index 5a7bf9c0cec..6de36e438e8 100644 --- a/src/mongo/db/commands/find_cmd.cpp +++ b/src/mongo/db/commands/find_cmd.cpp @@ -359,9 +359,8 @@ public: return CommandHelpers::appendCommandStatus( result, - Status(ErrorCodes::OperationFailed, - str::stream() << "Executor error during find command: " - << WorkingSetCommon::toStatusString(obj))); + WorkingSetCommon::getMemberObjectStatus(obj).withContext( + "Executor error during find command")); } // Before saving the cursor, ensure that whatever plan we established happened with the diff --git a/src/mongo/db/commands/geo_near_cmd.cpp b/src/mongo/db/commands/geo_near_cmd.cpp index 6fff31aabd5..d605fbb86b8 100644 --- a/src/mongo/db/commands/geo_near_cmd.cpp +++ b/src/mongo/db/commands/geo_near_cmd.cpp @@ -303,9 +303,8 @@ public: return CommandHelpers::appendCommandStatus( result, - Status(ErrorCodes::OperationFailed, - str::stream() << "Executor error during geoNear command: " - << WorkingSetCommon::toStatusString(currObj))); + WorkingSetCommon::getMemberObjectStatus(currObj).withContext( + "Executor error during geoNear command")); } PlanSummaryStats summary; diff --git a/src/mongo/db/commands/group_cmd.cpp b/src/mongo/db/commands/group_cmd.cpp index c4c67983ed8..3441e23a1ea 100644 --- a/src/mongo/db/commands/group_cmd.cpp +++ b/src/mongo/db/commands/group_cmd.cpp @@ -184,16 +184,10 @@ private: if (PlanExecutor::ADVANCED != state) { invariant(PlanExecutor::FAILURE == state || PlanExecutor::DEAD == state); - if (WorkingSetCommon::isValidStatusMemberObject(retval)) { - return CommandHelpers::appendCommandStatus( - result, WorkingSetCommon::getMemberObjectStatus(retval)); - } return CommandHelpers::appendCommandStatus( result, - Status(ErrorCodes::BadValue, - str::stream() << "error encountered during group " - << "operation, executor returned " - << PlanExecutor::statestr(state))); + WorkingSetCommon::getMemberObjectStatus(retval).withContext( + "Plan executor error during group command")); } invariant(planExecutor->isEOF()); diff --git a/src/mongo/db/exec/stagedebug_cmd.cpp b/src/mongo/db/exec/stagedebug_cmd.cpp index 92b9908f2a3..6d6bfc1a896 100644 --- a/src/mongo/db/exec/stagedebug_cmd.cpp +++ b/src/mongo/db/exec/stagedebug_cmd.cpp @@ -211,10 +211,8 @@ public: return CommandHelpers::appendCommandStatus( result, - Status(ErrorCodes::OperationFailed, - str::stream() << "Executor error during " - << "StageDebug command: " - << WorkingSetCommon::toStatusString(obj))); + WorkingSetCommon::getMemberObjectStatus(obj).withContext( + "Executor error during StageDebug command")); } return true; diff --git a/src/mongo/db/pipeline/document_source_cursor.cpp b/src/mongo/db/pipeline/document_source_cursor.cpp index 10d049cef28..10fe39a1484 100644 --- a/src/mongo/db/pipeline/document_source_cursor.cpp +++ b/src/mongo/db/pipeline/document_source_cursor.cpp @@ -133,23 +133,15 @@ void DocumentSourceCursor::loadBatch() { case PlanExecutor::ADVANCED: case PlanExecutor::IS_EOF: return; // We've reached our limit or exhausted the cursor. - case PlanExecutor::DEAD: { - _execStatus = - Status(ErrorCodes::QueryPlanKilled, - str::stream() << "collection or index disappeared when cursor yielded: " - << WorkingSetCommon::toStatusString(resultObj)); - break; - } + case PlanExecutor::DEAD: case PlanExecutor::FAILURE: { - _execStatus = Status(ErrorCodes::Error(17285), - str::stream() << "cursor encountered an error: " - << WorkingSetCommon::toStatusString(resultObj)); - break; + _execStatus = WorkingSetCommon::getMemberObjectStatus(resultObj).withContext( + "Error in $cursor stage"); + uassertStatusOK(_execStatus); } default: MONGO_UNREACHABLE; } - uassertStatusOK(_execStatus); } Pipeline::SourceContainer::iterator DocumentSourceCursor::doOptimizeAt( diff --git a/src/mongo/db/query/find.cpp b/src/mongo/db/query/find.cpp index 8b01d239967..8d754771d8a 100644 --- a/src/mongo/db/query/find.cpp +++ b/src/mongo/db/query/find.cpp @@ -677,7 +677,9 @@ std::string runQuery(OperationContext* opCtx, if (PlanExecutor::FAILURE == state || PlanExecutor::DEAD == state) { error() << "Plan executor error during find: " << PlanExecutor::statestr(state) << ", stats: " << redact(Explain::getWinningPlanStats(exec.get())); - uasserted(17144, "Executor error: " + WorkingSetCommon::toStatusString(obj)); + uassertStatusOKWithContext(WorkingSetCommon::getMemberObjectStatus(obj), + "Executor error during OP_QUERY find"); + MONGO_UNREACHABLE; } // Before saving the cursor, ensure that whatever plan we established happened with the expected diff --git a/src/mongo/db/query/plan_executor.cpp b/src/mongo/db/query/plan_executor.cpp index a85210d0751..54d56cfb313 100644 --- a/src/mongo/db/query/plan_executor.cpp +++ b/src/mongo/db/query/plan_executor.cpp @@ -488,7 +488,7 @@ PlanExecutor::ExecState PlanExecutor::waitForInserts(CappedInsertNotifierData* n PlanExecutor::ExecState PlanExecutor::getNextImpl(Snapshotted<BSONObj>* objOut, RecordId* dlOut) { if (MONGO_FAIL_POINT(planExecutorAlwaysFails)) { - Status status(ErrorCodes::OperationFailed, + Status status(ErrorCodes::InternalError, str::stream() << "PlanExecutor hit planExecutorAlwaysFails fail point"); *objOut = Snapshotted<BSONObj>(SnapshotId(), WorkingSetCommon::buildMemberStatusObject(status)); diff --git a/src/mongo/db/s/check_sharding_index_command.cpp b/src/mongo/db/s/check_sharding_index_command.cpp index 2d0d499fb1b..b638c9a0e7d 100644 --- a/src/mongo/db/s/check_sharding_index_command.cpp +++ b/src/mongo/db/s/check_sharding_index_command.cpp @@ -202,9 +202,8 @@ public: if (PlanExecutor::DEAD == state || PlanExecutor::FAILURE == state) { return CommandHelpers::appendCommandStatus( result, - Status(ErrorCodes::OperationFailed, - str::stream() << "Executor error while checking sharding index: " - << WorkingSetCommon::toStatusString(currKey))); + WorkingSetCommon::getMemberObjectStatus(currKey).withContext( + "Executor error while checking sharding index")); } return true; diff --git a/src/mongo/db/s/migration_chunk_cloner_source_legacy.cpp b/src/mongo/db/s/migration_chunk_cloner_source_legacy.cpp index 977c736458e..220e2658a35 100644 --- a/src/mongo/db/s/migration_chunk_cloner_source_legacy.cpp +++ b/src/mongo/db/s/migration_chunk_cloner_source_legacy.cpp @@ -670,9 +670,8 @@ Status MigrationChunkClonerSourceLegacy::_storeCurrentLocs(OperationContext* opC } if (PlanExecutor::DEAD == state || PlanExecutor::FAILURE == state) { - return {ErrorCodes::InternalError, - str::stream() << "Executor error while scanning for documents belonging to chunk: " - << WorkingSetCommon::toStatusString(obj)}; + return WorkingSetCommon::getMemberObjectStatus(obj).withContext( + "Executor error while scanning for documents belonging to chunk"); } const uint64_t collectionAverageObjectSize = collection->averageObjectSize(opCtx); diff --git a/src/mongo/db/s/split_vector.cpp b/src/mongo/db/s/split_vector.cpp index 3fd68070786..9b7bcdaa2eb 100644 --- a/src/mongo/db/s/split_vector.cpp +++ b/src/mongo/db/s/split_vector.cpp @@ -215,9 +215,8 @@ StatusWith<std::vector<BSONObj>> splitVector(OperationContext* opCtx, } if (PlanExecutor::DEAD == state || PlanExecutor::FAILURE == state) { - return {ErrorCodes::OperationFailed, - "Executor error during splitVector command: " + - WorkingSetCommon::toStatusString(currKey)}; + return WorkingSetCommon::getMemberObjectStatus(currKey).withContext( + "Executor error during splitVector command"); } if (!force) diff --git a/src/mongo/dbtests/documentsourcetests.cpp b/src/mongo/dbtests/documentsourcetests.cpp index 98ab5fc9e68..ebfaccbde5c 100644 --- a/src/mongo/dbtests/documentsourcetests.cpp +++ b/src/mongo/dbtests/documentsourcetests.cpp @@ -388,7 +388,8 @@ TEST_F(DocumentSourceCursorTest, TailableAwaitDataCursorShouldErrorAfterTimeout) DocumentSourceCursor::create(readLock.getCollection(), std::move(planExecutor), ctx()); ON_BLOCK_EXIT([cursor]() { cursor->dispose(); }); - ASSERT_THROWS_CODE(cursor->getNext().isEOF(), AssertionException, ErrorCodes::QueryPlanKilled); + ASSERT_THROWS_CODE( + cursor->getNext().isEOF(), AssertionException, ErrorCodes::ExceededTimeLimit); } TEST_F(DocumentSourceCursorTest, NonAwaitDataCursorShouldErrorAfterTimeout) { @@ -425,7 +426,8 @@ TEST_F(DocumentSourceCursorTest, NonAwaitDataCursorShouldErrorAfterTimeout) { DocumentSourceCursor::create(readLock.getCollection(), std::move(planExecutor), ctx()); ON_BLOCK_EXIT([cursor]() { cursor->dispose(); }); - ASSERT_THROWS_CODE(cursor->getNext().isEOF(), AssertionException, ErrorCodes::QueryPlanKilled); + ASSERT_THROWS_CODE( + cursor->getNext().isEOF(), AssertionException, ErrorCodes::ExceededTimeLimit); } TEST_F(DocumentSourceCursorTest, TailableAwaitDataCursorShouldErrorAfterBeingKilled) { |