When querying the "system.profile" collection with a user containing only the clusterMonitor role, closing the cursor appears to fail and "leak" the cursor until the 10 minute timeout. However querying with a user with higher privileges closes the cursor successfully.
Repro steps are above. I tried with both mgo and Java drivers just to double check.
Log level 2 output from a reproducer:
2015-09-10T18:31:50.300-0400 I NETWORK [initandlisten] connection accepted from 127.0.0.1:64007 #2199 (4 connections now open) 2015-09-10T18:31:50.307-0400 D COMMAND [conn2199] run command admin.$cmd { buildinfo: 1 } 2015-09-10T18:31:50.308-0400 I COMMAND [conn2199] command admin.$cmd command: buildInfo { buildinfo: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:977 locks:{} 0ms 2015-09-10T18:31:50.316-0400 D COMMAND [conn2199] run command admin.$cmd { ismaster: 1 } 2015-09-10T18:31:50.316-0400 I COMMAND [conn2199] command admin.$cmd command: isMaster { ismaster: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:465 locks:{} 0ms 2015-09-10T18:31:50.344-0400 I NETWORK [initandlisten] connection accepted from 127.0.0.1:64009 #2200 (5 connections now open) 2015-09-10T18:31:50.344-0400 D COMMAND [conn2200] run command admin.$cmd { buildinfo: 1 } 2015-09-10T18:31:50.344-0400 I COMMAND [conn2200] command admin.$cmd command: buildInfo { buildinfo: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:977 locks:{} 0ms 2015-09-10T18:31:50.357-0400 D COMMAND [conn2200] run command admin.$cmd { saslStart: 1, mechanism: "SCRAM-SHA-1", payload: BinData(0, 6E2C2C6E3D636C75737465726D6F6E69746F722C723D585E292A4C7B2164637D744B4C2965796D556548265C4677) } 2015-09-10T18:31:50.358-0400 D QUERY [conn2200] Relevant index 0 is kp: { user: 1, db: 1 } io: { v: 1, unique: true, key: { user: 1, db: 1 }, name: "user_1_db_1", ns: "admin.system.users" } 2015-09-10T18:31:50.358-0400 D QUERY [conn2200] Only one plan is available; it will be run but will not be cached. query: { user: "clustermonitor", db: "admin" } sort: {} projection: {} skip: 0 limit: 0, planSummary: IXSCAN { user: 1, db: 1 } 2015-09-10T18:31:50.358-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.358-0400 D STORAGE [conn2200] WT rollback_transaction 2015-09-10T18:31:50.362-0400 I COMMAND [conn2200] command admin.$cmd command: saslStart { saslStart: 1, mechanism: "SCRAM-SHA-1", payload: BinData(0, 6E2C2C6E3D636C75737465726D6F6E69746F722C723D585E292A4C7B2164637D744B4C2965796D556548265C4677) } keyUpdates:0 writeConflicts:0 numYields:0 reslen:171 locks:{ G lobal: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 4ms 2015-09-10T18:31:50.362-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.363-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::beingReleased 2015-09-10T18:31:50.363-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::broughtBack 2015-09-10T18:31:50.363-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.363-0400 D STORAGE [conn2200] WT commit_transaction 2015-09-10T18:31:50.363-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::beingReleased 2015-09-10T18:31:50.363-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::broughtBack 2015-09-10T18:31:50.363-0400 D STORAGE [conn2200] WT commit_transaction 2015-09-10T18:31:50.582-0400 D COMMAND [conn2200] run command admin.$cmd { saslContinue: 1, conversationId: 1, payload: BinData(0, 633D626977732C723D585E292A4C7B2164637D744B4C2965796D556548265C46772B5264594D65677343656D6871664D6841425237646A2F46556573484735505A2C703D576B...) } 2015-09-10T18:31:50.582-0400 I COMMAND [conn2200] command admin.$cmd command: saslContinue { saslContinue: 1, conversationId: 1, payload: BinData(0, 633D626977732C723D585E292A4C7B2164637D744B4C2965796D556548265C46772B5264594D65677343656D6871664D6841425237646A2F46556573484735505A2C703D576B...) } keyUpdates:0 writeConflicts:0 numYields:0 reslen:108 locks:{} 0ms 2015-09-10T18:31:50.583-0400 D COMMAND [conn2200] run command admin.$cmd { saslContinue: 1, conversationId: 1, payload: BinData(0, 763D4E373437683752596F3274504D4C49333047325862626D4E6D4D673D) } 2015-09-10T18:31:50.583-0400 D QUERY [conn2200] Relevant index 0 is kp: { user: 1, db: 1 } io: { v: 1, unique: true, key: { user: 1, db: 1 }, name: "user_1_db_1", ns: "admin.system.users" } 2015-09-10T18:31:50.583-0400 D QUERY [conn2200] Only one plan is available; it will be run but will not be cached. query: { user: "clustermonitor", db: "admin" } sort: {} projection: {} skip: 0 limit: 0, planSummary: IXSCAN { user: 1, db: 1 } 2015-09-10T18:31:50.583-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.583-0400 D STORAGE [conn2200] WT rollback_transaction 2015-09-10T18:31:50.583-0400 I ACCESS [conn2200] Successfully authenticated as principal clustermonitor on admin 2015-09-10T18:31:50.584-0400 I COMMAND [conn2200] command admin.$cmd command: saslContinue { saslContinue: 1, conversationId: 1, payload: BinData(0, 763D4E373437683752596F3274504D4C49333047325862626D4E6D4D673D) } keyUpdates:0 writeConflicts:0 numYields:0 reslen:78 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::beingReleased 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::broughtBack 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WT commit_transaction 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::beingReleased 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::broughtBack 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WT commit_transaction 2015-09-10T18:31:50.584-0400 D QUERY [conn2200] Running query: query: {} sort: { $natural: -1 } projection: {} skip: 0 limit: 20 2015-09-10T18:31:50.584-0400 D QUERY [conn2200] Only one plan is available; it will be run but will not be cached. query: {} sort: { $natural: -1 } projection: {} skip: 0 limit: 20, planSummary: COLLSCAN 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WT rollback_transaction 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::beingReleased 2015-09-10T18:31:50.584-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::broughtBack 2015-09-10T18:31:50.584-0400 I QUERY [conn2200] query admin.system.profile query: { $query: {}, $orderby: { $natural: -1 } } planSummary: COLLSCAN cursorid:39651685655 ntoreturn:20 ntoskip:0 nscanned:0 nscannedObjects:20 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:20 reslen:11243 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms 2015-09-10T18:31:50.585-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.585-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::beingReleased 2015-09-10T18:31:50.585-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::broughtBack 2015-09-10T18:31:50.585-0400 D STORAGE [conn2200] WT begin_transaction 2015-09-10T18:31:50.585-0400 D STORAGE [conn2200] WT commit_transaction 2015-09-10T18:31:50.585-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::beingReleased 2015-09-10T18:31:50.585-0400 D STORAGE [conn2200] WiredTigerRecoveryUnit::broughtBack 2015-09-10T18:31:50.585-0400 D STORAGE [conn2200] WT commit_transaction 2015-09-10T18:31:50.597-0400 I COMMAND [conn2200] killcursors: found 0 of 1 2015-09-10T18:31:50.598-0400 I QUERY [conn2200] killcursors keyUpdates:0 writeConflicts:0 numYields:0 locks:{} 0ms 2015-09-10T18:31:50.600-0400 D NETWORK [conn2199] SocketException: remote: 127.0.0.1:64007 error: 9001 socket exception [CLOSED] server [127.0.0.1:64007] 2015-09-10T18:31:50.600-0400 D NETWORK [conn2200] SocketException: remote: 127.0.0.1:64009 error: 9001 socket exception [CLOSED] server [127.0.0.1:64009] 2015-09-10T18:31:50.600-0400 I NETWORK [conn2199] end connection 127.0.0.1:64007 (4 connections now open) 2015-09-10T18:31:50.601-0400 I NETWORK [conn2200] end connection 127.0.0.1:64009 (4 connections now open)
Environment
OS X 10.8.4
MongoDB 3.0.4, WT
Replica Set with auth, authSchemaVersion 5
- is related to
-
SERVER-9609 Ensure users can only call getMore on cursors they created
- Closed