Exception while invoking method 'sendMessage'

[javiergoni]

Description:

We have this error eventually and the RC service goes down. It happens at least twice a day
Exception while invoking method 'sendMessage' { BulkWriteError: E11000 duplicate key error collection: rocketchat.rocketchat_message index: _id_ dup key
I think it could be due to clients with slow internet connection

Server Setup Information:

• Version of Rocket.Chat Server: 0.73.1
• Operating System: Ubuntu
• Deployment Method: tar
• Number of Running Instances: 4
• DB Replicaset Oplog: yes
• NodeJS Version: 8.11.4
• MongoDB Version: 3.2.15

Additional context

Relevant logs:

May 13 15:13:30 rocketchat-hb2 rocketchat[3755]: Exception while invoking method 'sendMessage' { BulkWriteError: E11000 duplicate key error collection: rocketchat.rocketchat_message index: _id_ dup key: { : "E6dL858N2S3sTAxji" }
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:     at OrderedBulkOperation.handleWriteError (/home/rocket/Rocket.Chat/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/bulk/common.js:1048:11)
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:     at resultHandler (/home/rocket/Rocket.Chat/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/bulk/ordered.js:159:23)
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:     at handler (/home/rocket/Rocket.Chat/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/topologies/replset.js:1195:22)
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:     at /home/rocket/Rocket.Chat/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/connection/pool.js:532:18
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:     at _combinedTickCallback (internal/process/next_tick.js:131:7)
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:     at process._tickDomainCallback (internal/process/next_tick.js:218:9)
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   index: 0,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   code: 11000,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   errmsg: 'E11000 duplicate key error collection: rocketchat.rocketchat_message index: _id_ dup key: { : "E6dL858N2S3sTAxji" }',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   op:
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:    { _id: 'E6dL858N2S3sTAxji',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      rid: 'BwfyGFvAyuBbANS8vtjH7ihkqHzMjpfWKc',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      msg: '+++++++++++++++++++++++++++++++++++++++++++++++++',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      ts: 2019-05-13T15:13:30.844Z,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      u:
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:       { _id: 'tjH7ihkqHzMjpfWKc',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         username: '++++++++++++++',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         name: '+++++++++++' },
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      mentions: [],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      channels: [],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      _updatedAt: 2019-05-13T15:13:30.861Z },
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   name: 'BulkWriteError',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   driver: true,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   err:
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:    { index: 0,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      code: 11000,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      errmsg: 'E11000 duplicate key error collection: rocketchat.rocketchat_message index: _id_ dup key: { : "E6dL858N2S3sTAxji" }',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      op:
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:       { _id: 'E6dL858N2S3sTAxji',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         rid: 'BwfyGFvAyuBbANS8vtjH7ihkqHzMjpfWKc',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         msg: '+++++++++++++++++++++++++++++++++++++++++++++++++++++++++',
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         ts: 2019-05-13T15:13:30.844Z,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         u: [Object],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         mentions: [],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         channels: [],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         _updatedAt: 2019-05-13T15:13:30.861Z } },
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   result:
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:    BulkWriteResult {
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:      result:
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:       { ok: 1,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         writeErrors: [Array],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         writeConcernErrors: [],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         insertedIds: [Array],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         nInserted: 0,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         nUpserted: 0,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         nMatched: 0,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         nModified: 0,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         nRemoved: 0,
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         upserted: [],
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:         lastOp: [Object] } },
May 13 15:13:30 rocketchat-hb2 rocketchat[3755]:   [Symbol(mongoErrorContextSymbol)]: {} }

[zogith]

I20190513-08:08:24.257(0) ➔ +-------------------------------------------------------+ 
I20190513-08:08:24.258(0) ➔ |                     SERVER RUNNING                    | 
I20190513-08:08:24.259(0) ➔ +-------------------------------------------------------+ 
I20190513-08:08:24.259(0) ➔ |                                                       | 
I20190513-08:08:24.260(0) ➔ |  Rocket.Chat Version: 1.0.3                           | 
I20190513-08:08:24.260(0) ➔ |       NodeJS Version: 8.11.4 - x64                    | 
I20190513-08:08:24.261(0) ➔ |      MongoDB Version: 3.2.21                          | 
I20190513-08:08:24.261(0) ➔ |       MongoDB Engine: wiredTiger                      | 
I20190513-08:08:24.262(0) ➔ |             Platform: linux                           | 
I20190513-08:08:24.263(0) ➔ |         Process Port: 3000                            | 
I20190513-08:08:24.263(0) ➔ |             Site URL: https://xxxxxxxx.yyyyyyyy.org  | 
I20190513-08:08:24.263(0) ➔ |     ReplicaSet OpLog: Enabled                         | 
I20190513-08:08:24.264(0) ➔ |          Commit Hash: f19473c626                      | 
I20190513-08:08:24.264(0) ➔ |        Commit Branch: HEAD                            | 
I20190513-08:08:24.265(0) ➔ |                                                       | 
I20190513-08:08:24.265(0) ➔ +-------------------------------------------------------+ 

We have been seeing similar on a very small rocketchat instance (under 40 active users) deployed from docker to Debian Linux. The mongoDB was converted to run DB Replicaset as a single instance when it was required with the v1.0 release.. The rocketchat doesn't crash but we see this error a few times a day, there are reports of rocketchat being slower as well but not sure if this is connected to these errors..

i.e.

Error sending message: { BulkWriteError: E11000 duplicate key error collection: meteor.rocketchat_message index: _id_ dup key: { : "B6tSoqXz4hvDuDadx" }     at OrderedBulkOperation.handleWriteError (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/bulk/common.js:1048:11

etc.