possible EventEmitter memory leak

[mddvul22]

Rocket.Chat Version: 0.54.2
Running Instances: 2
DB Replicaset OpLog: Enabled
Node Version: v4.7.3

This morning, we started having intermittent issues with our various Rocket Chat clients losing their connection to our Rocket Chat server. A restart of our mongo instances and our Rocket Chat services did not solve our problem. During this time, the load on the server was very high and, according to Top, Mongo was using all of the resources. We would stop mongo, and the system load would drop back down. As soon as we restarted, it would immediately spike again. Finally, we resorted to a reboot of the server and everything normalized.

(I have "xxxxxx" out server names below.)

Mar 31 09:49:24 chat rocketchat1: Exception in setInterval callback: MongoError: connection 39674 to xxxx.xxxxx.com:27017 timed out
Mar 31 09:49:24 chat rocketchat1: at Object.Future.wait (/root/Rocket.Chat/programs/server/node_modules/fibers/future.js:449:15)
Mar 31 09:49:24 chat rocketchat1: at [object Object]. (packages/meteor.js:213:24)
Mar 31 09:49:24 chat rocketchat1: at [object Object].MongoConnection.(anonymous function) [as update] (/root/Rocket.Chat/programs/server/packages/mongo.js:831:49)
Mar 31 09:49:24 chat rocketchat1: at Object. (packages/matb33_collection-hooks.js:504:27)
Mar 31 09:49:24 chat rocketchat1: at Object.collection.(anonymous function) [as update] (packages/matb33_collection-hooks.js:146:21)
Mar 31 09:49:24 chat rocketchat1: at [object Object].update (/root/Rocket.Chat/programs/server/packages/mongo.js:3882:31)
Mar 31 09:49:24 chat rocketchat1: at [object Object].Mongo.Collection.(anonymous function) [as update] (packages/dispatch_run-as-user.js:325:19)
Mar 31 09:49:24 chat rocketchat1: at Object.InstanceStatus.ping (packages/konecty_multiple-instances-status.js:110:24)
Mar 31 09:49:24 chat rocketchat1: at packages/konecty_multiple-instances-status.js:98:19
Mar 31 09:49:24 chat rocketchat1: at [object Object]._.extend.withValue (packages/meteor.js:1122:17)
Mar 31 09:49:24 chat rocketchat1: at packages/meteor.js:445:45
Mar 31 09:49:24 chat rocketchat1: at runWithEnvironment (packages/meteor.js:1176:24)
Mar 31 09:49:24 chat rocketchat1: - - - - -
Mar 31 09:49:24 chat rocketchat1: at Function.MongoError.create (/root/Rocket.Chat/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/error.js:29:11)
Mar 31 09:49:24 chat rocketchat1: at Socket. (/root/Rocket.Chat/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/connection/connection.js:184:20)
Mar 31 09:49:24 chat rocketchat1: at Socket.g (events.js:260:16)
Mar 31 09:49:24 chat rocketchat1: at emitNone (events.js:67:13)
Mar 31 09:49:24 chat rocketchat1: at Socket.emit (events.js:166:7)
Mar 31 09:49:24 chat rocketchat1: at Socket._onTimeout (net.js:332:8)
Mar 31 09:49:24 chat rocketchat1: at _runOnTimeout (timers.js:524:11)
Mar 31 09:49:24 chat rocketchat1: at makeTimerTimeout (timers.js:515:3)
Mar 31 09:49:24 chat rocketchat1: at Timer.unrefTimeout (timers.js:584:5)
Mar 31 09:49:24 chat rocketchat1: Exception in setInterval callback: MongoError: connection 39674 to xxxx.xxxxx.com:27017 timed out
Mar 31 09:49:24 chat rocketchat1: at Object.Future.wait (/root/Rocket.Chat/programs/server/node_modules/fibers/future.js:449:15)
Mar 31 09:49:24 chat rocketchat1: at [object Object]. (packages/meteor.js:213:24)
Mar 31 09:49:24 chat rocketchat1: at [object Object].MongoConnection.(anonymous function) [as update] (/root/Rocket.Chat/programs/server/packages/mongo.js:831:49)
Mar 31 09:49:24 chat rocketchat1: at Object. (packages/matb33_collection-hooks.js:504:27)
Mar 31 09:49:24 chat rocketchat1: at Object.collection.(anonymous function) [as update] (packages/matb33_collection-hooks.js:146:21)
Mar 31 09:49:24 chat rocketchat1: at [object Object].update (/root/Rocket.Chat/programs/server/packages/mongo.js:3882:31)
Mar 31 09:49:24 chat rocketchat1: at [object Object].Mongo.Collection.(anonymous function) [as update] (packages/dispatch_run-as-user.js:325:19)
Mar 31 09:49:24 chat rocketchat1: at Object.InstanceStatus.ping (packages/konecty_multiple-instances-status.js:110:24)
Mar 31 09:49:24 chat rocketchat1: at packages/konecty_multiple-instances-status.js:98:19
Mar 31 09:49:24 chat rocketchat1: at [object Object]..extend.withValue (packages/meteor.js:1122:17)
Mar 31 09:49:24 chat rocketchat1: at packages/meteor.js:445:45
Mar 31 09:49:24 chat rocketchat1: at runWithEnvironment (packages/meteor.js:1176:24)
Mar 31 09:49:24 chat rocketchat1: - - - - -
Mar 31 09:49:24 chat rocketchat1: at Function.MongoError.create (/root/Rocket.Chat/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/error.js:29:11)
Mar 31 09:49:24 chat rocketchat1: at Socket. (/root/Rocket.Chat/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/connection/connection.js:184:20)
Mar 31 09:49:24 chat rocketchat1: at Socket.g (events.js:260:16)
Mar 31 09:49:24 chat rocketchat1: at emitNone (events.js:67:13)
Mar 31 09:49:24 chat rocketchat1: at Socket.emit (events.js:166:7)
Mar 31 09:49:24 chat rocketchat1: at Socket._onTimeout (net.js:332:8)
Mar 31 09:49:24 chat rocketchat1: at _runOnTimeout (timers.js:524:11)
Mar 31 09:49:24 chat rocketchat1: at makeTimerTimeout (timers.js:515:3)
Mar 31 09:49:24 chat rocketchat1: at Timer.unrefTimeout (timers.js:584:5)
Mar 31 09:49:50 chat rocketchat2: app.js:9037 #33[34mStreamBroadcast ➔ Auth.info#033[39m prevent self connect localhost:3001
Mar 31 09:49:51 chat rocketchat1: (node) warning: possible EventEmitter memory leak detected. 11 exit listeners added. Use emitter.setMaxListeners() to increase limit.
Mar 31 09:49:51 chat rocketchat1: Trace
Mar 31 09:49:51 chat rocketchat1: at process.addListener (events.js:239:17)
Mar 31 09:49:51 chat rocketchat1: at Object.InstanceStatus.registerInstance (packages/konecty_multiple-instances-status.js:69:12)
Mar 31 09:49:51 chat rocketchat1: at Object.InstanceStatus.ping (packages/konecty_multiple-instances-status.js:121:19)
Mar 31 09:49:51 chat rocketchat1: at packages/konecty_multiple-instances-status.js:98:19
Mar 31 09:49:51 chat rocketchat1: at [object Object]..extend.withValue (packages/meteor.js:1122:17)
Mar 31 09:49:51 chat rocketchat1: at packages/meteor.js:445:45
Mar 31 09:49:51 chat rocketchat1: at runWithEnvironment (packages/meteor.js:1176:24)
Mar 31 09:49:51 chat rocketchat1: app.js:9037 #33[34mStreamBroadcast ➔ Auth.info#033[39m prevent self connect localhost:3001

