findById/findOne response after 10 seconds delay randomly

[newbaluku]

Node: 12.x (AWS Lambda)
mongodb: 3.5.9
mongoose: 5.9.20
Database: MongoDB v4.2.8 (MongoDB Atlas)

I have a warmer running to keep the Lambda warm and hence reusing the DB connection.

I have the following setup to connect DB once during Lambda cold start:

let isConnected;

const connectToDatabase = () => {
  if (isConnected) {
    console.log('connectToDatabase> using EXISTING database connection...');
    return Promise.resolve();
  }

  mongoose.set('useCreateIndex', true);
  mongoose.set('useFindAndModify', false);
  mongoose.set('useUnifiedTopology', true);

  const options = {
    useNewUrlParser: true,
    bufferCommands: false, // Disable mongoose buffering
    bufferMaxEntries: 0 // and MongoDB driver buffering
  };

  return mongoose.connect(DATABASEURL, options).then((db) => {
    isConnected = db.connections[0].readyState;
    console.log(`connectToDatabase> MongoDB - isConnected: ${isConnected}`);
  });
};

for some reason randomly, if the Lambda is not accessed by clients (and hence hitting the DB) after a period of time (say half an hour to few hours) but kept alive by the warmer. Calling findById/findOne on a Mongoose object will only response after a 10 seconds delay.

I've just started testing with additional options:
options.keepAlive = true;
options.keepAliveInitialDelay = 300000;

Any suggestions on what else to try/change if the keepAlive setting doesn't help?

[newbaluku]

tried turning on debug and got the following output from one of the query that took 10 seconds

