Parse server is sometimes unable to handle voting in mongo replicaset

nerakhon commented 8 years ago

Issue Description

Describe your issue in as much detail as possible.

I have a parse server running dockerized on ubuntu 14.04 on digital ocean, connected to MongoDB 3.0 replicaset with rocksdb engine. When a network issue happens at digital ocean and cluster undergoes voting parse server ends up in unrecoverable state complaining about closed sockets on original primary of the replicaset.

Steps to reproduce

Please include a detailed list of steps that reproduce the issue. Include curl commands when applicable.

have active parse requests on parse server
initiate voting on mongodb replicaset
Expected Results

Parse to fail over to new primary

Actual Outcome

Parse server hanging

Environment Setup

Server
- parse-server version (Be specific! Don't say 'latest'.) : 2.2.16
- Operating System: Ubuntu 14.04 (Dockerized)
- Hardware: Digital ocean small droplet
- Localhost or remote server? (AWS, Heroku, Azure, Digital Ocean, etc): Digital ocean
Database
- MongoDB version: 3.0
- Storage engine: Rocks
- Hardware: same as above for parse
- Localhost or remote server? (AWS, mLab, ObjectRocket, Digital Ocean, etc): digital ocean
  Logs/Trace

You can turn on additional logging by configuring VERBOSE=1 in your environment.

Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : Aug 17 22:06:10 : message: 'server db-1.######.com:27017 sockets closed' } MongoError: server db-1.######.com:27017 sockets closed at Server.destroy (/parse/node_modules/mongodb-core/lib/topologies/server.js:1075:47) at /parse/node_modules/mongodb-core/lib/topologies/replset.js:1267:20 at commandCallback (/parse/node_modules/mongodb-core/lib/topologies/server.js:1194:9) at Callbacks.emit (/parse/node_modules/mongodb-core/lib/topologies/server.js:119:3) at .messageHandler (/parse/node_modules/mongodb-core/lib/topologies/server.js:358:23) at TLSSocket. (/parse/node_modules/mongodb-core/lib/connection/connection.js:292:22) at emitOne (events.js:96:13) at TLSSocket.emit (events.js:188:7) at readableAddChunk (_stream_readable.js:172:18) at TLSSocket.Readable.push (_stream_readable.js:130:10) : #033[31merror#033[39m: error getting auth for sessionToken MongoError: server db-1.####.com:27017 sockets closed at Server.destroy (/parse/node_modules/mongodb-core/lib/topologies/server.js:1075:47) at /parse/node_modules/mongodb-core/lib/topologies/replset.js:1267:20 at commandCallback (/parse/node_modules/mongodb-core/lib/topologies/server.js:1194:9) at Callbacks.emit (/parse/node_modules/mongodb-core/lib/topologies/server.js:119:3) at .messageHandler (/parse/node_modules/mongodb-core/lib/topologies/server.js:358:23) at TLSSocket. (/parse/node_modules/mongodb-core/lib/connection/connection.js:292:22) at emitOne (events.js:96:13) at TLSSocket.emit (events.js:188:7) at readableAddChunk (_stream_readable.js:172:18) at TLSSocket.Readable.push (_stream_readable.js:130:10)

Aug 20 05:16:33 : Uncaught internal server error. { MongoError: no valid seed servers in list Aug 20 05:16:33 : at . (/parse/node_modules/mongodb-core/lib/topologies/replset.js:1415:39) Aug 20 05:16:33 : at g (events.js:286:16) Aug 20 05:16:33 : at emitTwo (events.js:106:13) Aug 20 05:16:33 : at emit (events.js:191:7) Aug 20 05:16:33 : at . (/parse/node_modules/mongodb-core/lib/topologies/server.js:177:12) Aug 20 05:16:33 : at g (events.js:286:16) Aug 20 05:16:33 : at emitTwo (events.js:106:13) Aug 20 05:16:33 : at emit (events.js:191:7) Aug 20 05:16:33 : at . (/parse/node_modules/mongodb-core/lib/connection/pool.js:119:12) Aug 20 05:16:33 : at g (events.js:286:16) name: 'MongoError', message: 'no valid seed servers in list' } MongoError: no valid seed servers in list Aug 20 05:16:33 : at . (/parse/node_modules/mongodb-core/lib/topologies/replset.js:1415:39) Aug 20 05:16:33 : at g (events.js:286:16) Aug 20 05:16:33 : at emitTwo (events.js:106:13) Aug 20 05:16:33 : at emit (events.js:191:7) Aug 20 05:16:33 : at . (/parse/node_modules/mongodb-core/lib/topologies/server.js:177:12) Aug 20 05:16:33 : at g (events.js:286:16) Aug 20 05:16:33 : at emitTwo (events.js:106:13) Aug 20 05:16:33 : at emit (events.js:191:7) Aug 20 05:16:33 : at . (/parse/node_modules/mongodb-core/lib/connection/pool.js:119:12) Aug 20 05:16:33 : at g (events.js:286:16)

