Two node/express servers behind AWS ELB are processing messages from IoT devices. Currently, about 5 messages per second. About once per day, the mongoose is being disconnected and re-connected immediately. How can I find the root cause?
We create DB connection like this:
return new Promise((resolve, reject) => {
const options = { useNewUrlParser: true, useUnifiedTopology: true };
const config = AppConfig.getDBConfig();
mongoose.connect(config.db, options);
mongoose.set('useCreateIndex', true);
mongoose.set('useFindAndModify', false);
const connection = mongoose.connection;
connection.on('error', (err) => {
logger.error('Mongo connection error', JSON.stringify(err));
reject(err);
});
connection.on('connected', () => {
logger.info('Mongo connected');
MongoDBConfig.isInitialized = true;
resolve();
});
connection.on('disconnected',(err) => {
let errString: string;
try {
errString = JSON.stringify(err);
} catch (err) {
errString = err;
}
logger.error(`Mongo disconnected!, error: ${errString}`);
mongoose.connect(config.db, options);
});
if (process.env.NODE_ENV === 'development') {
// mongoose.set('debug', true)
}
});
The callback on error is never triggered and err variable in disconnected event is always undefined, so it does not help.
We have no other errors in the log related to DB queries or accessing DB.
There is nothing special in mongod system log at the time of disconnect:
2021-03-19T05:18:01.238+0000 I NETWORK [listener] connection accepted from 10.111.1.125:46372 #234415 (30 connections now open)
2021-03-19T05:18:01.238+0000 I NETWORK [conn234415] end connection 10.111.1.125:46372 (29 connections now open)
2021-03-19T05:18:01.274+0000 I NETWORK [listener] connection accepted from 10.111.1.20:37476 #234416 (30 connections now open)
2021-03-19T05:18:01.275+0000 I NETWORK [conn234416] end connection 10.111.1.20:37476 (29 connections now open)
2021-03-19T05:18:01.578+0000 I NETWORK [listener] connection accepted from 10.111.1.108:47094 #234417 (30 connections now open)
2021-03-19T05:18:01.579+0000 I NETWORK [conn234417] end connection 10.111.1.108:47094 (29 connections now open)
2021-03-19T05:18:01.971+0000 I NETWORK [listener] connection accepted from 10.111.1.80:48588 #234418 (30 connections now open)
2021-03-19T05:18:01.971+0000 I NETWORK [conn234418] end connection 10.111.1.80:48588 (29 connections now open)
2021-03-19T05:18:02.031+0000 I NETWORK [listener] connection accepted from 10.111.1.54:55860 #234419 (30 connections now open)
2021-03-19T05:18:02.031+0000 I NETWORK [conn234419] end connection 10.111.1.54:55860 (29 connections now open)
2021-03-19T05:18:07.739+0000 I COMMAND [conn234380] command cholula.users command: findAndModify { findAndModify: "users", query: { _id: ObjectId('5febc23db6c2415ced9bbf0e') }, new: true, remove: false, upsert: true, fields: {}, update: { $setOnInsert: { __v: 0 }, $push: { clients: { _id: ObjectId('6054340f05b98a609858566f') } } }, lsid: { id: UUID("f85769be-6342-4be8-a1b3-f4602e0cfe10") }, $db: "cholula" } planSummary: IDHACK keysExamined:1 docsExamined:1 nMatched:1 nModified:1 numYields:0 reslen:15714377 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 108ms
2021-03-19T05:18:22.898+0000 I COMMAND [conn234384] command cholula.users command: findAndModify { findAndModify: "users", query: { _id: ObjectId('5febc23db6c2415ced9bbf0e') }, new: true, remove: false, upsert: true, fields: {}, update: { $setOnInsert: { __v: 0 }, $push: { clients: { _id: ObjectId('6054341e05b98a6098585764') } } }, lsid: { id: UUID("f5761ca9-c23c-4ef5-aa32-87c7e5148031") }, $db: "cholula" } planSummary: IDHACK keysExamined:1 docsExamined:1 nMatched:1 nModified:1 numYields:0 reslen:15714406 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 157ms
2021-03-19T05:18:33.697+0000 I WRITE [conn234388] update cholula.users command: { q: { _id: ObjectId('5febc23db6c2415ced9bbf0e'), clients._id: ObjectId('6054340f05b98a609858566f') }, u: { $set: { clients.$.refreshToken: "6054340f05b98a609858566f.3d62ff997442e52c1e37fab447741ecbe882df34e268c910caf81f0cf6bc740c6acde78c78af2c4c", clients.$.expire: new Date(1618550313538) } }, multi: false, upsert: false } planSummary: IXSCAN { _id: 1 } keysExamined:1 docsExamined:1 nMatched:1 nModified:1 numYields:1 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } 158ms
2021-03-19T05:18:33.697+0000 I COMMAND [conn234388] command cholula.$cmd command: update { update: "users", updates: [ { q: { _id: ObjectId('5febc23db6c2415ced9bbf0e'), clients._id: ObjectId('6054340f05b98a609858566f') }, u: { $set: { clients.$.refreshToken: "6054340f05b98a609858566f.3d62ff997442e52c1e37fab447741ecbe882df34e268c910caf81f0cf6bc740c6acde78c78af2c4c", clients.$.expire: new Date(1618550313538) } }, upsert: false, multi: false } ], ordered: true, lsid: { id: UUID("f85769be-6342-4be8-a1b3-f4602e0cfe10") }, $db: "cholula" } numYields:0 reslen:44 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_msg 158ms
2021-03-19T05:18:34.649+0000 I NETWORK [conn234379] end connection 10.111.1.108:44452 (28 connections now open)
2021-03-19T05:18:34.730+0000 I NETWORK [listener] connection accepted from 10.111.1.108:47166 #234420 (29 connections now open)
2021-03-19T05:18:34.755+0000 I NETWORK [listener] connection accepted from 10.111.1.108:47172 #234421 (30 connections now open)