SERVER-28196 Make legacy query and getMore appear in a consistent format across currentOp, profiler and logs

Closes #1139

Signed-off-by: David Storch <david.storch@10gen.com>

6 files changed, 207 insertions, 43 deletions

diff --git a/jstests/core/profile_getmore.js b/jstests/core/profile_getmore.js
index 09ec72d4bd4..a72f0ea236f 100644
--- a/jstests/core/profile_getmore.js
+++ b/jstests/core/profile_getmore.js
@@ -8,7 +8,6 @@
     var testDB = db.getSiblingDB("profile_getmore");
     assert.commandWorked(testDB.dropDatabase());
     var coll = testDB.getCollection("test");
-    var isLegacyReadMode = (db.getMongo().readMode() === "legacy");
 
     testDB.setProfilingLevel(2);
 
@@ -37,11 +36,11 @@
     assert.eq(profileObj.docsExamined, 2, tojson(profileObj));
     assert.eq(profileObj.cursorid, cursorId, tojson(profileObj));
     assert.eq(profileObj.nreturned, 2, tojson(profileObj));
+    assert.eq(profileObj.query.getMore, cursorId, tojson(profileObj));
+    assert.eq(profileObj.query.collection, coll.getName(), tojson(profileObj));
     assert.eq(profileObj.query.batchSize, 2, tojson(profileObj));
-    if (!isLegacyReadMode) {
-        assert.eq(profileObj.originatingCommand.filter, {a: {$gt: 0}});
-        assert.eq(profileObj.originatingCommand.sort, {a: 1});
-    }
+    assert.eq(profileObj.originatingCommand.filter, {a: {$gt: 0}});
+    assert.eq(profileObj.originatingCommand.sort, {a: 1});
     assert.eq(profileObj.planSummary, "IXSCAN { a: 1 }", tojson(profileObj));
     assert(profileObj.execStats.hasOwnProperty("stage"), tojson(profileObj));
     assert(profileObj.hasOwnProperty("responseLength"), tojson(profileObj));
@@ -110,11 +109,10 @@
 
     assert.eq(profileObj.ns, coll.getFullName(), tojson(profileObj));
     assert.eq(profileObj.op, "getmore", tojson(profileObj));
-    if (!isLegacyReadMode) {
-        assert.eq(profileObj.originatingCommand.pipeline[0],
-                  {$match: {a: {$gte: 0}}},
-                  tojson(profileObj));
-    }
+    assert.eq(profileObj.query.getMore, cursorId, tojson(profileObj));
+    assert.eq(profileObj.query.collection, coll.getName(), tojson(profileObj));
+    assert.eq(
+        profileObj.originatingCommand.pipeline[0], {$match: {a: {$gte: 0}}}, tojson(profileObj));
     assert.eq(profileObj.cursorid, cursorId, tojson(profileObj));
     assert.eq(profileObj.nreturned, 20, tojson(profileObj));
     assert.eq(profileObj.planSummary, "IXSCAN { a: 1 }", tojson(profileObj));
@@ -122,7 +120,5 @@
     assert.eq(profileObj.keysExamined, 20, tojson(profileObj));
     assert.eq(profileObj.docsExamined, 20, tojson(profileObj));
     assert.eq(profileObj.appName, "MongoDB Shell", tojson(profileObj));
-    if (!isLegacyReadMode) {
-        assert.eq(profileObj.originatingCommand.hint, {a: 1}, tojson(profileObj));
-    }
+    assert.eq(profileObj.originatingCommand.hint, {a: 1}, tojson(profileObj));
 })();
diff --git a/jstests/noPassthrough/currentop_query.js b/jstests/noPassthrough/currentop_query.js
index c4e2d87c1a6..dd5c0992dbb 100644
--- a/jstests/noPassthrough/currentop_query.js
+++ b/jstests/noPassthrough/currentop_query.js
@@ -271,7 +271,8 @@
         });
 
         //
