Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
alitoufighi opened this issue Oct 7, 2020 · 9 comments
Milestone

Comments

@alitoufighi
Copy link

alitoufighi commented Oct 7, 2020

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 vkarpov15 added this to the 5.10.10 milestone Oct 10, 2020
@vkarpov15 vkarpov15 added the developer-experience This issue improves error messages, debugging, or reporting label Oct 10, 2020
@vkarpov15
Copy link
Collaborator

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':

return Array.from(topologyDescription.servers.keys()).
every(host => host.endsWith('.mongodb.net:27017'));

@vkarpov15 vkarpov15 removed this from the 5.10.10 milestone Oct 14, 2020
@vkarpov15 vkarpov15 added needs clarification This issue doesn't have enough information to be actionable. Close after 14 days of inactivity and removed developer-experience This issue improves error messages, debugging, or reporting labels Oct 14, 2020
@alitoufighi
Copy link
Author

alitoufighi commented Oct 14, 2020

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
Copy link
Author

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
Copy link
Author

alitoufighi commented Oct 14, 2020

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
Copy link
Author

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
Copy link

Hmm, I never actually thought this could be a issue from mongoose but I'm facing (maybe) similar issue. See docker-library/mongo#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
Copy link
Author

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

@bwgjoseph
Copy link

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 vkarpov15 added this to the 5.10.11 milestone Oct 24, 2020
@vkarpov15 vkarpov15 removed the needs clarification This issue doesn't have enough information to be actionable. Close after 14 days of inactivity label Oct 24, 2020
@vkarpov15
Copy link
Collaborator

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 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants