search

Automattic / mongoose

MongoDB object modeling designed to work in an asynchronous environment.
https://mongoosejs.com
MIT License
26.96k stars 3.84k forks source link

Connecting to mongos while providing replicaSet parameter raises wrong exception about Atlas cluster #9470

Closed alitoufighi closed 4 years ago

alitoufighi commented 4 years ago

What is the current behavior? By providing following connection string, the client remains in connecting (2) status for a while, then throws an exception about Atlas clusters, while I'm using my self-hosted MongoDB servers. mongodb://user:pass@mongos/db?replicaSet=rs0

The complain is:

MongooseServerSelectionError: Could not connect to any servers in your MongoDB Atlas cluster. One common reason is that you're trying to access the database from an IP that isn't whitelisted. Make sure your current IP address is on your Atlas cluster's IP whitelist: https://docs.atlas.mongodb.com/security-whitelist/
    at NativeConnection.Connection.openUri (/root/backend/services/ride/node_modules/mongoose/lib/connection.js:800:32)
    at Mongoose.connect (/root/backend/services/ride/node_modules/mongoose/lib/index.js:339:15)
    at repl:1:10
    at Script.runInThisContext (vm.js:122:20)
    at REPLServer.defaultEval (repl.js:332:29)
    at bound (domain.js:402:14)
    at REPLServer.runBound [as eval] (domain.js:415:12)
    at REPLServer.onLine (repl.js:642:10)
    at REPLServer.emit (events.js:203:15)
    at REPLServer.EventEmitter.emit (domain.js:448:20)
    at REPLServer.Interface._onLine (readline.js:308:10)
    at REPLServer.Interface._line (readline.js:656:8)
    at REPLServer.Interface._ttyWrite (readline.js:937:14)
    at REPLServer.self._ttyWrite (repl.js:715:7)
    at ReadStream.onkeypress (readline.js:184:10)
    at ReadStream.emit (events.js:198:13)
    at ReadStream.EventEmitter.emit (domain.js:448:20)
    at emitKeys (internal/readline.js:424:14)
    at emitKeys.next (<anonymous>)
    at ReadStream.onData (readline.js:1073:36)
    at ReadStream.emit (events.js:198:13)
    at ReadStream.EventEmitter.emit (domain.js:448:20)

If the current behavior is a bug, please provide the steps to reproduce. The following would produce the same result:

const mongoose = require('mongoose');
const url = "mongodb://user:pass@mongos/db?replicaSet=rs0"
mongoose.connect(url, {useNewUrlParser: true, useUnifiedTopology: true});

What is the expected behavior? The exception is very deceptive. Providing replicaSet option for mongos was just a misconfiguration but the exception made me think of Mongoose considering some specific IP ranges as Atlas ranges. Since I was running my deployment on Kubernetes and the IP is address of the Service, this was nearly a heart attack to me.

What are the versions of Node.js, Mongoose and MongoDB you are using? Note that "latest" is not a version. I'm using Mongoose 5.10.0 in Node.js v10.22.1 and MongoDB server 4.4

vkarpov15 commented 4 years ago

Hmm can you please print the err.reason property?

mongoose.connect(url, {useNewUrlParser: true, useUnifiedTopology: true}).catch(err => console.log(err.reason));

Also, is the hostname that you're connecting to just 'mongos' or something different? This error only happens when every hostname ends with '.mongodb.net': https://github.com/Automattic/mongoose/blob/d41bce48b52363df93dbc6d39b126bed87969ac5/lib/helpers/topology/isAtlas.js#L9-L10

alitoufighi commented 4 years ago

Yeah, mongos is the service name in my Kubernetes cluster. This also happens when I'm connecting to a standalone instance.

Here's the output of err.reason:

TopologyDescription {
  type: 'ReplicaSetNoPrimary',
  setName: null,
  maxSetVersion: null,
  maxElectionId: null,
  servers: Map {},
  stale: false,
  compatible: true,
  compatibilityError: null,
  logicalSessionTimeoutMinutes: null,
  heartbeatFrequencyMS: 10000,
  localThresholdMS: 15,
  commonWireVersion: 9 }

image

alitoufighi commented 4 years ago

It seems that since somehow the servers is an empty Map, isAtlas will return true:

> Array.from(new Map()).every(host => host.endsWith('.mongodb.net:27017'));
true
alitoufighi commented 4 years ago

This happens with any name or explicit IPs. The problem is the existence of replicaSet parameter when connecting to a non-replicaset instance. Modifying isAtlas() to return false will change the exception message to this:

MongooseServerSelectionError: Server selection timed out after 30000 ms
at MessageStream.messageHandler (/node_modules/mongoose/node_modules/mongodb/lib/cmap/connection.js:266:20)

which is still ambiguous.

alitoufighi commented 4 years ago

I have another update.

I used this:

const mongoose = require('mongoose');
const url = "mongodb://user:pass@mongos/db?replicaSet=rs0"
mongoose.connect(url, { useNewUrlParser: true, useUnifiedTopology: true }).catch(err => console.log(mongoose.connection.client.topology.s.servers));
console.log(mongoose.connection.client.topology.s.servers)

and it first printed this (which is line 4):

Map {
  'mongos:27017' => Server {
    _events:
      ....

Then (in catch) printed:

Map {}

What happened here?

bwgjoseph commented 4 years ago

Hmm, I never actually thought this could be a issue from mongoose but I'm facing (maybe) similar issue. See https://github.com/docker-library/mongo/issues/418

I'm also running local mongo replica set, but unable to connect via replica uri like mongodb://localhost:30000,localhost:30001,localhost:30002/ttt?replicaSet=rs0

alitoufighi commented 4 years ago

@bwgjoseph Do you have this issue of servers Map being empty?

bwgjoseph commented 4 years ago

I think mine is the same as yours.

This is what it complains about, something about no PRIMARY

MongooseServerSelectionError: Could not connect to any servers in your MongoDB Atlas cluster. One common reason is that you're trying to access the database from an IP that isn't whitelisted. Make sure your current IP address is on your Atlas cluster's IP whitelist: https://docs.atlas.mongodb.com/security-whitelist/
    at NativeConnection.Connection.openUri (Z:\Development\workspace\node_modules\mongoose\lib\connection.js:828:32)
    at Mongoose.connect (Z:\Development\workspace\node_modules\mongoose\lib\index.js:335:15)
    at Function.mongooseClient (Z:\Development\workspace\src\mongoose.ts:14:6)
    at Function.configure (Z:\Development\workspace\node_modules\@feathersjs\feathers\lib\application.js:59:8)
    at Object.<anonymous> (Z:\Development\workspace\src\app.ts:44:5)
    at Module._compile (internal/modules/cjs/loader.js:1133:30)
    at Module._compile (Z:\Development\workspace\node_modules\source-map-support\source-map-support.js:547:25)
    at Module.m._compile (C:\Users\Joseph\AppData\Local\Temp\ts-node-dev-hook-8594340632681687.js:60:25)
    at Module._extensions..js (internal/modules/cjs/loader.js:1153:10)
    at require.extensions.<computed> (C:\Users\Joseph\AppData\Local\Temp\ts-node-dev-hook-8594340632681687.js:62:14)
    at Object.nodeDevHook [as .ts] (Z:\Development\workspace\node_modules\ts-node-dev\lib\hook.js:61:7)
    at Module.load (internal/modules/cjs/loader.js:977:32)
    at Function.Module._load (internal/modules/cjs/loader.js:877:14)
    at Module.require (internal/modules/cjs/loader.js:1019:19)
    at require (internal/modules/cjs/helpers.js:77:18)
    at Object.<anonymous> (Z:\Development\workspace\src\index.ts:2:1) {
  reason: TopologyDescription {
    type: 'ReplicaSetNoPrimary',
    setName: 'rs0',
    maxSetVersion: 1,
    maxElectionId: 7fffffff0000000000000004,
    servers: Map {},
    stale: false,
    compatible: true,
    compatibilityError: null,
    logicalSessionTimeoutMinutes: null,
    heartbeatFrequencyMS: 10000,
    localThresholdMS: 15,
    commonWireVersion: 9
  }
}

But when I do a check using rs.status(), this is the info and it does seem like I have a PRIMARY

rs0:PRIMARY> rs.status()
{
        "set" : "rs0",
        "date" : ISODate("2020-10-21T16:10:17.629Z"),
        "myState" : 1,
        "term" : NumberLong(4),
        "syncSourceHost" : "",
        "syncSourceId" : -1,
        "heartbeatIntervalMillis" : NumberLong(2000),
        "majorityVoteCount" : 2,
        "writeMajorityCount" : 2,
        "votingMembersCount" : 3,
        "writableVotingMembersCount" : 2,
        "optimes" : {
                "lastCommittedOpTime" : {
                        "ts" : Timestamp(1603296615, 1),
                        "t" : NumberLong(4)
                },
                "lastCommittedWallTime" : ISODate("2020-10-21T16:10:15.787Z"),
                "readConcernMajorityOpTime" : {
                        "ts" : Timestamp(1603296615, 1),
                        "t" : NumberLong(4)
                },
                "readConcernMajorityWallTime" : ISODate("2020-10-21T16:10:15.787Z"),
                "appliedOpTime" : {
                        "ts" : Timestamp(1603296615, 1),
                        "t" : NumberLong(4)
                },
                "durableOpTime" : {
                        "ts" : Timestamp(1603296615, 1),
                        "t" : NumberLong(4)
                },
                "lastAppliedWallTime" : ISODate("2020-10-21T16:10:15.787Z"),
                "lastDurableWallTime" : ISODate("2020-10-21T16:10:15.787Z")
        },
        "lastStableRecoveryTimestamp" : Timestamp(1603296605, 1),
        "electionCandidateMetrics" : {
                "lastElectionReason" : "priorityTakeover",
                "lastElectionDate" : ISODate("2020-10-21T15:59:25.697Z"),
                "electionTerm" : NumberLong(4),
                "lastCommittedOpTimeAtElection" : {
                        "ts" : Timestamp(1603295955, 2),
                        "t" : NumberLong(3)
                },
                "lastSeenOpTimeAtElection" : {
                        "ts" : Timestamp(1603295965, 1),
                        "t" : NumberLong(3)
                },
                "numVotesNeeded" : 2,
                "priorityAtElection" : 2,
                "electionTimeoutMillis" : NumberLong(10000),
                "priorPrimaryMemberId" : 1,
                "numCatchUpOps" : NumberLong(0),
                "newTermStartDate" : ISODate("2020-10-21T15:59:25.759Z"),
                "wMajorityWriteAvailabilityDate" : ISODate("2020-10-21T15:59:26.726Z")
        },
        "electionParticipantMetrics" : {
                "votedForCandidate" : true,
                "electionTerm" : NumberLong(3),
                "lastVoteDate" : ISODate("2020-10-21T15:59:15.265Z"),
                "electionCandidateMemberId" : 1,
                "voteReason" : "",
                "lastAppliedOpTimeAtElection" : {
                        "ts" : Timestamp(1602173625, 1),
                        "t" : NumberLong(1)
                },
                "maxAppliedOpTimeInSet" : {
                        "ts" : Timestamp(1602173625, 1),
                        "t" : NumberLong(1)
                },
                "priorityAtElection" : 2
        },
        "members" : [
                {
                        "_id" : 0,
                        "name" : "mongo-primary:27017",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 674,
                        "optime" : {
                                "ts" : Timestamp(1603296615, 1),
                                "t" : NumberLong(4)
                        },
                        "optimeDate" : ISODate("2020-10-21T16:10:15Z"),
                        "syncSourceHost" : "",
                        "syncSourceId" : -1,
                        "infoMessage" : "",
                        "electionTime" : Timestamp(1603295965, 2),
                        "electionDate" : ISODate("2020-10-21T15:59:25Z"),
                        "configVersion" : 1,
                        "configTerm" : 4,
                        "self" : true,
                        "lastHeartbeatMessage" : ""
                },
                {
                        "_id" : 1,
                        "name" : "mongo-secondary:27017",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 672,
                        "optime" : {
                                "ts" : Timestamp(1603296615, 1),
                                "t" : NumberLong(4)
                        },
                        "optimeDurable" : {
                                "ts" : Timestamp(1603296615, 1),
                                "t" : NumberLong(4)
                        },
                        "optimeDate" : ISODate("2020-10-21T16:10:15Z"),
                        "optimeDurableDate" : ISODate("2020-10-21T16:10:15Z"),
                        "lastHeartbeat" : ISODate("2020-10-21T16:10:15.892Z"),
                        "lastHeartbeatRecv" : ISODate("2020-10-21T16:10:16.940Z"),
                        "pingMs" : NumberLong(0),
                        "lastHeartbeatMessage" : "",
                        "syncSourceHost" : "mongo-primary:27017",
                        "syncSourceId" : 0,
                        "infoMessage" : "",
                        "configVersion" : 1,
                        "configTerm" : 4
                },
                {
                        "_id" : 2,
                        "name" : "mongo-arbiter:27017",
                        "health" : 1,
                        "state" : 7,
                        "stateStr" : "ARBITER",
                        "uptime" : 672,
                        "lastHeartbeat" : ISODate("2020-10-21T16:10:15.889Z"),
                        "lastHeartbeatRecv" : ISODate("2020-10-21T16:10:15.893Z"),
                        "pingMs" : NumberLong(0),
                        "lastHeartbeatMessage" : "",
                        "syncSourceHost" : "",
                        "syncSourceId" : -1,
                        "infoMessage" : "",
                        "configVersion" : 1,
                        "configTerm" : 4
                }
        ],
        "ok" : 1,
        "$clusterTime" : {
                "clusterTime" : Timestamp(1603296615, 1),
                "signature" : {
                        "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
                        "keyId" : NumberLong(0)
                }
        },
        "operationTime" : Timestamp(1603296615, 1)
}
rs0:PRIMARY>

Not exactly sure what is causing it

vkarpov15 commented 4 years ago

Found the issue, it's subtle and hard to notice but it turns out that, given that you're connecting to a mongos with the replicaSet parameter, the MongoDB driver couldn't connect to any servers. And Mongoose uses Array#every() to check if you're connected to Atlas, so if there are no servers Mongoose always thinks it is connected to Atlas.

Fix will be in 5.10.11 :+1: