The test runs this aggregate command:
[js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] ---- [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] testing command { [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] "mapReduce" : "foo", [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] "map" : function() { [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] emit(this.x, 1); [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] }, [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] "reduce" : function(key, values) { [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] return Array.sum(values); [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] }, [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] "out" : { [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] "inline" : 1 [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] } [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] } [js_test:safe_secondary_reads_single_migration_waitForDelete] [jsTest] ----
We expect that there's exactly one operation in the profiler matching this query:
{ "command.shardVersion" : { "$exists" : true }, "command.shardVersion.0" : { "$ne" : Timestamp(0, 0) }, "command.shardVersion.1" : { "$ne" : ObjectId("00000000ffffffffffffffff") }, "command.$readPreference" : { "mode" : "secondary" }, "command.readConcern" : { "level" : "local" }, "errCode" : { "$ne" : 13388 }, "command.aggregate" : "foo" }
However, the profiler has two matching aggregate commands out of four entries total (two aggregates, a getMore, and the find itself on system.profile).
Here's the first aggregate for the mapreduce command:
{ "op" : "command", "ns" : "test.foo", "command" : { "aggregate" : "foo", "pipeline" : [ { "$project" : { "emits" : { "$_internalJsEmit" : { "eval" : "function() {\n emit(this.x, 1);\n }", "this" : "$$ROOT" } }, "_id" : false } }, { "$unwind" : { "path" : "$emits" } }, { "$group" : { "_id" : "$emits.k", "value" : { "$_internalJsReduce" : { "data" : "$emits", "eval" : "function(key, values) {\n return Array.sum(values);\n }" } } } } ], "cursor" : { "batchSize" : 0 }, "allowDiskUse" : true, "fromMongos" : true, "let" : { "IS_MR" : true, "NOW" : ISODate("2021-04-12T22:19:31.033Z"), "CLUSTER_TIME" : Timestamp(1618265970, 87) }, "isMapReduceCommand" : true, "$queryOptions" : { "$readPreference" : { "mode" : "secondary" } }, "readConcern" : { "level" : "local" }, "needsMerge" : true, // etc...
The other aggregate command is a $mergeCursors:
"op" : "command", "ns" : "test.foo", "command" : { "aggregate" : "foo", "pipeline" : [ { "$mergeCursors" : { "lsid" : { "id" : UUID("16770975-1dd1-4392-b907-948771436821"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "compareWholeSortKey" : false, "remotes" : [ { "shardId" : "safe_secondary_reads_single_migration_waitForDelete-rs0", "hostAndPort" : "ip-10-122-47-239.ec2.internal:21521", "cursorResponse" : { "cursor" : { "id" : NumberLong("2479107308808163874"), "ns" : "test.foo", "firstBatch" : [ ] }, "ok" : 1 } }, { "shardId" : "safe_secondary_reads_single_migration_waitForDelete-rs1", "hostAndPort" : "ip-10-122-47-239.ec2.internal:21523", "cursorResponse" : { "cursor" : { "id" : NumberLong("497587830264602086"), "ns" : "test.foo", "firstBatch" : [ ] }, "ok" : 1 } } ], "tailableMode" : "normal", "nss" : "test.foo", "allowPartialResults" : false, "recordRemoteOpWaitTime" : true } }, { "$group" : { "_id" : "$$ROOT._id", "value" : { "$_internalJsReduce" : { "data" : "$$ROOT.value", "eval" : "function(key, values) {\n return Array.sum(values);\n }" } }, "$doingMerge" : true } } ],
The full output is very large so full logs are attached to the ticket in their entirety.