Automattic / mongoose

MongoDB object modeling designed to work in an asynchronous environment.
https://mongoosejs.com
MIT License
26.92k stars 3.84k forks source link

Obscure error message from onError event. #9401

Closed CLaszlo closed 4 years ago

CLaszlo commented 4 years ago

What is the current behavior? I have a nodeJs API that connects to a mongodb replica set with 3 nodes. A cron job is set to run multiple times every hour, during which a script is executed that connects to all databases on the replica set, and executes a set of queries on them. During execution, the connections are initialized one by one and a new connection is only created after the queries have finished on the most recently connected database.

Recently the script started to fail, and from the logs the following was extracted:

ERROR : true

which is logged by the following code: connection.on('error', function(err) { console.log('ERROR : ' + err); } After the onError event, onDisconnected and onConnecting events are also triggered.

My question would be regarding the error printed. I can't seem to find any indication where the value 'true' would originate from. I have looked at the mongoose and mongoDb errors, but can't seem to find anything that would be relevant.

What are the versions of Node.js, Mongoose and MongoDB you are using? Note that "latest" is not a version. Node.js version: 10.14.1 Mongoose version: 5.5.1 Node MongoDB driver version: 3.2.2 MongoDB version: 4.0.12

vkarpov15 commented 4 years ago

This is very strange. Can you please change your log statement to console.log('ERROR : ' + err, new Error().stack);? That will help tell us where the code that's generating this error is coming from.

CLaszlo commented 4 years ago

Absolutely. The error appears sporadically, therefore it might take a bit of time for it to show up again, however I have updated the code with your change proposal. I will update the post as soon as I get the error again!

CLaszlo commented 4 years ago

Sorry for the late update, the error only showed up now. Here is the extracted stack trace:

** ERROR : true Error
at NativeConnection. (****)
at NativeConnection.emit (events.js:182:13)
at process.nextTick (**\node_modules\mongoose\lib\connection.js:618:37)
at process._tickCallback (internal/process/next_tick.js:61:11)

vkarpov15 commented 4 years ago

According to the stack trace, this error comes up from the MongoDB node driver: https://github.com/Automattic/mongoose/blob/5.5.1/lib/connection.js#L616-L618. It's coming from either the initial connection or the connection string parsing.

Are you connecting to MongoDB Atlas using a mongodb+srv:// connection string?

CLaszlo commented 4 years ago

No, we are not connecting to Atlas. Connections are made to the mongo replicaset hosted on a VM in the cloud (MS Azure).

The connection does not use the +srv modifier, it is formatted simply based on how the documentation suggested: mongodb://[username:password@]host1[:port1][,...hostN[:portN]][/[defaultauthdb]

vkarpov15 commented 4 years ago

So that means that initial connection is failing.

Are you able to connect to this URI using the mongo shell? Try running mongo "mongodb://host1:27017/mydb", replacing host1:27017/mydb with your credentials.

CLaszlo commented 4 years ago

I am unable to test it by manually connecting, sadly.

The DB VM is locked behind a firewall, only accepting traffic from the API and this can't be overridden. Even though I can't test it manually, I can see that future connections to the same db succeed, and the script executes without problem. However, the same error message pops up every few days.

Additional investigation seems to point towards SNAT Port Exhaustion warnings, that somewhat align up with the timestamps on the error logs. Could it be that the initial connection is being rejected by the host of the API, resulting in this obscure error?

vkarpov15 commented 4 years ago

I unfortunately don't know anything about SNAT ports, so I can't say. I've never seen this error pop up as the result of initial connection being rejected, but I'm not confident that it is impossible.

Note for me to look into: perhaps somewhere the MongoDB driver is bubbling up the value from the 'close' event as an error, which is a boolean: https://nodejs.org/api/net.html

vkarpov15 commented 4 years ago

I took a closer look and it appears that this is a known issue with older versions of the MongoDB driver, it was fixed in this commit: https://github.com/mongodb-js/mongodb-core/commit/83e224b . The earliest version of Mongoose that has this fix is v5.5.12, so please upgrade to 5.5.12 or higher and see if that fixes it.