Cursor session id (none) is not the same as the operation context's - release 5.0.15 broken

[simllll]

bug with the latest mongoose (guess the underyling problem lies in mongodb-core though).

What is the current behavior?
After upgrading to 5.0.15 no queries are running anymore:

Unhandled rejection MongoError: Cursor session id (none) is not the same as the operation context's session id (f6a28f6f-7dfa-424d-8691-fd40b12733ee - 0rbp3hXFaGQzW/eEz2QZrZ7et36CzL3bnxgnuRX9rEo=)
    at /home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/pool.js:598:61
    at authenticateStragglers (/home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/pool.js:516:16)
    at Connection.messageHandler (/home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/pool.js:552:5)
    at emitMessageHandler (/home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/connection.js:309:10)
    at Socket.<anonymous> (/home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/connection.js:452:17)
    at Socket.emit (events.js:159:13)
    at addChunk (_stream_readable.js:265:12)
    at readableAddChunk (_stream_readable.js:252:11)
    at Socket.Readable.push (_stream_readable.js:209:10)

If the current behavior is a bug, please provide the steps to reproduce.
Just upgrade it, didn't change anything else.

What is the expected behavior?
Work the same way like it does with 5.0.14. Downgrading to .14 solves all problems instantely.

Please mention your node.js, mongoose and MongoDB version.
node v9.3.0
mongoose 5.0.15
mongodb 3.6.4

[lineus]

@simllll I'd like to dig into this, can you provide an example script that works for you on 5.0.14 but not on 5.0.15?

[simllll]

@lineus any idea how I get a backtrace to track this a bit more down?

I tried several approaches to extract the issue, but can't find it. But if I start my application the error appears, unfortuantely I cannot see what triggered it.

[lineus]

@simllll I would start the node process with # node --inspect-brk myapp.js and then attach a debugger ( ie. chrome dev tools or vscode ). You can then use the debugger to step through the app until it breaks. It can be tedious, but that's the only way I know of to really dig in to it.

[simllll]

I kind of narrowed it down already, and unlikely my first guess is that this is also related with the connection issue I experienced awhile ago (https://jira.mongodb.org/plugins/servlet/mobile#issue/NODE-1340).

I enabled debug log for mongodb-native and that's the output when I do 7 very simple queries in parallel (get entries from a table limited by one key .. something like translate.find({'lang': 'de'})).

debug_all.log
debug_tofirsterror.log

But I just managed to track it down even further.
1.) Only one collection and especially one query is failing (guess it has either todo with the content or with the length of the result?)
2.) it is only happening if I set readPreference expicity to "primaryPreferred".
3.) It is a mongo core issue, not directly related to mongoose. I opened a seperate issue here: https://jira.mongodb.org/projects/NODE/issues/NODE-1420

Final test script which fails:
Import the attached file "buggycollection1.json" like this into a mongo db shard cluster / connect to a mongos:
mongoimport -h localhost -d mongo-bug-sessions -c buggycollection1 buggycollection1.json

buggycollection1.zip

const mongodb = require('mongodb');

const conf = {
    opts: {
        readPreference: 'primaryPreferred'
    },
    url: 'mongodb://mongos-instance/mongo-bug-sessions'
};

mongodb.MongoClient.connect(
    conf.url,
    conf.opts
)
    .then((client) => {
        console.log(new Date(), 'connected');
        client.on('close', () => console.log('closed'));
        client.on('reconnect', () => console.log('reconnect'));
        client.on('disconnect', () => console.log('disconnect'));

        const db = client.db('mongo-bug-sessions');

        db.collection('buggycollection1').find({lang: 'de'}).toArray()
            .then((translations) => {
                console.log('A', !!translations);
            });
    });

Output:

/usr/local/bin/node /home/simon/Dev/Web/hokify-server/helpers/mongodbtest2.js
2018-04-19T08:45:25.804Z 'connected'
(node:9721) UnhandledPromiseRejectionWarning: MongoError: Cursor session id (none) is not the same as the operation context's session id (c9b18612-f8b1-4efb-a2a8-b2319b5d78f2 - 0rbp3hXFaGQzW/eEz2QZrZ7et36CzL3bnxgnuRX9rEo=)
    at /home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/pool.js:599:61
    at authenticateStragglers (/home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/pool.js:516:16)
    at Connection.messageHandler (/home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/pool.js:552:5)
    at emitMessageHandler (/home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/connection.js:309:10)
    at Socket.<anonymous> (/home/simon/Dev/Web/hokify-server/node_modules/mongodb-core/lib/connection/connection.js:452:17)
    at Socket.emit (events.js:159:13)
    at addChunk (_stream_readable.js:265:12)
    at readableAddChunk (_stream_readable.js:252:11)
    at Socket.Readable.push (_stream_readable.js:209:10)
    at TCP.onread (net.js:608:20)
(node:9721) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:9721) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Can you read something from the attached logs? Does the script also fail in your setup?

Thanks
Simon

[vkarpov15]

As a workaround, try passing the skipSessions option to the failing query.

MyModel.find({}, null, { skipSessions: true });

The MongoDB driver implicitly creates sessions if you're connected to MongoDB 3.6 running WT, that option will turn off that behavior. Should help with this issue.

[simllll]

They fixed the issue already upstream. Unfortunately no new release of mongodb-core yet... So far I go with older mongoose ;)

Thanks for the workaround.

Simon

[vkarpov15]

I'll keep this open to track, glad they fixed the issue 👍 I got bit today by implicit sessions as well, got some good feedback for the MongoDB driver team to improve them

[simllll]

New mongodb-core got released today, as soon as mongoose upgrades to 5.0.18 tthe issues should be done/gone!

Thanks