Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-33553

OP_KILL_CURSORS fails on mongos: Unable to check out cursor for killCursor

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 3.6.6
    • Affects Version/s: 3.6.3
    • Component/s: None
    • Fully Compatible
    • ALL
      1. Start a 3.6.3 sharded cluster with auth enabled.
      2. Create a cursor via the find command with a session.
      3. Send an OP_KILL_CURSORS message to mongos.
      4. The cursor is not killed.
    • Query 2018-06-04, Query 2018-06-18

      Sending OP_KILL_CURSORS to 3.6.3 Mongos fails when auth is enabled with: "Unable to check out cursor for killCursor. Namespace: 'pymongo_test.test', cursor id: 3368188369600609201."

      Here is the mongos log including the initial find command, OP_KILL_CURSORS request, and a final getMore that succeeds:

      2018-02-28T12:22:07.571-0800 D EXECUTOR [conn47] Scheduling remote command request: RemoteCommand 1473 -- target:localhost:27018 db:pymongo_test cmd:{ find: "test", batchSize: 1, shardVersion: [ Timestamp(0, 0), ObjectId('000000000000000000000000') ], lsid: { id: UUID("12da197b-c453-44d7-9a80-f35416b3b5c9"), uid: BinData(0, 78E672A9F1DF895A5FBE23C35A0004466CCD167529F1405D95628DE7416FF5FA) } }