the exception repeatedly thrown by parse even when mongo replicaset is back online and finished voting

similar issue is referenced in issue: #2446 by @jeacott1

benishak commented 8 years ago

I also have similar issue but with mongos! althought I have 3 Mongos but when one of them is not available or a member of one of the replicaSet of one of the mongos goes down or one of the 3 replicaset enter an election stat, Parse stop working and throw error

flovilmart commented 8 years ago

@benishak what is the error that is thrown?

jeacott1 commented 8 years ago

I can confirm that there is an issue, but for us we get a "not master, slaveOk=false;." exception. to be clear we intend slave to be set false. for me its bizarre behaviour when the slave=true/false setting is clientside, so why it would ever send a request to a mongo slave knowing that it will reject the response is just odd. There is no problem if parse/mongo are idle. when a mongo election occurs and parse is idle, parse recovers to the new master properly. When parse is actively serving load and an election occurs, we see this exception, and parse is dead until its restarted.

flovilmart commented 8 years ago

@jeacott1 what version are you running? We added in 2.2.17 a recovery for exceptions in the mongo driver. If that's not effective for your use case, we shall invesitgate what error is triggered and clean up the pending connections while the election is occurring.

benishak commented 8 years ago

As far as I remember, something like this MongoError .... Primary shard shard_1 not available, election stat

nerakhon commented 8 years ago

Just a brief update, we've seen the same issue even with versions > 2.2.20

mrmarcsmith commented 7 years ago

The same happens for us. "not master and slaveOk=false" is the error and our server is completely unavailable until I restart it. we are running version 2.3.1

error: Error generating response. { MongoError: not master and slaveOk=false
    at Function.MongoError.create (/parse-server/node_modules/mongodb-core/lib/error.js:31:11)
    at queryCallback (/parse-server/node_modules/mongodb-core/lib/cursor.js:198:34)
    at /parse-server/node_modules/mongodb-core/lib/connection/pool.js:436:18
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickDomainCallback (internal/process/next_tick.js:122:9)
  name: 'MongoError',
  message: 'not master and slaveOk=false',
  '$err': 'not master and slaveOk=false',
  code: 13435 } name=MongoError, message=not master and slaveOk=false, $err=not master and slaveOk=false, code=13435

mman commented 7 years ago

Just hit that again today, the moment mongo replica set changes PRIMARY the parse-server looses mongo connection and is not able to get it back until restarted.

This is on parse 2.3.2.

Parse Server `backend-2-nyc3`

The Mongo URL string contains db-1, db-2, and db-3. Parse Server was connected to db-3 that was the primary.

The moment primary changes parse server starts emitting these exceptions until the point when it's restarted automatically by monit for not serving HTTP requests. After the restart everything runs fine until next PRIMARY change.

Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]: #033[31merror#033[39m: error getting auth for sessionToken MongoError: connection 1165 to db-3:27017 closed
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at Function.MongoError.create (/parse/node_modules/mongodb-core/lib/error.js:29:11)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at TLSSocket.<anonymous> (/parse/node_modules/mongodb-core/lib/connection/connection.js:187:22)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at TLSSocket.g (events.js:286:16)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at emitOne (events.js:101:20)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at TLSSocket.emit (events.js:188:7)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at Socket._handle.close (net.js:492:12)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at Socket.g (events.js:286:16)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at emitOne (events.js:96:13)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at Socket.emit (events.js:188:7)
Feb  2 07:29:38 backend-2-nyc3 ea73b33bcbfb[1179]:     at TCP._handle.close [as _onclose] (net.js:492:12)

Mongo DB `db-3:27017`

Feb  2 07:29:38 db-3 ee4276c1a636[873]: 2017-02-02T06:29:38.329+0000 I REPL     [ReplicationExecutor] Member db-1:27017 is now in state PRIMARY
Feb  2 07:29:38 db-3 ee4276c1a636[873]: 2017-02-02T06:29:38.332+0000 I REPL     [ReplicationExecutor] replset: another primary seen with election time 5892d1d1:3 my election time is 588c2da7:1
Feb  2 07:29:38 db-3 ee4276c1a636[873]: 2017-02-02T06:29:38.333+0000 I REPL     [ReplicationExecutor] stepping down; another primary was elected more recently
Feb  2 07:29:38 db-3 ee4276c1a636[873]: 2017-02-02T06:29:38.333+0000 I REPL     [ReplicationExecutor] Stepping down from primary in response to heartbeat
Feb  2 07:29:38 db-3 ee4276c1a636[873]: 2017-02-02T06:29:38.334+0000 I REPL     [replCallbackWithGlobalLock-0] transition to SECONDARY

flovilmart commented 7 years ago

Closing as the mongodb driver was updated many times in between.

On a side note, we pass the DB URL provided right into the nodejs mongodb client. I believe the server that very little to do with those issues.

I've experienced a few failover over the past 6 months on our setup and parse-server seems to have responded very well to all of those.

parse-community / parse-server