Timeout when debuggin Node.js application locally or remotely

sw360cab commented 3 years ago

When debugging a Node.js application both locally or remotely there is an annoying connection timeout that does not occur at all when the application is running without debug mode (not meaning strictly Mongoose debug) or stopping ar breakpoints.

The application is connecting to MongoDB via Mongoose with the following configuration:

  const connectionUri = `mongodb://${dbHost}/${dbName}`;
  mongoose.connect(connectionUri, {
    useNewUrlParser: true,
    useFindAndModify: false,
    useCreateIndex: true,
    /*
    * current Server Discovery and Monitoring engine is deprecated, 
    * and will be removed in a future version. 
    * To use the new Server Discover and Monitoring engine, 
    * pass option { useUnifiedTopology: true } to the MongoClient constructor.
    * Set to true to opt in to using the MongoDB driver's new connection management engine.
    * You should set this option to true, except for the unlikely case 
    * that it prevents you from maintaining a stable connection.
    */
    useUnifiedTopology: true,
    // cfr. https://mongoosejs.com/docs/connections.html#error-handling
    serverSelectionTimeoutMS: 5000
  });

Depending on the environment the connection to MongoDB can be toward:

localhost
remote host
via Docker network
MongoDB is usually running in a container exposing port 27017 (whether not in the same network stack with application)
At the moment nor replica set or other particular topolgies are in charge in this environment configuration

Lib versions

NodeJS: 14.3
Mongoose: 5.10.11
Mongo: 4.4

Apparently this did not happen with previous versions of Mongoose. Haven't tried yet, but the configuration above remained the same.

Step to reproduce

Run a Node.js app connecting to MongoDB via Mongoose in debug, stop at a breakpoint. Waiting few seconds and the following error message should show up:

app          | 2020-12-10T10:19:27.053Z | ERROR |  MongooseServerSelectionError: connection <monitor> to 172.19.0.2:27017 timed out
app          |     at Function.Model.$wrapCallback (/usr/src/app/node_modules/mongoose/lib/model.js:4856:32)
app          |     at /usr/src/app/node_modules/mongoose/lib/query.js:4393:21
app          |     at promiseOrCallback (/usr/src/app/node_modules/mongoose/lib/helpers/promiseOrCallback.js:9:12)
app          |     at model.Query.exec (/usr/src/app/node_modules/mongoose/lib/query.js:4392:10)
app          |     at _execPopulateQuery (/usr/src/app/node_modules/mongoose/lib/model.js:4502:9)
app          |     at populate (/usr/src/app/node_modules/mongoose/lib/model.js:4423:24)
app          |     at _populate (/usr/src/app/node_modules/mongoose/lib/model.js:4291:5)
app          |     at /usr/src/app/node_modules/mongoose/lib/model.js:4267:5
app          |     at promiseOrCallback (/usr/src/app/node_modules/mongoose/lib/helpers/promiseOrCallback.js:9:12)
app          |     at Function.Model.populate (/usr/src/app/node_modules/mongoose/lib/model.js:4265:10)
app          |     at model.populate (/usr/src/app/node_modules/mongoose/lib/document.js:3805:19)
app          |     at /usr/src/app/node_modules/mongoose/lib/document.js:3856:10
app          |     at /usr/src/app/node_modules/mongoose/lib/helpers/promiseOrCallback.js:31:5
app          |     at new Promise (<anonymous>)
app          |     at promiseOrCallback (/usr/src/app/node_modules/mongoose/lib/helpers/promiseOrCallback.js:30:10)
app          |     at model.Document.execPopulate (/usr/src/app/node_modules/mongoose/lib/document.js:3855:10)
app          |     at /usr/src/app/models/Event.js:198:8
app          |     at new Promise (<anonymous>)
app          |     at model.EventSchema.methods.decorate (/usr/src/app/models/Event.js:196:10)
app          |     at /usr/src/app/routes/api/eventApi.js:773:46
app          |     at Array.map (<anonymous>)
app          |     at /usr/src/app/routes/api/eventApi.js:773:33
app          |     at processTicksAndRejections (internal/process/task_queues.js:93:5) {
app          |   reason: **TopologyDescription** {
app          |     type: 'Single',
app          |     setName: null,
app          |     maxSetVersion: null,
app          |     maxElectionId: null,
app          |     servers: Map(1) { 'mongo_klosed:27017' => [ServerDescription] },
app          |     stale: false,
app          |     compatible: true,
app          |     compatibilityError: null,
app          |     logicalSessionTimeoutMinutes: null,
app          |     heartbeatFrequencyMS: 10000,
app          |     localThresholdMS: 15,
app          |     commonWireVersion: 9
app          |   },
app          |   methodName: 'geoQuery',
app          |   httpStatusCode: undefined
app          | }