2020-06-26T12:41:42.680Z 991a9c44-efa5-49c3-93b7-b3c6c5c8cdac INFO [0;36mMongoose: [0m users.findOne({ [32m'tokens.token' [39m: [32m'eyJhbGciOiJIUzI1NiI.....XXXXXXXXX......' [39m, [32m'tokens.access' [39m: [32m'auth' [39m, uid: ObjectId("5ee0826aaa95df000895fadc")}, { projection: { password: [33m0 [39m, [32m'headMaps.blob' [39m [33m0 [39m, tokens: [33m0 [39m, qrTokens: [33m0 [39m }})

and this is the debug log for a normal response time (typically around 10 ms):

2020-06-26T12:54:18.193Z 945ff20e-b389-4c09-96cc-49152f51c095 INFO [0;36mMongoose: [0m users.findOne({ [32m'tokens.token' [39m [32m'eyJhbGciOiJIUzI1NiI......XXXXXXXX......' [39m, [32m'tokens.access' [39m: [32m'auth' [39m, uid: ObjectId("5ee0826aaa95df000895fadc")}, { projection: { password: [33m0 [39m, [32m'headMaps.blob' [39m [33m0 [39m, tokens: [33m0 [39m, qrTokens: [33m0 [39m }})

are there any other ways to help with debugging?

[bhrigushr]

Experiencing a similar issue.

Node: 10.x (AWS Lambda)
mongoose: 5.9.19
Database: MongoDB v4.2.8 (MongoDB Atlas)

Unable to find the root cause of the issue

[vkarpov15]

Hard to say exactly without being able to repro this consistently on my end. But I have a few ideas:

1. There's a race condition in your code: if two Lambdas call connectToDatabase() at the same time then they'll both call mongoose.connect(). I'd recommend something like this instead:

let conn = null;

const connectToDatabase = () => {
  if (conn != null) {
    console.log('connectToDatabase> using EXISTING database connection...');
    return Promise.resolve();
  }

  mongoose.set('useCreateIndex', true);
  mongoose.set('useFindAndModify', false);
  mongoose.set('useUnifiedTopology', true);

  const options = {
    useNewUrlParser: true,
    bufferCommands: false, // Disable mongoose buffering
    bufferMaxEntries: 0 // and MongoDB driver buffering
  };

  conn = mongoose.connection;
  return mongoose.connect(DATABASEURL, options).then((db) => {
    console.log(`connectToDatabase> MongoDB - isConnected: ${isConnected}`);
  });
};

2. Try reducing heartbeatFrequencyMS to 2000 and see if that changes the behavior: mongoose.connect(uri, { heartbeatFrequencyMS: 2000 }). Off the top of my head, the only default timeout I can think of that's exactly 10 sec is heartbeatFrequencyMS.

3. How approximate is the 10 seconds? Is it always 10 seconds plus a little bit, or is it sometimes 8 seconds and sometimes 12?

[newbaluku]

Sure, I will amend my code to handle the race condition.

I will also try and monitor the response by adding the option of heartbeatFrequencyMS: 2000. Thanks.

The delay is always 10 secs plus a little bit, never fall below 10 secs. and not more then 11 secs from my testing so far.

[newbaluku]

after setting heartbeatFrequencyMS: 2000. Preliminary testing shows that occasional query lag still happened after idling for a while. Just that instead of delay of 10 secs plus a bit, it now delay for 2 secs plus a bit. Sometimes, a bit less than 2 secs.

I wonder what is the implication of setting this.

[vkarpov15]

heartbeatFrequencyMS controls how often the MongoDB driver sends a heartbeat to the server to check its status. Thanks for testing this, your feedback is very helpful, I can now look into the MongoDB driver and see why this might be happening.

[newbaluku]

not sure if you still need sample codes to repro this on your side. Let me know, if there is a need I will try to do up a sample project based on serverless.

[vkarpov15]

@newbaluku a sample project that can consistently repro this issue would be extremely helpful. Otherwise we're just digging in the source code :)

[vkarpov15]

@newbaluku my best guess as to the cause of this issue is that, when you define a model using mongoose.model(), Mongoose takes bufferCommands as it was at the time you called mongoose.model(). So in Mongoose v5.9.24, the below code wouldn't disable buffering on Model because bufferCommands isn't set when mongoose.model() is called.

const Model = mongoose.model('Test', Schema({ name: String }));

mongoose.connect(uri, { bufferCommands: false });

We'll add a fix for this to 5.9.25 👍

[newbaluku]

Is this fixed in 5.9.25?

because I just tried this version and I can still repro the 10 secs delay. I didn't specify heartbeatFrequencyMS in options.

[vkarpov15]

@newbaluku we haven't been able to repro this on our side, the bufferCommands fix was our best guess.

In order to help us debug this, we added a 'buffer' event to Mongoose connections that gets emitted when a connection buffers a command. Can you please listen to that event using the below code:

mongoose.connection.on('buffer', data => {
  console.log('Buffered', mongoose.connection.readyState, data);
});

And let us know if that event is being fired when you get a 10 second delay? That would help us confirm that this is an issue with Mongoose buffering.

[mbroadst]

Hi @newbaluku , thank you very much for your patience and thorough bug report. I believe this issue will be solved in mongodb/node-mongodb-native#2551. If you want to test the fix in your code you can copy the changes in the wake method in the mongodb folder within the node_modules uploaded to your lambda function.

[timeswind]

This this issue solved? I am currently using mongoose@5.10.8 with AWS Lambda and still experiencing the the 10 seconds query issue.

[vkarpov15]

@timeswind not yet, it should be fixed with the next mongodb driver release. We've been running @newbaluku 's repro for weeks and haven't seen the issue with a patched version, so we're fairly certain that once this patch is released this issue will be fixed. Sorry for the delay!

[vkarpov15]

This issue should be fixed by #9521

[ErnestBrandi]

@vkarpov15
Hi, I am using Mongoose latest version (5.12.3) and it still occurs.
Take a look at this thread for how to experience it.
EDIT : I think I found the issue. I was using an outdated version of connect-mongo which used an outdated version of mongodb itself as a peer dependency...