2018-02-28T12:22:07.571-0800 D ASIO     [conn47] startCommand: RemoteCommand 1473 -- target:localhost:27018 db:pymongo_test cmd:{ find: "test", batchSize: 1, shardVersion: [ Timestamp(0, 0), ObjectId('000000000000000000000000') ], lsid: { id: UUID("12da197b-c453-44d7-9a80-f35416b3b5c9"), uid: BinData(0, 78E672A9F1DF895A5FBE23C35A0004466CCD167529F1405D95628DE7416FF5FA) } }
2018-02-28T12:22:07.571-0800 D ASIO     [NetworkInterfaceASIO-TaskExecutorPool-3-0] Initiating asynchronous command: RemoteCommand 1473 -- target:localhost:27018 db:pymongo_test cmd:{ find: "test", batchSize: 1, shardVersion: [ Timestamp(0, 0), ObjectId('000000000000000000000000') ], lsid: { id: UUID("12da197b-c453-44d7-9a80-f35416b3b5c9"), uid: BinData(0, 78E672A9F1DF895A5FBE23C35A0004466CCD167529F1405D95628DE7416FF5FA) } }
2018-02-28T12:22:07.571-0800 D NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-3-0] Compressing message with zlib
2018-02-28T12:22:07.571-0800 D ASIO     [NetworkInterfaceASIO-TaskExecutorPool-3-0] Starting asynchronous command 1473 on host localhost:27018
2018-02-28T12:22:07.572-0800 D NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-3-0] Decompressing message with zlib
2018-02-28T12:22:07.572-0800 D ASIO     [NetworkInterfaceASIO-TaskExecutorPool-3-0] Request 1473 finished with response: { cursor: { firstBatch: [ { _id: 0 } ], id: 93684278245, ns: "pymongo_test.test" }, ok: 1.0, operationTime: Timestamp(1519849327, 208), $gleStats: { lastOpTime: { ts: Timestamp(1519849053, 208), t: 2 }, electionId: ObjectId('7fffffff0000000000000002') }, $clusterTime: { clusterTime: Timestamp(1519849327, 208), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $configServerState: { opTime: { ts: Timestamp(1519849327, 7), t: 2 } } }
2018-02-28T12:22:07.572-0800 D EXECUTOR [NetworkInterfaceASIO-TaskExecutorPool-3-0] Received remote response: RemoteResponse --  cmd:{ cursor: { firstBatch: [ { _id: 0 } ], id: 93684278245, ns: "pymongo_test.test" }, ok: 1.0, operationTime: Timestamp(1519849327, 208), $gleStats: { lastOpTime: { ts: Timestamp(1519849053, 208), t: 2 }, electionId: ObjectId('7fffffff0000000000000002') }, $clusterTime: { clusterTime: Timestamp(1519849327, 208), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $configServerState: { opTime: { ts: Timestamp(1519849327, 7), t: 2 } } }
2018-02-28T12:22:07.572-0800 D SHARDING [conn47] Command end db: pymongo_test msg id: 893351816
2018-02-28T12:22:08.344-0800 D NETWORK  [conn47] Request::process begin ns:  msg id: -1116753739 op: killcursors
2018-02-28T12:22:08.344-0800 D SHARDING [conn47] Unable to check out cursor for killCursor.  Namespace: 'pymongo_test.test', cursor id: 3368188369600609201.
2018-02-28T12:22:08.344-0800 D NETWORK  [conn47] Request::process end ns:  msg id: -1116753739 op: killcursors
2018-02-28T12:22:09.578-0800 D SHARDING [conn47] Command begin db: pymongo_test msg id: 1954899097
2018-02-28T12:22:09.578-0800 D EXECUTOR [conn47] Scheduling remote command request: RemoteCommand 1475 -- target:localhost:27018 db:pymongo_test cmd:{ getMore: 93684278245, collection: "test", batchSize: 1, lsid: { id: UUID("12da197b-c453-44d7-9a80-f35416b3b5c9"), uid: BinData(0, 78E672A9F1DF895A5FBE23C35A0004466CCD167529F1405D95628DE7416FF5FA) } }
2018-02-28T12:22:09.578-0800 D ASIO     [conn47] startCommand: RemoteCommand 1475 -- target:localhost:27018 db:pymongo_test cmd:{ getMore: 93684278245, collection: "test", batchSize: 1, lsid: { id: UUID("12da197b-c453-44d7-9a80-f35416b3b5c9"), uid: BinData(0, 78E672A9F1DF895A5FBE23C35A0004466CCD167529F1405D95628DE7416FF5FA) } }
2018-02-28T12:22:09.578-0800 D ASIO     [NetworkInterfaceASIO-TaskExecutorPool-0-0] Initiating asynchronous command: RemoteCommand 1475 -- target:localhost:27018 db:pymongo_test cmd:{ getMore: 93684278245, collection: "test", batchSize: 1, lsid: { id: UUID("12da197b-c453-44d7-9a80-f35416b3b5c9"), uid: BinData(0, 78E672A9F1DF895A5FBE23C35A0004466CCD167529F1405D95628DE7416FF5FA) } }
2018-02-28T12:22:09.578-0800 D NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-0-0] Compressing message with zlib
2018-02-28T12:22:09.578-0800 D ASIO     [NetworkInterfaceASIO-TaskExecutorPool-0-0] Starting asynchronous command 1475 on host localhost:27018
2018-02-28T12:22:09.579-0800 D NETWORK  [NetworkInterfaceASIO-TaskExecutorPool-0-0] Decompressing message with zlib
2018-02-28T12:22:09.579-0800 D ASIO     [NetworkInterfaceASIO-TaskExecutorPool-0-0] Request 1475 finished with response: { cursor: { nextBatch: [ { _id: 1 } ], id: 93684278245, ns: "pymongo_test.test" }, ok: 1.0, operationTime: Timestamp(1519849327, 208), $gleStats: { lastOpTime: Timestamp(0, 0), electionId: ObjectId('7fffffff0000000000000002') }, $clusterTime: { clusterTime: Timestamp(1519849327, 208), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $configServerState: { opTime: { ts: Timestamp(1519849327, 7), t: 2 } } }

      I can reproduce this on 3.6.3 but not on mongodb latest version:
      mongos version v3.7.2-169-g67d04f1
      git version: 67d04f1a286b23ea824bdfb7042462d7da1b515d

            Assignee:
            ian.boros@mongodb.com Ian Boros
            Reporter:
            shane.harvey@mongodb.com Shane Harvey
            Votes:
            2 Vote for this issue
            Watchers:
            14 Start watching this issue

              Created:
              Updated:
              Resolved: