Loading...

Type: Bug
Resolution: Fixed
Priority: Major - P3
Fix Version/s: 3.6.9, 4.0.3, 4.1.3
Affects Version/s: 3.6.3
Component/s: Shell
Labels:
- ShardingTechDebt

Backwards Compatibility:
Minor Change
Backport Requested:

v4.0, v3.6
Sprint:
Sharding 2018-08-13, Sharding 2018-08-27, Sharding 2018-09-10
Confidence Status:
None
Work Order:
3

Aha! Reference:
None
Tracking Level:
None
Risk Status:
None
Exec Notes:
None
Goal Name:
None
Goal Link:
None

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)

related to

SERVER-32064 A logical session id should be included in all command requests from the mongo shell

Closed

Details

Description

Attachments

Issue Links

Activity

People

Dates