Node call stack exceeded from Mongo bulkOperation

1

Hi!

I have a nightly sync that refreshes a large collection.

I make a call to the Meteor server md that downloads data and then makes another call to another method that upserts this data. This 2nd server md uses the Node Mongo driver to perform a large list of upserts and removes in a single orderedBulkOperation execute.

So the Meteor Server method that calls another method that makes an async callout to actually perform the bulk operation.

This has ran fine for about a year now on the cloud. I recently updated from Meteor 1.8.0.2 to 2.2 (involved updating Node 8 → 12) - and also switched from Heroku to AWS.

I don’t think the platform change is the issue but it’s hard to say. It’s a big Meteor update, but I haven’t seen anything in changelogs about specific Mongo Driver

I’ve now gotten a few errors over the last couple weeks about Node’s call stack exceeding. It looks like this is due to recursive calls internally in the Mongo Driver (and no base of recursion). I’m unable to reproduce this locally.

I see that the bulk.remove is deprecated https://mongodb.github.io/node-mongodb-native/3.6/api/FindOperators.html#remove I can’t imagine that being the culprit though.

It is a rather large list of docs that are being processed by the single execute method (~20+MB of JSON).

Here is the stacktrace. Not sure how to debug it as I cannot reproduce locally and it’s happening inconsistently on the cloud. Thought maybe it was a one-off thing (As it worked fine for couple weeks after first incident - but now it happened again today) I still gotta check my Mongo Server logs

Edit: I Checked /var/log/mongodb . I can see the it shows Node disconnected and that it re-establiushed a connection when the app server restarted. But nothing specific to what caused the issue. This makes sense as the error is on the client-side

 /var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:691
 throw error;
 RangeError: Maximum call stack size exceeded
 at ServerSessionPool.acquire (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/sessions.js:623:12)
 at ClientSession.get serverSession [as serverSession] (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/sessions.js:113:47)
 at /var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/sessions.js:148:19
 at maybePromise (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:685:3)
 at ClientSession.endSession (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/sessions.js:130:12)
 at Cursor._endSession (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/cursor.js:392:15)
 at done (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/cursor.js:448:16)
 at /var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/cursor.js:536:11
 at /var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:688:9
 at /var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/operations/execute_operation.js:82:7
 at maybePromise (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:685:3)
 at executeOperation (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/operations/execute_operation.js:34:10)
 at Cursor._initializeCursor (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/cursor.js:534:7)
 at Cursor._initializeCursor (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/cursor.js:186:11)
 at Object.callback (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/cursor.js:439:14)
 at processWaitQueue (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/sdam/topology.js:1049:21)
 at NativeTopology.selectServer (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/sdam/topology.js:449:5)
 at executeWithServerSelection (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/operations/execute_operation.js:131:12)
 at /var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/operations/execute_operation.js:70:9
 at maybePromise (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/utils.js:685:3)
 at executeOperation (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/operations/execute_operation.js:34:10)
 at Cursor._initializeCursor (/var/app/current/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/core/cursor.js:534:7)

Not sure what I can do other than refactoring whole methodology and hoping it doesn’t come back again.

Potential ideas

  1. Update the deprecated remove to delete
  2. “chunk” the execute call (maybe processing the >20MB is just too much)
  3. Don’t have Meteor server md call another md just to handle the execute (put it into just 1 server call)
2

npm-mongo changed from 3.1.x to 3.9.x

1 Like
3

Ah, good to know. I’ll look through changelogs to see if anything pops out

4

mm…I see the change in my versions file now. There’s a ton in the changelogs throughout the jump. Not sure where to start. COuldn’t see anything about a bug with recursion or anything. Might be worth it to replace deprecated remove with delete. Tough bc I cannot reproduce locally though. Bug doesn’t even seem to happen on my staging environment

5

I went through code of actual stack trace and put in a console.trace of the top of the trace in an internal node-mongo cursor.js.
The console.traces were frequently popping up and there wasn’t a 1-time call

So I suspect that the issue could be with unrelated connections for the app and pub/sub being done while this bulk execute is being attempted.

OP on https://www.mongodb.com/community/forums/t/under-load-mongodb-queries-may-result-in-maximum-call-stack-exceeded-error/115695/2 seems to have a very similar issue.

6

https://docs.meteor.com/changelog.html#migrationsteps-2

Hm…I’m wondering if opting in to useUnifiedTopology could be causing this. I could set to false if so, but again, hard to test/reproduce issue

7

This guy is also using Meteor.

So I think it’s something to do with ongoing pub/sub while an expensive DB call is made.
My bulk.execute is trying to process a ~30MB JSON.

Npm-mongo states that it already splits payload into chunks of 1k Docs. So I see no reason to manually do this in hopes of preventing the crash.

ANy insights?