-        // Confirm currentOp content for getMore.
+        // Confirm currentOp content for getMore. This case tests command and legacy getMore with an
+        // originating find command.
         //
         coll.drop();
         for (i = 0; i < 10; ++i) {
@@ -284,15 +285,10 @@
 
         TestData.commandResult = cmdRes;
 
-        var filter;
-        if (params.readMode === "legacy") {
-            filter = {"op": "getmore", "query.filter.$comment": "currentop_query"};
-        } else {
-            filter = {
-                "query.getMore": TestData.commandResult.cursor.id,
-                "originatingCommand.filter.$comment": "currentop_query"
-            };
-        }
+        var filter = {
+            "query.getMore": TestData.commandResult.cursor.id,
+            "originatingCommand.filter.$comment": "currentop_query"
+        };
 
         confirmCurrentOpContents({
             test: function() {
@@ -306,6 +302,49 @@
         delete TestData.commandResult;
 
         //
+        // Confirm that currentOp displays upconverted getMore and originatingCommand in the case of
+        // a legacy query.
+        //
+        if (params.readMode === "legacy") {
+            let filter = {
+                "query.getMore": {$gt: 0},
+                "query.collection": "currentop_query",
+                "query.batchSize": 2,
+                originatingCommand: {
+                    find: "currentop_query",
+                    filter: {},
+                    ntoreturn: 2,
+                    comment: "currentop_query"
+                }
+            };
+
+            confirmCurrentOpContents({
+                test: function() {
+                    // Temporarily disable hanging yields so that we can iterate the first batch.
+                    assert.commandWorked(
+                        db.adminCommand({configureFailPoint: "setYieldAllLocksHang", mode: "off"}));
+
+                    let cursor =
+                        db.currentop_query.find({}).comment("currentop_query").batchSize(2);
+
+                    // Exhaust the current batch so that the next request will force a getMore.
+                    while (cursor.objsLeftInBatch() > 0) {
+                        cursor.next();
+                    }
+
+                    // Set yields to hang so that we can check currentOp output.
+                    assert.commandWorked(db.adminCommand(
+                        {configureFailPoint: "setYieldAllLocksHang", mode: "alwaysOn"}));
+
+                    assert.eq(cursor.itcount(), 8);
+                },
+                operation: "getmore",
+                planSummary: "COLLSCAN",
+                currentOpFilter: filter
+            });
+        }
+
+        //
         // Confirm 512 byte size limit for currentOp query field.
         //
         coll.drop();
diff --git a/jstests/noPassthrough/log_find_getmore.js b/jstests/noPassthrough/log_find_getmore.js
new file mode 100644
index 00000000000..347749bc909
--- /dev/null
+++ b/jstests/noPassthrough/log_find_getmore.js
@@ -0,0 +1,115 @@
+/**
+ * Confirms that the log output for command and legacy find and getMore are in the expected format.
+ * Legacy operations should be upconverted to match the format of their command counterparts.
+ */
+(function() {
+    "use strict";
+
+    // For checkLog and getLatestProfilerEntry.
+    load("jstests/libs/check_log.js");
+    load("jstests/libs/profiler.js");
+
+    const conn = MongoRunner.runMongod();
+    assert.neq(null, conn, "mongod was unable to start up");
+
+    const testDB = conn.getDB("log_getmore");
+    const coll = testDB.test;
+
+    assert.commandWorked(testDB.dropDatabase());
+
+    for (let i = 1; i <= 10; ++i) {
+        assert.writeOK(coll.insert({a: i}));
+    }
+
+    assert.commandWorked(coll.createIndex({a: 1}));
+
+    // Set the diagnostic logging threshold to capture all operations, and enable profiling so that
+    // we can easily retrieve cursor IDs in all cases.
+    assert.commandWorked(testDB.setProfilingLevel(2, -1));
+
+    //
+    // Command tests.
+    //
+    testDB.getMongo().forceReadMode("commands");
+
+    // TEST: Verify the log format of the find command.
+    let cursor = coll.find({a: {$gt: 0}}).sort({a: 1}).skip(1).limit(10).hint({a: 1}).batchSize(5);
+    cursor.next();  // Perform initial query and retrieve first document in batch.
+
+    let cursorid = getLatestProfilerEntry(testDB).cursorid;
+
+    let logLine =
+        'command log_getmore.test appName: "MongoDB Shell" command: find { find: "test", filter:' +
+        ' { a: { $gt: 0.0 } }, skip: 1.0, batchSize: 5.0, limit: 10.0, singleBatch: false, sort:' +
+        ' { a: 1.0 }, hint: { a: 1.0 } }';
+
+    // Check the logs to verify that find appears as above.
+    checkLog.contains(conn, logLine);
+
+    // TEST: Verify the log format of a getMore command following a find command.
+
+    assert.eq(cursor.itcount(), 8);  // Iterate the cursor established above to trigger getMore.
+
+    logLine = 'command log_getmore.test appName: "MongoDB Shell" command: getMore { getMore: ' +
+        cursorid + ', collection: "test", batchSize: 5.0 } originatingCommand: { find: "test", ' +
+        'filter: { a: { $gt: 0.0 } }, skip: 1.0, batchSize: 5.0, limit: 10.0, singleBatch: ' +
+        'false, sort: { a: 1.0 }, hint: { a: 1.0 } }';
+
+    checkLog.contains(conn, logLine);
+
+    // TEST: Verify the log format of a getMore command following an aggregation.
+    cursor = coll.aggregate([{$match: {a: {$gt: 0}}}], {cursor: {batchSize: 0}, hint: {a: 1}});
+    cursorid = getLatestProfilerEntry(testDB).cursorid;
+
+    assert.eq(cursor.itcount(), 10);
+
+    logLine = 'command log_getmore.test appName: "MongoDB Shell" command: getMore { getMore: ' +
+        cursorid + ', collection: "test" } originatingCommand: { aggregate: "test", pipeline: ' +
+        '[ { $match: { a: { $gt: 0.0 } } } ], cursor: { batchSize: 0.0 }, hint: { a: 1.0 } }';
+
+    checkLog.contains(conn, logLine);
+
+    //
+    // Legacy tests.
+    //
+    testDB.getMongo().forceReadMode("legacy");
+
+    // TEST: Verify the log format of a legacy find. This should be upconverted to resemble a find
+    // command.
+    cursor = coll.find({a: {$gt: 0}}).sort({a: 1}).skip(1).limit(10).hint({a: 1}).batchSize(5);
+    cursor.next();
+
+    cursorid = getLatestProfilerEntry(testDB).cursorid;
+
+    logLine =
+        'query log_getmore.test appName: "MongoDB Shell" query: { find: "test", filter: { a: { ' +
+        '$gt: 0.0 } }, skip: 1, ntoreturn: 5, sort: { a: 1.0 }, hint: { a: 1.0 } }';
+
+    checkLog.contains(conn, logLine);
+
+    // TEST: Verify that a legacy getMore following a find is logged in the expected format. This
+    // should be upconverted to resemble a getMore command, with the preceding upconverted legacy
+    // find in the originatingCommand field.
+
+    assert.eq(cursor.itcount(), 8);  // Iterate the cursor established above to trigger getMore.
+
+    logLine = 'getmore log_getmore.test appName: "MongoDB Shell" query: { getMore: ' + cursorid +
+        ', collection: "test", batchSize: 5 } originatingCommand: { find: "test", filter: { a: {' +
+        ' $gt: 0.0 } }, skip: 1, ntoreturn: 5, sort: { a: 1.0 }, hint: { a: 1.0 } }';
+
+    checkLog.contains(conn, logLine);
+
+    // TEST: Verify that a legacy getMore following an aggregation is logged in the expected format.
+    // This should be upconverted to resemble a getMore command, with the preceding aggregation in
+    // the originatingCommand field.
+    cursor = coll.aggregate([{$match: {a: {$gt: 0}}}], {cursor: {batchSize: 0}, hint: {a: 1}});
+    cursorid = getLatestProfilerEntry(testDB).cursorid;
+
+    assert.eq(cursor.itcount(), 10);
+
+    logLine = 'getmore log_getmore.test appName: "MongoDB Shell" query: { getMore: ' + cursorid +
+        ', collection: "test", batchSize: 0 } originatingCommand: { aggregate: "test", pipeline:' +
+        ' [ { $match: { a: { $gt: 0.0 } } } ], cursor: { batchSize: 0.0 }, hint: { a: 1.0 } }';
+
+    checkLog.contains(conn, logLine);
+})();
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index 3b5f71f23ce..51016d486ce 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -39,7 +39,6 @@
 #include "mongo/db/client.h"
 #include "mongo/db/commands.h"
 #include "mongo/db/commands/server_status_metric.h"
-#include "mongo/db/cursor_id.h"
 #include "mongo/db/json.h"
 #include "mongo/db/query/getmore_request.h"
 #include "mongo/db/query/plan_summary_stats.h"
@@ -69,10 +68,8 @@ const std::vector<const char*> kDollarQueryModifiers = {
     "$maxTimeMS",
 };
 
-/**
- * For a find using the OP_QUERY protocol (as opposed to the commands protocol), upconverts the
- * "query" field so that the profiling entry matches that of the find command.
- */
+}  // namespace
+
 BSONObj upconvertQueryEntry(const BSONObj& query,
                             const NamespaceString& nss,
                             int ntoreturn,
@@ -128,10 +125,6 @@ BSONObj upconvertQueryEntry(const BSONObj& query,
     return bob.obj();
 }
 
-/**
- * For a getMore using OP_GET_MORE, as opposed to getMore command, upconverts the "query" field so
- * that the profiling entry matches that of the getMore command.
- */
 BSONObj upconvertGetMoreEntry(const NamespaceString& nss, CursorId cursorId, int ntoreturn) {
     return GetMoreRequest(nss,
                           cursorId,
@@ -143,8 +136,6 @@ BSONObj upconvertGetMoreEntry(const NamespaceString& nss, CursorId cursorId, int
         .toBSON();
 }
 
-}  // namespace
-
 /**
  * This type decorates a Client object with a stack of active CurOp objects.
  *
@@ -432,7 +423,16 @@ string OpDebug::report(Client* client,
         }
     }
 
-    auto query = curop.query();
+    BSONObj query;
+
+    // If necessary, upconvert legacy find operations so that their log lines resemble their find
+    // command counterpart.
+    if (!iscommand && networkOp == dbQuery) {
+        query =
+            upconvertQueryEntry(curop.query(), NamespaceString(curop.getNS()), ntoreturn, ntoskip);
+    } else {
+        query = curop.query();
+    }
 
     if (!query.isEmpty()) {
         if (iscommand) {
@@ -556,9 +556,6 @@ void OpDebug::append(const CurOp& curop,
                             upconvertQueryEntry(curop.query(), nss, ntoreturn, ntoskip),
                             maxElementSize,
                             &b);
-    } else if (!iscommand && networkOp == dbGetMore) {
-        appendAsObjOrString(
-            "query", upconvertGetMoreEntry(nss, cursorid, ntoreturn), maxElementSize, &b);
     } else if (curop.haveQuery()) {
         const char* fieldName = (logicalOp == LogicalOp::opCommand) ? "command" : "query";
         appendAsObjOrString(fieldName, curop.query(), maxElementSize, &b);
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index f0aea88f81d..4e0ef0d2d7b 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -33,6 +33,7 @@
 
 #include "mongo/base/disallow_copying.h"
 #include "mongo/db/commands.h"
+#include "mongo/db/cursor_id.h"
 #include "mongo/db/operation_context.h"
 #include "mongo/db/server_options.h"
 #include "mongo/platform/atomic_word.h"
@@ -327,7 +328,7 @@ public:
     }
 
     /**
-     * Sets the original command object. Used only by the getMore command.
+     * Sets the original command object.
      */
     void setOriginatingCommand_inlock(const BSONObj& commandObj) {
         _originatingCommand = commandObj.getOwned();
@@ -457,4 +458,18 @@ private:
 
     std::string _planSummary;
 };
+
+/**
+ * Upconverts a legacy query object such that it matches the format of the find command.
+ */
+BSONObj upconvertQueryEntry(const BSONObj& query,
+                            const NamespaceString& nss,
+                            int ntoreturn,
+                            int ntoskip);
+
+/**
+ * Generates a getMore command object from the specified namespace, cursor ID and batchsize.
+ */
+BSONObj upconvertGetMoreEntry(const NamespaceString& nss, CursorId cursorId, int ntoreturn);
+
 }  // namespace mongo
diff --git a/src/mongo/db/query/find.cpp b/src/mongo/db/query/find.cpp
index 9fcaa7cef02..f60bbe33ae5 100644
--- a/src/mongo/db/query/find.cpp
+++ b/src/mongo/db/query/find.cpp
@@ -380,9 +380,11 @@ Message getMore(OperationContext* txn,
             stdx::lock_guard<Client> lk(*txn->getClient());
             curOp.setPlanSummary_inlock(planSummary);
 
-            // Ensure that the original query or command object is available in the slow query log,
-            // profiler and currentOp.
-            curOp.setQuery_inlock(cc->getQuery());
+            // Ensure that the original query object is available in the slow query log, profiler
+            // and currentOp. Upconvert _query to resemble a getMore command, and set the original
+            // command or upconverted legacy query in the originatingCommand field.
+            curOp.setQuery_inlock(upconvertGetMoreEntry(nss, cursorid, ntoreturn));
+            curOp.setOriginatingCommand_inlock(cc->getQuery());
         }
 
         PlanExecutor::ExecState state;
@@ -673,7 +675,7 @@ std::string runQuery(OperationContext* txn,
              nss.ns(),
              txn->recoveryUnit()->isReadingFromMajorityCommittedSnapshot(),
              qr.getOptions(),
-             qr.getFilter()});
+             upconvertQueryEntry(q.query, qr.nss(), q.ntoreturn, q.ntoskip)});
         ccId = pinnedCursor.getCursor()->cursorid();
 
         LOG(5) << "caching executor with cursorid " << ccId << " after returning " << numResults