Uploaded image for project: 'MongoDB Database Tools'
  1. MongoDB Database Tools
  2. TOOLS-2317

Mongodump - same query, different results

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 4.0.10
    • Component/s: mongodump
    • Labels:
    • Environment:
      Running script from Win10 Enterprise Mongo v 4.0.10, connecting to Standalone instance of MongoDB running version v4.0.2.

      Hi everyone,

       

      I have a problem running backup script using mongodump. The problem is that whenever I run the exact same query from cmd, the results is different (the backed up document count is different). 

       

      DB Model (index on "_id"):

      {
         "_id" :

      {        "DateTime" : ISODate("2018-11-27T05:00:00.370Z"),        "Ticks" : NumberLong(636788916003706990) }

      ,

      "SomeData" : "Data"
      }

       

      Running query from cmd:

      mongodump --verbose --uri mongodb://User:Password@Machine:Port/DBName?authSource=AuthDB --gzip --numParallelCollections 1 --collection "MyCollection" --archive="C:\Dumps" --query "{ _id: { $gte:

      { DateTime : new Date('2019-04-04T00:00:00.000Z'), Ticks: NumberLong('636899328000000000')}

      , $lte: { DateTime: new Date('2019-04-05T00:00:00.000Z'), Ticks: NumberLong('636900192000000000') } } }"

       

      Run like 8x times (mongodump outputs, there should be 6 docs):

      2019-06-25T11:09:23.559+0200 done dumping DBName.MyCollection (6 documents)

      2019-06-25T11:09:26.626+0200 done dumping DBName.MyCollection (2545 documents)

       2019-06-25T11:40:14.085+0200 done dumping DBName.MyCollection (0 documents)

      What I see in MongoLog:

      2019-06-25T11:09:23.521+0200 D COMMAND [conn643310] run command DBName.$cmd { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" }
2019-06-25T11:09:23.522+0200 D QUERY [conn643310] Relevant index 0 is kp: { _id: 1 } unique name: '_id_' io: { v: 2, key: { _id: 1 }, name: "_id_", ns: "DBName.MyCollection" }
2019-06-25T11:09:23.522+0200 D QUERY [conn643310] Only one plan is available; it will be run but will not be cached. query: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } } sort: {} projection: {}, planSummary: IXSCAN { _id: 1 }
2019-06-25T11:09:23.523+0200 I COMMAND [conn643310] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
2019-06-25T11:09:26.525+0200 D COMMAND [conn643312] run command DBName.$cmd { find: "MyCollection", filter: { _id: { $gte: { Ticks: 636899328000000000, DateTime: new Date(1554336000000) }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" }
2019-06-25T11:09:26.525+0200 D QUERY [conn643312] Relevant index 0 is kp: { _id: 1 } unique name: '_id_' io: { v: 2, key: { _id: 1 }, name: "_id_", ns: "DBName.MyCollection" }
2019-06-25T11:09:26.525+0200 D QUERY [conn643312] Only one plan is available; it will be run but will not be cached. query: { _id: { $gte: { Ticks: 636899328000000000, DateTime: new Date(1554336000000) }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } } sort: {} projection: {}, planSummary: IXSCAN { _id: 1 }
2019-06-25T11:09:26.528+0200 I COMMAND [conn643312] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { Ticks: 636899328000000000, DateTime: new Date(1554336000000) }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } cursorid:5363372859493 keysExamined:101 docsExamined:101 numYields:0 nreturned:101 reslen:19827 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 2ms
2019-06-25T11:09:26.532+0200 D COMMAND [conn643312] run command DBName.$cmd { getMore: 5363372859493, collection: "MyCollection", $db: "DBName" }
2019-06-25T11:09:26.557+0200 I COMMAND [conn643312] command DBName.MyCollection command: getMore { getMore: 5363372859493, collection: "MyCollection", $db: "DBName" } originatingCommand: { find: "MyCollection", filter: { _id: { $gte: { Ticks: 636899328000000000, DateTime: new Date(1554336000000) }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } cursorid:5363372859493 keysExamined:2444 docsExamined:2444 cursorExhausted:1 numYields:19 nreturned:2444 reslen:594467 locks:{ Global: { acquireCount: { r: 20 } }, Database: { acquireCount: { r: 20 } }, Collection: { acquireCount: { r: 20 } } } protocol:op_query 25ms

       

       What is different in MongoLog when running the same query is "position of embedded query document":

      This is a log where I run the same query mulitple times - sometimes nreturned is 6, sometimes 0, sometimes 101.

      2019-06-25T11:09:10.512+0200 I COMMAND  [conn643300] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1ms
2019-06-25T11:09:14.053+0200 I COMMAND  [conn643302] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 1ms
2019-06-25T11:09:16.547+0200 I COMMAND  [conn643304] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
2019-06-25T11:09:18.853+0200 I COMMAND  [conn643306] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
2019-06-25T11:09:21.172+0200 I COMMAND  [conn643308] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
2019-06-25T11:09:23.523+0200 I COMMAND  [conn643310] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
2019-06-25T11:09:26.528+0200 I COMMAND  [conn643312] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { Ticks: 636899328000000000, DateTime: new Date(1554336000000) }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } cursorid:5363372859493 keysExamined:101 docsExamined:101 numYields:0 nreturned:101 reslen:19827 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 2ms
2019-06-25T11:40:07.212+0200 I COMMAND  [conn643314] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { Ticks: 636899328000000000, DateTime: new Date(1554336000000) }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } cursorid:5361194763604 keysExamined:101 docsExamined:101 numYields:0 nreturned:101 reslen:19827 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 16ms
2019-06-25T11:40:09.641+0200 I COMMAND  [conn643316] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
2019-06-25T11:40:11.840+0200 I COMMAND  [conn643318] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { DateTime: new Date(1554422400000), Ticks: 636900192000000000 } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:6 docsExamined:6 cursorExhausted:1 numYields:0 nreturned:6 reslen:1734 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
2019-06-25T11:40:14.027+0200 I COMMAND  [conn643320] command DBName.MyCollection command: find { find: "MyCollection", filter: { _id: { $gte: { DateTime: new Date(1554336000000), Ticks: 636899328000000000 }, $lte: { Ticks: 636900192000000000, DateTime: new Date(1554422400000) } } }, skip: 0, $readPreference: { mode: "secondaryPreferred" }, $db: "DBName" } planSummary: IXSCAN { _id: 1 } keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:156 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms

       So from my point of view when the query is exactly the same as send from my PC, the dump is ok. In other cases the dump is invalid (0 or some non-sensical number of documents).

      Is this some bug in mongodump? Is my query somehow wrong (how?)?

       

      Thanks

       

            Assignee:
            Unassigned Unassigned
            Reporter:
            svope Petr S
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: