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

Mongodump - same query, different results

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: 4.0.10
    • Fix Version/s: None
    • 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.

      Description

      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

       

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                backlog-server-tools Backlog - Server Tools Team
                Reporter:
                svope Petr S
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: