Model init can hang

[neil-hardlight]

Prerequisites

• I have written a descriptive issue title
• I have searched existing issues to ensure the bug has not already been reported

Mongoose version

8.9.5

Node.js version

20.14.0

MongoDB server version

8.0.1

Typescript version (if applicable)

No response

Description

It is possible for model.init to fail to complete. This happens if the heartbeat expires when making the call; the code hangs inside "Connection.prototype.createCollection" - internally this function never returns from the call to "_waitForConnect".

Steps to Reproduce

Run this self contained script - breakpoint the "init" line for long enough to expire the heartbeat.

const mongoose = require('mongoose');

async function testMongoose() {
    const db = await mongoose.connect('mongodb://127.0.0.1/testMongoose', {heartbeatFrequencyMS: 2500});
    let firstTime = true;

    // Wait for valid heartbeat to be registered.
    db.connection.db.client.on('serverHeartbeatSucceeded', () => {
        console.log(`heartbeat - readyState ${db.connection.readyState}`);

        if (firstTime) {
            firstTime = false;
            const Schema = mongoose.Schema;
            const ObjectId = Schema.ObjectId;

            const blogSchema = new Schema({author: ObjectId, title: String, body: String, date: Date});
            const blogModel = mongoose.model('blog', blogSchema);
            // Breakpoint here for long enough for the heartbeat to expire (2.5s in this case).
            blogModel.init().then(() => {
                console.log('initialised');
            }).catch((err) => {
                console.error(err);
            });
        }
    });
}

testMongoose().then(() => {});

I found it useful to update this mongoose function to show that the readyState becomes 0 and that causes the "end _waitForConnect" to never happen.

Connection.prototype.createCollection = async function createCollection(collection, options) {
  if (typeof options === 'function' || (arguments.length >= 3 && typeof arguments[2] === 'function')) {
    throw new MongooseError('Connection.prototype.createCollection() no longer accepts a callback');
  }

  console.log(`_waitForConnect ${this.readyState}`);
  await this._waitForConnect();
  console.log(`end _waitForConnect ${this.readyState}`);

  return this.db.createCollection(collection, options);
};

Expected Behavior

model.init should never hang. From the test code above you can see that the heartbeat signal correctly continues to be emitted, and even the connection readyState gets updated, but _waitForConnect never returns.

console output when fails:

heartbeat - readyState 1
_waitForConnect 0
heartbeat - readyState 1
heartbeat - readyState 1
heartbeat - readyState 1
heartbeat - readyState 1

console output when succeeds:

heartbeat - readyState 1
_waitForConnect 1
end _waitForConnect 1
initialised
heartbeat - readyState 1

[neil-hardlight]

Worth noting that this problem exists in mongoose 8.8.4 as well as 8.9.5 - however, it appears to have got more prevelant in 8.9.x. I think this is because the heartbeat emit happens later in 8.9.x after calling "openUri" (or any similar connection API). I am finding that with a heartbeat of 2.5s, it is not uncommon for there to be no heartbeat for over 5s...which exaserbates the issue here:

Object.defineProperty(Connection.prototype, 'readyState', {

which only considers there to be a disconnection when 2x the heartbeat frequency has elapsed:

this.client.topology.s.description.heartbeatFrequencyMS * 2

[neil-hardlight]

Another thing worth trying that shows the issue without needing to breakpoint the code.

1. Open a connection
2. Wait for a heartbeat (this sets _lastHeartbeatAt to a non-null value).
3. Close the connection and wait for >2x the heartbeat frequency
4. Reopen the connection
5. "readyState" is likely to report 0 (disconnected) because _lastHeartbeatAt is from the previous open connection, which is too long ago. Model initialisation and index creation likely to hang/fail due to _waitForConnect never returning.

Things that may help?:

• Set _lastHeartbeatAt to null when closing a connection
• Set _lastHeartbeatAt to Date.now() when opening a connection, so it's fresh and likely not to report an incorrect "readyState" when models are created/initialised.

These ideas do not fix the underlying issue, i.e. _waitForConnect hangs. But I think the out of date _lastHeartbeatAt has certainly exasperated the issue and made it much more likely that our unit tests hang.

[vkarpov15]

I was able to repro using the following script

const mongoose = require('mongoose');

async function testMongoose() {
    const db = await mongoose.connect('mongodb://127.0.0.1/testMongoose', {heartbeatFrequencyMS: 2500, bufferTimeoutMS: 1000});
    let firstTime = true;

    // Wait for valid heartbeat to be registered.
    db.connection.db.client.on('serverHeartbeatSucceeded', async () => {
        console.log(`heartbeat - readyState ${db.connection.readyState}`);

        await db.connection.close();
        console.log('Wait');
        await new Promise(resolve => setTimeout(resolve, 5100));
        const blogSchema = new mongoose.Schema({author: 'ObjectId', title: String, body: String, date: Date}, { });
        const blogModel = mongoose.model('blog', blogSchema);

        const promise = blogModel.init();
        await db.connection.openUri('mongodb://127.0.0.1/testMongoose', {heartbeatFrequencyMS: 2500});
        console.log('Wait for init');
        await promise;
        console.log('Done');
        
    });
}

testMongoose().then(() => {});

You're correct that a stale _lastHeartbeatAt from connecting/disconnecting is the cause. It seems like, as suggested, setting _lastHeartbeatAt to null when closing the connection is the correct approach here. We used to set _lastHeartbeatAt on initial connection, but removed that in 8.9. We have a fix for that issue, but there's another issue: _waitForConnect() isn't subject to bufferTimeoutMS, which is inconsistent. We are working on a fix for that.

[neil-hardlight]

Hi - unfortunately this has not fixed the issue. I copied your script above and had two different issues:

1. "bufferTimeoutMS: 1000" causes the following error:
   MongoParseError: option buffertimeoutms is not supported

2. If I remove "bufferTimeoutMS" the code hangs here:
   console.log('Wait for init');

I verified that I had correctly installed 8.9.7 by checking the "mongoose" version at runtime (just in case my script was somehow grabbing a different version). I'm running Node 20.14.0.

I feel like maybe I'm doing something wrong??? But can't think what. Having said this, I have also tested 8.9.7 in our full unit test suite and it's still hanging in the same place as before.

[neil-hardlight]

Sorry - I think I've misread the notes - I thought the fix had been merged into both 8.9.7 (released) and 8.10.x (pending release).

[vkarpov15]

We merged the PR and fix into 8.10, and we just shipped 8.10.0. We did not put this change into 8.9.7.

[neil-hardlight]

I can confirm that 8.10.0 has fixed the issue. Thank you for the quick turnaround on this issue - much appreciated.