[IQ2022]

what issue are we on right now? i am on 54.0 and notice slowness and sometimes i think chat is hanging or restarting.
some messages get sent late and i see them in error log..

�[34mI20170331-15:18:43.394(0) Exception while invoking method 'sendMessage' WriteError({"code":11000,"index":0,"errmsg":"E11000 duplicate key error collection: rocketchat.rocketchat_message index: id dup key: { : "GTMmzDi8ssG2pCXac" }","op":{"_id":"GTMmzDi8ssG2pCXac","rid":"YF6BrrcmupQ2Y9LqbqwERPrKbWbr7ogGbS","msg":"ya just reading through them ","ts":"2017-03-31T15:18:43.309Z","u":{"id":"YF6BrrcmupQ2Y9Lqb","username":"iv_trader"},"updatedAt":"2017-03-31T15:18:43.322Z"}}) at Object.Future.wait (/app/bundle/programs/server/node_modules/fibers/future.js:449:15) at [object Object]. (packages/meteor.js:213:24) at [object Object].MongoConnection.(anonymous function) [as insert] (/app/bundle/programs/server/packages/mongo.js:831:49) at Object. (packages/matb33_collection-hooks.js:395:18) at Object.collection.(anonymous function) [as insert] (packages/matb33_collection-hooks.js:146:21) at [object Object].insert (/app/bundle/programs/server/packages/mongo.js:3820:38) at ModelsBaseDb.insert (/app/bundle/programs/server/packages/rocketchat_lib.js:9527:54) at Class.insert (/app/bundle/programs/server/packages/rocketchat_lib.js:4175:36) at Object.RocketChat.sendMessage (/app/bundle/programs/server/packages/rocketchat_lib.js:3175:46) at [object Object].Meteor.methods.sendMessage (/app/bundle/programs/server/packages/rocketchat_lib.js:12910:23) at [object Object].methodsMap.(anonymous function) (/app/bundle/programs/server/packages/rocketchat_lib.js:1095:26) at maybeAuditArgumentChecks (/app/bundle/programs/server/packages/ddp-server.js:1817:12) at /app/bundle/programs/server/packages/ddp-server.js:905:20 at [object Object]..extend.withValue (packages/meteor.js:1122:17) at /app/bundle/programs/server/packages/ddp-server.js:904:41 at [object Object]..extend.withValue (packages/meteor.js:1122:17) at /app/bundle/programs/server/packages/ddp-server.js:903:46 at [object Object]..extend.protocol_handlers.method (/app/bundle/programs/server/packages/ddp-server.js:876:21) at /app/bundle/programs/server/packages/ddp-server.js:755:85 - - - - - at Function.MongoError.create (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/error.js:31:11) at toError (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:114:22) at /app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/collection.js:657:23 at handleCallback (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:95:56) at resultHandler (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/bulk/ordered.js:421:14) at /app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/connection/pool.js:455:18 at nextTickCallbackWith0Args (node.js:489:9) at process._tickDomainCallback (node.js:459:13)
�[34mI20170331-15:47:54.041(0) Exception while invoking method 'sendMessage' WriteError({"code":11000,"index":0,"errmsg":"E11000 duplicate key error collection: rocketchat.rocketchat_message index: id dup key: { : "kfddAqAXqi9NJZfDr" }","op":{"_id":"kfddAqAXqi9NJZfDr","rid":"rdEXg8CBeh5RT4EJa","msg":"STO -2 IRON CONDOR DE 100 (Weeklys) 7 APR 17 109/112/109/106 CALL/PUT @1.60 LMT ","ts":"2017-03-31T15:47:53.969Z","u":{"id":"YF6BrrcmupQ2Y9Lqb","username":"iv_trader"},"updatedAt":"2017-03-31T15:47:53.975Z"}}) at Object.Future.wait (/app/bundle/programs/server/node_modules/fibers/future.js:449:15) at [object Object]. (packages/meteor.js:213:24) at [object Object].MongoConnection.(anonymous function) [as insert] (/app/bundle/programs/server/packages/mongo.js:831:49) at Object. (packages/matb33_collection-hooks.js:395:18) at Object.collection.(anonymous function) [as insert] (packages/matb33_collection-hooks.js:146:21) at [object Object].insert (/app/bundle/programs/server/packages/mongo.js:3820:38) at ModelsBaseDb.insert (/app/bundle/programs/server/packages/rocketchat_lib.js:9527:54) at Class.insert (/app/bundle/programs/server/packages/rocketchat_lib.js:4175:36) at Object.RocketChat.sendMessage (/app/bundle/programs/server/packages/rocketchat_lib.js:3175:46) at [object Object].Meteor.methods.sendMessage (/app/bundle/programs/server/packages/rocketchat_lib.js:12910:23) at [object Object].methodsMap.(anonymous function) (/app/bundle/programs/server/packages/rocketchat_lib.js:1095:26) at maybeAuditArgumentChecks (/app/bundle/programs/server/packages/ddp-server.js:1817:12) at /app/bundle/programs/server/packages/ddp-server.js:905:20 at [object Object]..extend.withValue (packages/meteor.js:1122:17) at /app/bundle/programs/server/packages/ddp-server.js:904:41 at [object Object]..extend.withValue (packages/meteor.js:1122:17) at /app/bundle/programs/server/packages/ddp-server.js:903:46 at [object Object]..extend.protocol_handlers.method (/app/bundle/programs/server/packages/ddp-server.js:876:21) at /app/bundle/programs/server/packages/ddp-server.js:755:85 - - - - - at Function.MongoError.create (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/error.js:31:11) at toError (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:114:22) at /app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/collection.js:657:23 at handleCallback (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:95:56) at resultHandler (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/bulk/ordered.js:421:14) at /app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/connection/pool.js:455:18 at nextTickCallbackWith0Args (node.js:489:9) at process._tickDomainCallback (node.js:459:13)

[geekgonecrazy]

@IQ2022 these don't look to be related. Hit me up on the community server :)

[geekgonecrazy]

@mddvul22 if you take a look at your mongo servers stats are you noticing high CPU / Memory around this time? Or high latency between your rocket.chat server and your mongo server?

[mddvul22]

Definitely high load. We've only encountered this once. mongo was using all of the processing power, if I recall correctly. If it happens again, I'll be sure to get the details.

[geekgonecrazy]

@mddvul22 what version of mongo are you using? It sounds like you may be using a later version with the wiredtiger storage engine enabled. I've found it to be a bit aggressive on CPU and Memory.

[mddvul22]

3.0.14 on Centos 7.

[geekgonecrazy]

ok so you do have wiredtiger. If this continues to be an issue for you I would suggest switching storage engines to mmapv1.

[mddvul22]

Thanks! We will keep an eye on this and look into mmapv1.

[geekgonecrazy]

mmapv1 used to be shipped as default by mongo before mongo 3.0 3.2(thanks @mddvul22). Please let us know how you end up. We're looking for as many observations as we can, to determine if this should be the recommended storage engine. Thanks!

[mddvul22]

Hi geekgonecrazy, I got around today to checking our mongo/rocketchat install more closely. While we are running 3.0.14, we are not using wiredtiger. Connecting to our mongo instance shows:

rs0:PRIMARY> db.serverStatus().storageEngine
{ "name" : "mmapv1" }

It appears from the mongo documentation that mmapv1 is the default in 3.0, wiredtiger became the default in 3.2.

[geekgonecrazy]

@mddvul22 perfect.

Just noticed when looking over the logs you have:

xxxx.xxxxx.com:27017

This isn't public exposed any is it? It saying:

MongoError: connection 39674

makes it seem as if there are a lot of connections to the server.

Something is definitely causing mongo to get hammered. On average you shouldn't be having very many connections to mongo. A lot of data is actually cached in memory to avoid having to connect to mongo as much. This cache is even propagated between nodes, to prevent mongo from being needed for instance syncing either.

Our demo server is running 6 instances currently and only consuming 40 connections. Definitely check into the high connection count.

[mddvul22]

No, is is firewalled off, and I've just double checked that to make sure. I've replaced the hostname in the bug report just to keep it hidden in the bug report. The reverse proxy is publicly available, but the the mongo instance is only accessible from localhost (for the nginx proxy), the secondary mongo instance, and the arbiter. Currently, the connections look good. But of course, we aren't having any issues right now, either.

"connections" : {
	"current" : 19,
	"available" : 51181,
	"totalCreated" : NumberLong(393625)

[geekgonecrazy]

Please let us know if you discover anything!