Step to resolve

Apparently forcing

useUnifiedTopology: false

make the issue disappear. But as the comment left above says:

You should set this option to true, except for the unlikely case that it prevents you from maintaining a stable connection.

On the other side, it is now quite impossible to debug the application remotely when in Staging environment (or even worse production).

vkarpov15 commented 3 years ago

What debugger are you using?

sw360cab commented 3 years ago

v8-inspector vithin VS Code.

@vkarpov15 does this answer your question?

jaffarc commented 3 years ago

I same problem: node:12.20.0 ubuntu:20.04 mongo:4.2.1 mongoose:5.11.7

if add useUnifiedTopology: true

let options = {
  keepAlive: true,
  connectTimeoutMS: 300000,
  socketTimeoutMS: 300000,
  useFindAndModify: false,
  bufferMaxEntries: 0,
  poolSize: 5,
  useUnifiedTopology: true,
  useNewUrlParser: true
};
const db = mongoose.createConnection(mongoUrl, options);

Error in mongodb connection: MongooseServerSelectionError: getaddrinfo EAI_AGAIN undefined
unhandledRejection Err:: MongooseServerSelectionError: getaddrinfo EAI_AGAIN undefined
    at NativeConnection.Connection.openUri (/var/www/api_ES6/node_modules/mongoose/lib/connection.js:832:32)
    at Mongoose.createConnection (/var/www/api_ES6/node_modules/mongoose/lib/index.js:285:17)
    at file:///var/www/api_ES6/src/conn/conection.js:16:21
    at ModuleJob.run (internal/modules/esm/module_job.js:145:37)
    at async Loader.import (internal/modules/esm/loader.js:182:24)
    at async Object.loadESM (internal/process/esm_loader.js:68:5) {
  reason: TopologyDescription {
    type: 'Unknown',
    setName: null,
    maxSetVersion: null,
    maxElectionId: null,
    servers: Map { 'undefined:27017' => [ServerDescription] },
    stale: false,
    compatible: true,
    compatibilityError: null,
    logicalSessionTimeoutMinutes: null,
    heartbeatFrequencyMS: 10000,
    localThresholdMS: 15,
    commonWireVersion: null
  }
}
unhandledRejection Stack:: "MongooseServerSelectionError: getaddrinfo EAI_AGAIN undefined\n    at NativeConnection.Connection.openUri (/var/www/api_ES6/node_modules/mongoose/lib/connection.js:832:32)\n    at Mongoose.createConnection (/var/www/api_ES6/node_modules/mongoose/lib/index.js:285:17)\n    at file:///var/www/api_ES6/src/conn/conection.js:16:21\n    at ModuleJob.run (internal/modules/esm/module_job.js:145:37)\n    at async Loader.import (internal/modules/esm/loader.js:182:24)\n    at async Object.loadESM (internal/process/esm_loader.js:68:5)"

sw360cab commented 3 years ago

@jaffarc it looks more that you have EAI_AGAIN variable undefined rather than the timeout I am exposing

jaffarc commented 3 years ago

@sw360cab If I leave it as true a few seconds pass it will pop the error: my string:
mongodb://userV2:1234@10.23.150.145:27017/v2_api?replicaSet=v2&authSource=v2_api&authMechanism=SCRAM-SHA-1&w=majority

If I let useNewUrlParser: false ,I stay connected normally. only with the alert message.

I forced the env into the conn file. and solved it ... Strange because when I put false he did not give the error. I was connected and only with warn msg

vkarpov15 commented 3 years ago

I haven't used node-inspector for debugging before, but I set it up and tried running the below script with a breakpoint on the first findOne():

'use strict';

const mongoose = require('mongoose');

mongoose.set('debug', true);

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

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

  await mongoose.connection.dropDatabase();

  const SchemaPerson = new mongoose.Schema({
    _id: String,
    name: String
  });

  const Person = mongoose.model('Person', SchemaPerson);

  const doc = await Person.create({ _id: 'foo', name: 'CPU' });

  await Person.findOne();

  await Person.findOne();

  console.log(doc._id);
}

Left the script hanging at the breakpoint for 30 seconds and resumed, no error.

Can you please come up with a script that repros this issue? It doesn't look like it happens with just any breakpoint in a Mongoose script.

sw360cab commented 3 years ago

Apparently with newest versions of mongoose lib this rarely happens and it is very hard to reproduce. I will update the issue if encounter it again.

Automattic / mongoose