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

mongo shell startSession() should fail if the server doesn't support logical sessions

    XMLWordPrintable

    Details

    • Backwards Compatibility:
      Minor Change
    • Backport Requested:
      v4.0, v3.6
    • Sprint:
      Sharding 2018-08-13, Sharding 2018-08-27, Sharding 2018-09-10

      Description

      Currently db.getMongo().startSession() succeeds and generates a session id when connected to an old server. However the wire protocol checks mean that this session id is never actually used (ie. never actually sent to the server), and so operations sent via the session object also silently succeed (likely old servers would just ignore the lsid field even if it was sent).

      This all conspires to give the false impression that the operations being performed will be part of a logical session. The expected behaviour is that if the server doesn't support logical sessions, then startSession() should throw an exception.

      For example, expose the wire protocol checking functions/consts in SessionAwareClient (kWireVersionSupporting* and serverSupports()), and then check the wire version in the ServerSession constructor (after creating the SessionAwareClient but before calling _startSession() on it).

      3.6.3 with verbose log:

      $ mongo --port 23456 --norc
      MongoDB shell version v3.6.3
      connecting to: mongodb://127.0.0.1:23456/
      MongoDB server version: 3.6.3
      > session = db.getMongo().startSession()
      session { "id" : UUID("29f3064b-10dd-4d8f-835a-0a88cd418266") }
      > session.getDatabase("test").foo.insert({})
      WriteResult({ "nInserted" : 1 })
      > session.getDatabase("test").foo.find()
      { "_id" : ObjectId("5a98c4e41f7838043549f9a1") }
      > db.runCommand({startSession:1})
      {
              "id" : {
                      "id" : UUID("dcbd3bbf-9c04-49d8-8ad9-d49cf88327e2")
              },
              "timeoutMinutes" : 30,
              "ok" : 1
      }
      >
      bye
      

      2018-03-02T14:28:23.712+1100 I NETWORK  [listener] connection accepted from 127.0.0.1:52462 #6 (1 connection now open)
      2018-03-02T14:28:23.713+1100 I NETWORK  [conn6] received client metadata from 127.0.0.1:52462 conn: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.6.3" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
      2018-03-02T14:28:23.713+1100 I COMMAND  [conn6] command admin.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1, client: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.6.3" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }, $db: "admin" } numYields:0 reslen:223 locks:{} protocol:op_query 0ms
      2018-03-02T14:28:23.713+1100 I COMMAND  [conn6] command admin.$cmd appName: "MongoDB Shell" command: whatsmyuri { whatsmyuri: 1, $db: "admin" } numYields:0 reslen:47 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:23.715+1100 I COMMAND  [conn6] command admin.$cmd appName: "MongoDB Shell" command: buildInfo { buildinfo: 1.0, $db: "admin" } numYields:0 reslen:1270 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:23.717+1100 I COMMAND  [conn6] command admin.$cmd appName: "MongoDB Shell" command: getLog { getLog: "startupWarnings", $db: "admin" } numYields:0 reslen:1661 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:23.718+1100 I COMMAND  [conn6] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0, $db: "test" } numYields:0 reslen:208 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:23.719+1100 I COMMAND  [conn6] command test.$cmd appName: "MongoDB Shell" command: buildInfo { buildInfo: 1.0, $db: "test" } numYields:0 reslen:1270 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:23.720+1100 I COMMAND  [conn6] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0, $db: "test" } numYields:0 reslen:208 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:23.720+1100 I COMMAND  [conn6] command admin.$cmd appName: "MongoDB Shell" command: replSetGetStatus { replSetGetStatus: 1.0, forShell: 1.0, $db: "admin" } numYields:0 reslen:106 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:29.077+1100 I COMMAND  [conn6] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0, $db: "test" } numYields:0 reslen:208 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:36.357+1100 I COMMAND  [conn6] command config.transactions appName: "MongoDB Shell" command: find { find: "transactions", filter: { _id: { id: UUID("29f3064b-10dd-4d8f-835a-0a88cd418266"), uid: BinData(0, E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855) } }, ntoreturn: 1, singleBatch: true, $db: "config" } planSummary: EOF keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:92 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_msg 0ms
      2018-03-02T14:28:36.358+1100 D -        [conn6] reloading view catalog for database test
      2018-03-02T14:28:36.358+1100 D STORAGE  [conn6] create collection test.foo {}
      2018-03-02T14:28:36.358+1100 I STORAGE  [conn6] createCollection: test.foo with generated UUID: be030971-65a0-4fa5-94d7-4011dc553ade
      2018-03-02T14:28:36.358+1100 D STORAGE  [conn6] stored meta data for test.foo @ RecordId(5)
      2018-03-02T14:28:36.383+1100 D STORAGE  [conn6] test.foo: clearing plan cache - collection info cache reset
      2018-03-02T14:28:36.383+1100 D STORAGE  [conn6] create uri: table:index-8-7315913501069923330 config: type=file,internal_page_max=16k,leaf_page_max=16k,checksum=on,prefix_compression=true,block_compressor=,,,,key_format=u,value_format=u,app_metadata=(formatVersion=8,infoObj={ "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_", "ns" : "test.foo" }),log=(enabled=true)
      2018-03-02T14:28:36.407+1100 D STORAGE  [conn6] test.foo: clearing plan cache - collection info cache reset
      2018-03-02T14:28:36.407+1100 I COMMAND  [conn6] command test.foo appName: "MongoDB Shell" command: insert { insert: "foo", ordered: true, lsid: { id: UUID("29f3064b-10dd-4d8f-835a-0a88cd418266") }, $db: "test" } ninserted:1 keysInserted:1 numYields:0 reslen:29 locks:{ Global: { acquireCount: { r: 5, w: 3 } }, Database: { acquireCount: { r: 1, w: 2, W: 1 } }, Collection: { acquireCount: { r: 1, w: 2 } } } protocol:op_msg 49ms
      2018-03-02T14:28:36.408+1100 I COMMAND  [conn6] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0, $db: "test" } numYields:0 reslen:208 locks:{} protocol:op_msg 0ms
      2018-03-02T14:28:56.359+1100 I COMMAND  [conn6] command test.foo appName: "MongoDB Shell" command: find { find: "foo", filter: {}, lsid: { id: UUID("29f3064b-10dd-4d8f-835a-0a88cd418266") }, $db: "test" } planSummary: COLLSCAN keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:106 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_msg 1ms
      2018-03-02T14:28:56.360+1100 I COMMAND  [conn6] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0, $db: "test" } numYields:0 reslen:208 locks:{} protocol:op_msg 0ms
      2018-03-02T14:29:03.990+1100 I COMMAND  [conn6] command test.$cmd appName: "MongoDB Shell" command: startSession { startSession: 1.0, $db: "test" } numYields:0 reslen:76 locks:{} protocol:op_msg 0ms
      2018-03-02T14:29:03.991+1100 I COMMAND  [conn6] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0, $db: "test" } numYields:0 reslen:208 locks:{} protocol:op_msg 0ms
      2018-03-02T14:29:04.871+1100 I COMMAND  [conn6] command admin.$cmd appName: "MongoDB Shell" command: endSessions { endSessions: [ { id: UUID("29f3064b-10dd-4d8f-835a-0a88cd418266") } ], $db: "admin" } numYields:0 reslen:22 locks:{} protocol:op_msg 0ms
      2018-03-02T14:29:04.871+1100 I NETWORK  [conn6] end connection 127.0.0.1:52462 (0 connections now open)
      

      3.4.13 with verbose log:

      $ mongo --port 12345 --norc
      MongoDB shell version v3.6.3
      connecting to: mongodb://127.0.0.1:12345/
      MongoDB server version: 3.4.13
      WARNING: shell and server versions do not match
      > session = db.getMongo().startSession()
      session { "id" : UUID("513af8ae-f902-4c07-979a-a939812f368b") }
      > session.getDatabase("test").foo.insert({})
      WriteResult({ "nInserted" : 1 })
      > session.getDatabase("test").foo.find()
      { "_id" : ObjectId("5a98c64b3012b89e79da8491") }
      > db.runCommand({startSession:1})
      {
              "ok" : 0,
              "errmsg" : "no such command: 'startSession', bad cmd: '{ startSession: 1.0 }'",
              "code" : 59,
              "codeName" : "CommandNotFound"
      }
      >
      bye
      

      2018-03-02T14:34:28.206+1100 I NETWORK  [thread1] connection accepted from 127.0.0.1:52532 #8 (1 connection now open)
      2018-03-02T14:34:28.206+1100 I NETWORK  [conn8] received client metadata from 127.0.0.1:52532 conn8: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.6.3" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
      2018-03-02T14:34:28.206+1100 I COMMAND  [conn8] command admin.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1, client: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.6.3" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } } } numYields:0 reslen:189 locks:{} protocol:op_query 0ms
      2018-03-02T14:34:28.206+1100 I COMMAND  [conn8] command admin.$cmd appName: "MongoDB Shell" command: whatsmyuri { whatsmyuri: 1 } numYields:0 reslen:47 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:28.207+1100 I COMMAND  [conn8] command admin.$cmd appName: "MongoDB Shell" command: buildInfo { buildinfo: 1.0 } numYields:0 reslen:1250 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:28.207+1100 I COMMAND  [conn8] command admin.$cmd appName: "MongoDB Shell" command: getLog { getLog: "startupWarnings" } numYields:0 reslen:800 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:28.208+1100 I COMMAND  [conn8] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0 } numYields:0 reslen:174 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:28.208+1100 I COMMAND  [conn8] command test.$cmd appName: "MongoDB Shell" command: buildInfo { buildInfo: 1.0 } numYields:0 reslen:1250 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:28.208+1100 I COMMAND  [conn8] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0 } numYields:0 reslen:174 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:28.209+1100 I COMMAND  [conn8] command admin.$cmd appName: "MongoDB Shell" command: replSetGetStatus { replSetGetStatus: 1.0, forShell: 1.0 } numYields:0 reslen:106 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:32.308+1100 I COMMAND  [conn8] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0 } numYields:0 reslen:174 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:35.940+1100 D -        [conn8] reloading view catalog for database test
      2018-03-02T14:34:35.940+1100 D STORAGE  [conn8] create collection test.foo {}
      2018-03-02T14:34:35.940+1100 D STORAGE  [conn8] stored meta data for test.foo @ RecordId(4)
      2018-03-02T14:34:35.960+1100 D STORAGE  [conn8] test.foo: clearing plan cache - collection info cache reset
      2018-03-02T14:34:35.960+1100 D STORAGE  [conn8] create uri: table:index-6--2894484955783166514 config: type=file,internal_page_max=16k,leaf_page_max=16k,checksum=on,prefix_compression=true,block_compressor=,,,,key_format=u,value_format=u,app_metadata=(formatVersion=8,infoObj={ "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_", "ns" : "test.foo" }),
      2018-03-02T14:34:35.988+1100 D STORAGE  [conn8] test.foo: clearing plan cache - collection info cache reset
      2018-03-02T14:34:35.989+1100 I COMMAND  [conn8] command test.foo appName: "MongoDB Shell" command: insert { insert: "foo", ordered: true, documents: [ { _id: ObjectId('5a98c64b3012b89e79da8491') } ] } ninserted:1 keysInserted:1 numYields:0 reslen:29 locks:{ Global: { acquireCount: { r: 3, w: 3 } }, Database: { acquireCount: { w: 2, W: 1 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_command 49ms
      2018-03-02T14:34:35.990+1100 I COMMAND  [conn8] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0 } numYields:0 reslen:174 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:39.284+1100 I COMMAND  [conn8] command test.foo appName: "MongoDB Shell" command: find { find: "foo", filter: {} } planSummary: COLLSCAN keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:106 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms
      2018-03-02T14:34:39.285+1100 I COMMAND  [conn8] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0 } numYields:0 reslen:174 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:43.355+1100 D -        [conn8] User Assertion: 59:no such command: 'startSession', bad cmd: '{ startSession: 1.0 }' src/mongo/db/run_commands.cpp 59
      2018-03-02T14:34:43.355+1100 D COMMAND  [conn8] assertion while executing command 'startSession' on database 'test': 59 no such command: 'startSession', bad cmd: '{ startSession: 1.0 }'
      2018-03-02T14:34:43.355+1100 I COMMAND  [conn8] command test.$cmd appName: "MongoDB Shell" command: { startSession: 1.0 } exception: no such command: 'startSession', bad cmd: '{ startSession: 1.0 }' code:59 numYields:0 reslen:140 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:43.356+1100 I COMMAND  [conn8] command test.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0 } numYields:0 reslen:174 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:44.947+1100 D -        [conn8] User Assertion: 59:no such command: 'endSessions', bad cmd: '{ endSessions: [ { id: BinData(4, 513AF8AEF9024C07979AA939812F368B) } ] }' src/mongo/db/run_commands.cpp 59
      2018-03-02T14:34:44.947+1100 D COMMAND  [conn8] assertion while executing command 'endSessions' on database 'admin': 59 no such command: 'endSessions', bad cmd: '{ endSessions: [ { id: BinData(4, 513AF8AEF9024C07979AA939812F368B) } ] }'
      2018-03-02T14:34:44.947+1100 I COMMAND  [conn8] command admin.$cmd appName: "MongoDB Shell" command: { endSessions: [ { id: BinData(4, 513AF8AEF9024C07979AA939812F368B) } ] } exception: no such command: 'endSessions', bad cmd: '{ endSessions: [ { id: BinData(4, 513AF8AEF9024C07979AA939812F368B) } ] }' code:59 numYields:0 reslen:191 locks:{} protocol:op_command 0ms
      2018-03-02T14:34:44.948+1100 I -        [conn8] end connection 127.0.0.1:52532 (1 connection now open)
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              kevin.pulo Kevin Pulo
              Reporter:
              kevin.pulo Kevin Pulo
              Participants:
              Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: