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

mongoreplay does not remap getMore cursor IDs

    • Type: Icon: Bug Bug
    • Resolution: Won't Fix
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: mongoreplay
    • None

      Observed on v3.4.16.

      It looks like mongoreplay plays back the original (recorded) cursor ID for getMores rather than remapping them to the cursor associated with the replayed command.

      Attached is the test.py I used. Repro steps:

      $ mlaunch init --single
      
      # run the POC driver for a few seconds to populate the collection.
      $ java -jar POCDriver.jar
      
      # Trace all operations
      > db.setProfilingLevel(1,-1)
      
      $ mongoreplay record -i lo0  -e "port 27017"  -p playback
      
      # Run for a few seconds to generate gemores.
      $ python test.py
      
      # kill mongoreplay
      # ^Ccompleted with 617 packets dropped
      
      # Restart mongod to ensure cursors are still open / unexhausted
      # Trace all operations
      > db.setProfilingLevel(1,-1)
      
      $ mongoreplay play -p playback -v
       

      The replayed getMore uses the recorded cursor id 21012219614 instead of the expected 21012219614 13569681992 [Josef edit Oct 22nd: fixed cursor ID].

      grep 'find\|getMore' recorded.log
      2018-10-19T18:03:22.646+0200 I COMMAND  [conn12] command POCDB.POCCOLL command: find { find: "POCCOLL", filter: {} } planSummary: COLLSCAN cursorid:21012219614 keysExamined:0 docsExamined:101 numYields:0 nreturned:101 reslen:30341 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
      2018-10-19T18:03:22.752+0200 I COMMAND  [conn12] command POCDB.POCCOLL command: getMore { getMore: 21012219614, collection: "POCCOLL" } originatingCommand: { find: "POCCOLL", filter: {} } planSummary: COLLSCAN cursorid:21012219614 keysExamined:0 docsExamined:55520 numYields:434 nreturned:55519 reslen:16776993 locks:{ Global: { acquireCount: { r: 870 } }, Database: { acquireCount: { r: 435 } }, Collection: { acquireCount: { r: 435 } } } protocol:op_query 39ms
      
      $ grep 'find\|getMore' replayed.log
      2018-10-19T18:06:19.482+0200 I COMMAND  [conn3] command POCDB.POCCOLL command: find { find: "POCCOLL", filter: {} } planSummary: COLLSCAN cursorid:13569681992 keysExamined:0 docsExamined:101 numYields:0 nreturned:101 reslen:30341 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
      2018-10-19T18:06:19.539+0200 I COMMAND  [conn3] command POCDB.POCCOLL command: getMore { getMore: 21012219614, collection: "POCCOLL" } cursorid:21012219614 numYields:0 reslen:129 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 0ms
      

      Attaching full logs and playback file.

        1. test.py
          0.2 kB
        2. replayed.log
          11 kB
        3. recorded.log
          18 kB
        4. playback
          34 kB

            Assignee:
            Unassigned Unassigned
            Reporter:
            josef.ahmad@mongodb.com Josef Ahmad
            Votes:
            1 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: