Atlas MongoDb+Lambda connection count spiking after update 5.7.1->5.12.10

[scottweinert]

bug

What is the current behavior?

I'm experiencing an odd behavior after upgrading our mongoose package from 5.7.1 to 5.12.10 that I cannot explain. We're using AWS Lambda and we are reusing the connections with the script below, and setting context.callbackWaitsForEmptyEventLoop = false; in our Lambda handler. We've been running it for months, and after releasing the package update on production, our connections quickly went through the roof.

We had to quickly revert as to not bring our system down. Reading through the release notes, I cannot find anything that would explain this behavior, but I am able to consistently reproduce it by releasing and putting load on our dev environment in AWS Lambda.

If the current behavior is a bug, please provide the steps to reproduce.

Here is our code for connecting to the DB:

const mongoose = require('mongoose')
const { createLogger } = require('@atomicfi/logger')
const logger = createLogger({ package: 'database' })

let connection = null

exports.init = async (mongoDbUri) => {
  if (connection !== null || mongoose.connection.readyState === 1) {
    return
  }

  mongoose.set('debug', false)
  mongoose.connection.on('connected', () => {
    logger.info('Mongoose default connection open')
  })
  mongoose.connection.on('error', (err) => {
    logger.error('Mongoose default connection error: ' + err)
  })
  mongoose.connection.on('disconnected', () => {
    logger.info('Mongoose default connection disconnected')
  })

  connection = await mongoose.connect(mongoDbUri, {
    useNewUrlParser: true,
    useUnifiedTopology: true,
    useCreateIndex: true,
    bufferMaxEntries: 0,
    useFindAndModify: false, 
    bufferCommands: false // Disable mongoose buffering
  })
}

What is the expected behavior?

For the connections not to spike after updating mongoose.

What are the versions of Node.js, Mongoose and MongoDB you are using? Note that "latest" is not a version.

Node 14.x runtime in AWS Lambda, MongoDB 4.4, Mongoose 5.12.10

[scottweinert]

Update:

Using this connection code seems to have resolved the issue:

const mongoose = require('mongoose')

let cached = global.mongoose

if (!cached) {
  cached = global.mongoose = { conn: null, promise: null }
}

exports.init = async (mongoDbUri) => {
  if (cached.conn) {
    return cached.conn
  }

  if (!cached.promise) {
    const opts = {
      useNewUrlParser: true,
      useUnifiedTopology: true,
      bufferCommands: false,
      bufferMaxEntries: 0,
      useFindAndModify: false,
      useCreateIndex: true
    }

    cached.promise = mongoose.connect(mongoDbUri, opts).then((mongoose) => {
      return mongoose
    })
    cached.conn = await cached.promise
    return cached.conn
  }
}

I found this code inside of this PR: https://github.com/vercel/next.js/pull/23321/files

I'd be curious why this approach works better than the former 🤔

[guillaumekh]

I can confirm the report.

We didn't notice it straight away but it seems that our poolSize:1 option is ignored and our mongoose client uses the default setting (up to 5 connections).

I've tried several previous releases and it seems 5.9.29 was the last version to respect the setting.

Thanks @scottweinert for sharing your fix.

[vkarpov15]

@guillaumekh poolSize option works fine as far as I can tell, below script prints out "Done 10075" on my machine, which means the two queries are getting queued up because of poolSize: 1. Can you modify the below script to demonstrate your issue?

'use strict';
  
const mongoose = require('mongoose');

mongoose.set('useFindAndModify', false);

const { Schema } = mongoose;

run().catch(err => console.log(err));

async function run() {
  await mongoose.connect('mongodb://localhost:27017/test', {
    useNewUrlParser: true,
    useUnifiedTopology: true,
    poolSize: 2
  });

  await mongoose.connection.dropDatabase();

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

  const start = Date.now();
  await Promise.all([
    Model.find({ $where: 'sleep(5000) || true' }),
    Model.find({ $where: 'sleep(5000) || true' })
  ]);
  console.log('Done', Date.now() - start);
}

@scottweinert it's hard to tell without taking a closer look at your code. My best guess is because your original code has a race condition: connection = await mongoose.connect(mongoDbUri, ...) is async, so you may end up having multiple mongoose.connect() calls running in parallel. We believe we fixed the race condition in v5.10.0 with #9203, but there may be other issues with your code that are contributing to this.

It looks like your new code also has a similar race condition, it's possible for cached.promise to be set but not cached.conn. Try this:

const mongoose = require('mongoose')

let cached = global.mongoose

if (!cached) {
  cached = global.mongoose = { conn: null, promise: null }
}

exports.init = async (mongoDbUri) => {
  if (cached.conn) {
    return cached.conn
  }

  if (!cached.promise) {
    const opts = {
      useNewUrlParser: true,
      useUnifiedTopology: true,
      bufferCommands: false,
      bufferMaxEntries: 0,
      useFindAndModify: false,
      useCreateIndex: true
    }

    cached.promise = mongoose.connect(mongoDbUri, opts).then((mongoose) => {
      return mongoose
    })
    cached.conn = await cached.promise
    return cached.conn
  }

  return cached.promise // <-- add this case
}

[guillaumekh]

@vkarpov15 OK i've done some digging around.

Like @scottweinert we had a conditional check on connection.readyState and i have a hunch that readystate might not be 100% reliable in the context of AWS Lambda.

With that said, I have managed to narrow down our poolSize misbehaviour in an easily reproductible manner.

With Node 16.4, Mongoose 5.12.14, and a 3-node MongoDB 4.4.6 replica set running on Atlas:

mongoose = require('mongoose')
mongoose.connect('mongodb+srv://myreplicaset-vtcmd.mongodb.net/mydb', {
  user: 'mysuser',
  pass:'mypass',
  useNewUrlParser: true,
  useUnifiedTopology: true,
  useFindAndModify: false,
  autoIndex: false,
  poolSize: 1,
  serverSelectionTimeoutMS: 5000,
  bufferCommands: false
})

$ lsof -i tcp:27017
node    6408 user   27u  IPv4 0xe04adf287240058d      0t0  TCP 192.168.1.115:52120->ec2-52-47-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    6408 user   28u  IPv4 0xe04adf2877cb19dd      0t0  TCP 192.168.1.115:52121->ec2-52-47-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    6408 user   29u  IPv4 0xe04adf288ea68e2d      0t0  TCP 192.168.1.115:52118->ec2-15-188-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    6408 user   30u  IPv4 0xe04adf28724019dd      0t0  TCP 192.168.1.115:52119->ec2-15-236-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    6408 user   31u  IPv4 0xe04adf2892f3c9dd      0t0  TCP 192.168.1.115:52124->ec2-15-188-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    6408 user   32u  IPv4 0xe04adf289334c6cd      0t0  TCP 192.168.1.115:52125->ec2-15-236-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    6408 user   33u  IPv4 0xe04adf2892fda27d      0t0  TCP 192.168.1.115:52126->ec2-52-47-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)

Upstream (mongodb@3.6.8) shows similar behaviour so this might not be a mongoose thing.

mongodb = require('mongodb')
let MC = new mongodb.MongoClient('mongodb+srv://myreplicaset-vtcmd.mongodb.net/mydb', {
  tls: true,
  auth: {user: 'myuser', password:'mypassword'},
  useNewUrlParser: true,
  useUnifiedTopology: true,
  poolSize: 1,
  maxPoolSize: 1,
  serverSelectionTimeoutMS: 5000,
  bufferCommands: false
})

$ lsof -i tcp:27017
node    8250 user   27u  IPv4 0xe04adf2892fda27d      0t0  TCP 192.168.1.115:52663->ec2-52-47-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    8250 user   28u  IPv4 0xe04adf2877cb427d      0t0  TCP 192.168.1.115:52668->ec2-15-236-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    8250 user   29u  IPv4 0xe04adf289301f9dd      0t0  TCP 192.168.1.115:52662->ec2-15-188-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    8250 user   30u  IPv4 0xe04adf287abf7b1d      0t0  TCP 192.168.1.115:52661->ec2-15-236-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    8250 user   31u  IPv4 0xe04adf28933e627d      0t0  TCP 192.168.1.115:52669->ec2-15-188-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)
node    8250 user   32u  IPv4 0xe04adf287240058d      0t0  TCP 192.168.1.115:52670->ec2-52-47-xx-xx.eu-west-3.compute.amazonaws.com:27017 (ESTABLISHED)

Shouldn't there be a single TCP connection here, or am I misunderstanding how poolSize applies to Unified Topology replica sets ?

[guillaumekh]

Submitted to upstream : https://developer.mongodb.com/community/forums/t/poolsize-connection-count/113029

I think this issue can be closed.

[guillaumekh]

For reference, and in case anyone else stumbles here wondering just how many TCP connections a single Connection (Mongoose) or MongoClient (native Mongo driver) will actually consume when using useUnifiedTopology: true:

The connection pool is on a per-mongod/mongos basis, so when connecting to a 3-member replica there will be three connection pools (one per mongod), each with a maxPoolSize of 1. Additionally, there is a required monitoring connection for each node as well, so you end up with (maxPoolSize+1)*number_of_nodes TCP connections, or (1+1)*3=6 total TCP connections in the case of a 3-member replica set.

Source: MongoDB @emadum @ https://developer.mongodb.com/community/forums/t/poolsize-connection-count/113029/2