GRPC-JS: Possible EventEmitter memory leak detected

[schmidt-sebastian]

See #623 (comment)

I just upgraded to @google-cloud/firestore@2.0.0 and since upgrading, I've been getting all of these warnings that say:
(node:2870) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 connectivityStateChanged listeners added. Use emitter.setMaxListeners() to increase limit

[schmidt-sebastian]

I believe that this is an issue in grpc-js. See: grpc/grpc-node#694 (comment)

The user report indicates that this happens when a client repeatedly cannot connect to the backend.

[jakeleventhal]

@schmidt-sebastian this happens when run a lot of operations at once i.e. i have a function to wipe my development database and it looks something like this

['Collection1', 'Collection2', 'Collection3'].map((collection) => {
    const data = await firestore.collection(collection).select().get();
    return data.docs.map((doc) => firestore.collection(collection).doc(doc.id).delete());
});

When my database is rather full, this error pops up hundreds of times.

This also happens when I onboard large users to my application - a lot of documents are being created/updated (different from contention on a single document), often in parallel functions like above^.

[schmidt-sebastian]

I believe this happens when there are more than 10 outstanding requests (with pending DeadlineFilters) on a single HTTP2 channel. For me, this does not reproduce over fast networks, but reproduces reliably when I turn on package loss (using Apple's Network Link Conditioner). A test that can be used to reproduce is https://github.com/googleapis/nodejs-firestore/blob/master/dev/system-test/firestore.ts#L928

I will ping the GRPC team directly to prioritize this issue.

[schmidt-sebastian]

grpc-js version 0.4.1 includes a fix for this issue. If you update your dependencies, you should receive this version (google-gax pulls in 0.4.x). You might have to update/delete your package lock files.

[schmidt-sebastian]

We had to revert grpc-js back to 0.4.0. I am re-opening this issue.

[jmacedoit]

This happens with my firestore node server setup always on startup (where I begin listening to several collections) ever since i upgraded to @google-cloud/firestore": "^2.1.0". And the greater the number of listeners, the greater the number of messages. It looks like this message is output once for every 100 or so streams I'm listening. My setup is exactly the same as described in: #673

[schmidt-sebastian]

@jmacedoit Sorry to hear about your troubles. We will get this fixed as soon as we sort out the remaining issues with @grpc/grpc-js v0.4.1.

[jakeleventhal]

@schmidt-sebastian any update on this? I am having critical problems with firestore related to this bug. is there a fix in the meantime to revert?

[schmidt-sebastian]

This has been fixed with the release of @grpc/grpc-js, which any version of @google-cloud/firestore 2.x (with the exception of the bugfix release 2.1.1) should pull in automatically.

[guanzo]

I'm still getting this error, here's the output of npm ls

/file-processor # npm ls @grpc/grpc-js
file-processor@ /file-processor
+-- @google-cloud/datastore@3.1.2
| `-- google-gax@0.25.6
|   `-- @grpc/grpc-js@0.3.6 
`-- @google-cloud/firestore@2.2.0
  `-- google-gax@1.1.1
    `-- @grpc/grpc-js@0.4.3

Screenshot of error

Is the onSnapshot method able to listen forever? Or should I close the listener and resubscribe periodically?

[schmidt-sebastian]

@guanzo Are you using datastore when you see these errors? The EventEmitter warning might come from the old version of grpc-js bundled with google-gax < 1.0.

I can certainly try to reproduce this issue again with the newest version of grpc-js, but for me the warnings went away as of 0.4.1.

You should be able to listen forever, and we reconnect for you. In general, will we abort a listen stream only if we fail to reconnect 10 times in a row.

[jmacedoit]

I'm seeing the same thing as @guanzo. And the only occurrences of grpc/grpc-js in my dependency tree are of grpc-js@0.4.3.

├─┬ @google-cloud/firestore@2.2.0
│ ├─┬ bun@0.0.12
│ │ └─┬ readable-stream@1.0.34
│ │   ├── core-util-is@1.0.2
│ │   ├── inherits@2.0.3 deduped
│ │   ├── isarray@0.0.1 deduped
│ │   └── string_decoder@0.10.31
│ ├── deep-equal@1.0.1
│ ├── functional-red-black-tree@1.0.1
│ ├─┬ google-gax@1.1.1
│ │ ├── @grpc/grpc-js@0.4.3 deduped
...
├─┬ @grpc/grpc-js@0.4.3

Note that the warning messages are slighty different also. Now we get:

(node:48004) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 drain listeners added. Use emitter.setMaxListeners() to increase limit
(node:48004) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 error listeners added. Use emitter.setMaxListeners() to increase limit
(node:48004) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added. Use emitter.setMaxListeners() to increase limit

as opposed to

(node:2870) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 connectivityStateChanged listeners added. Use emitter.setMaxListeners() to increase limit

[schmidt-sebastian]

I will work with the GRPC JS team to get this one fixed as well. Sorry for all the trouble with this new networking layer, but shipping a 50MB+ C-dependency (the old GRPC core) was never something we were proud of.

[jmacedoit]

@schmidt-sebastian And you people have been doing great. From what I've seen in the past few weeks, I believe that we will soon be able to enjoy an error/warning free and very robust SDK. Keep up with the good work 🥇

[schmidt-sebastian]

@jmacedoit Are you able to help us debug over at grpc/grpc-node#916?

[schmidt-sebastian]

Re-opening this issue for additional visibility.

[jmacedoit]

@schmidt-sebastian Yes I'm trying to reproduce it again.

[Tobb3]

I've encountered this problem for a couple of weeks. My packages/dependencies are the same as @jmacedoit
To narrow it down, I created an application that subscribes to 1 single collection in firestore. A collection that has no documents and no documents are ever added.
db.collection('somecollection').onSnapshot(...)

The subscription is starting and everything looks fine until about 4 hours of idling, I get this error

MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 drain listeners added. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:256:17)
    at DestroyableTransform.addListener (events.js:272:10)
    at DestroyableTransform.Readable.on (c:\repos\testworker\node_modules\through2\node_modules\readable-stream\lib\_stream_readable.js:786:33)
    at BunWrapper.Stream.pipe (internal/streams/legacy.js:28:8)
    at _firestore.readWriteStream.then.backendStream (c:\repos\testworker\node_modules\@google-cloud\firestore\build\src\watch.js:343:35)

That's all I have atm, I will try to find out more

[guanzo]

Thanks for the fix 👍 , will upgrade now and report any errors.

[MarkChrisLevy]

@thebrianchen @schmidt-sebastian It is still an issue - latest @google-cloud/firestore (2.3.0) and latest grpc@grpc-js (0.5.3). Stack trace:

node --trace-warnings dist/local-test.js
(node:15717) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:243:17)
    at TLSSocket.addListener (events.js:259:10)
    at TLSSocket.Readable.on (_stream_readable.js:799:35)
    at Http2CallStream.attachHttp2Stream (/cloud-functions/node_modules/@grpc/grpc-js/build/src/call-stream.js:275:35)
    at Http2SubChannel.startCallStream (/cloud-functions/node_modules/@grpc/grpc-js/build/src/subchannel.js:110:20)
    at finalMetadata.then.metadataValue (/cloud-functions/node_modules/@grpc/grpc-js/build/src/channel.js:205:28)

It happens not only in my local environment, but also in a production firebase function.

[nip10]

Also happening here, GCP Function w/ Firestore + KMS

@google-cloud/firestore": "2.3.0"
@google-cloud/kms": "1.3.2"

MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added. Use emitter.setMaxListeners() to increase limit  
    at _addListener (events.js:280:19)  
    at TLSSocket.addListener (events.js:297:10)  
    at TLSSocket.Readable.on (_stream_readable.js:772:35)  
    at Http2CallStream.attachHttp2Stream (/srv/node_modules/@grpc/grpc-js/build/src/call-stream.js:275:35)  
    at Http2SubChannel.startCallStream (/srv/node_modules/@grpc/grpc-js/build/src/subchannel.js:110:20)  
    at finalMetadata.then.metadataValue (/srv/node_modules/@grpc/grpc-js/build/src/channel.js:205:28) 

[jakeleventhal]

can confirm

[marcinolawski]

It is still an issue:

@google-cloud/firestore@2.3.0
@grpc/grpc-js@0.5.3

MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added. Use emitter.setMaxListeners() to increase limit
    at _addListener (events.js:280:19)
    at TLSSocket.addListener (events.js:297:10)
    at TLSSocket.Readable.on (_stream_readable.js:772:35)
    at Http2CallStream.attachHttp2Stream (/srv/node_modules/@grpc/grpc-js/build/src/call-stream.js:275:35)
    at Http2SubChannel.startCallStream (/srv/node_modules/@grpc/grpc-js/build/src/subchannel.js:110:20)
    at finalMetadata.then.metadataValue (/srv/node_modules/@grpc/grpc-js/build/src/channel.js:205:28)
    at <anonymous>

[krufebird]

Issue over here as well:

$ npm ls @grpc/grpc-js
└─┬ firebase-admin@8.5.0
└─┬ @google-cloud/firestore@2.3.0
└─┬ google-gax@1.5.2
└── @grpc/grpc-js@0.5.3

(node:10569) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [TLSSocket]. Use emitter.setMaxListeners() to increase limit
MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [TLSSocket]. Use emitter.setMaxListeners() to increase limit
at _addListener (events.js:261:17)
at TLSSocket.addListener (events.js:277:10)
at TLSSocket.Readable.on (_stream_readable.js:846:35)
at Http2CallStream.attachHttp2Stream (/Users/x/repos/x-app/server/node_modules/@grpc/grpc-js/build/src/call-stream.js:275:35)
at Http2SubChannel.startCallStream (/Users/x/repos/x-app/server/node_modules/@grpc/grpc-js/build/src/subchannel.js:110:20)
at /Users/x/repos/x-app/server/node_modules/@grpc/grpc-js/build/src/channel.js:205:28
at processTicksAndRejections (internal/process/task_queues.js:85:5)

(node:10569) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [TLSSocket]. Use emitter.setMaxListeners() to increase limit
MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 close listeners added to [TLSSocket]. Use emitter.setMaxListeners() to increase limit
at _addListener (events.js:261:17)
at TLSSocket.addListener (events.js:277:10)
at TLSSocket.Readable.on (_stream_readable.js:846:35)
at Http2CallStream.attachHttp2Stream (/Users/x/repos/x-app/server/node_modules/@grpc/grpc-js/build/src/call-stream.js:275:35)
at Http2SubChannel.startCallStream (/Users/x/repos/x-app/server/node_modules/@grpc/grpc-js/build/src/subchannel.js:110:20)
at /Users/x/repos/x-app/server/node_modules/@grpc/grpc-js/build/src/channel.js:205:28
at processTicksAndRejections (internal/process/task_queues.js:85:5)

[guanzo]

FWIW, i'm still on @google-cloud/firestore@2.2.4 and no issues. something must have regressed in later releases.

[schmidt-sebastian]

@MarkChrisLevy @krufebird @guanzo This is a regression in the latest release of @grpc/grpc-js. If you are blocked on this, you can manually pin to 0.5.2.

The corresponding issue is: grpc/grpc-node#1027

[lzl124631x]

@schmidt-sebastian How to pin the grpc version without adding that to package.json? Add it to package-lock.json would be fine. I tried npm install @grpc/grpc-js@0.5.2 --save-exact but that saves grpc in package.json which is unnecessary.

[MarkChrisLevy]

@schmidt-sebastian Yep, grpc-js@0.5.2 is ok. Thanks.

[schmidt-sebastian]

@lzl124631x If you have a package-lock.json, you can remove the dependency from "package.json" one it is in the lockfile.

[lzl124631x]

@schmidt-sebastian ic. Thanks!

[glawson]

I found @grpc/grpc-js@0.5.3 in firebase-admin:

functions@ 
├─┬ @google-cloud/pubsub@1.0.0
│ ├── @grpc/grpc-js@0.5.2  deduped
│ └─┬ google-gax@1.6.1
│   └── @grpc/grpc-js@0.5.2  deduped
├── @grpc/grpc-js@0.5.2 
└─┬ firebase-admin@8.5.0
  └─┬ @google-cloud/firestore@2.3.0
    └─┬ google-gax@1.5.2
      └── @grpc/grpc-js@0.5.3 

Upgrading to firebase-admin@8.6.0 fixed it

functions
├─┬ @google-cloud/pubsub@1.0.0
│ ├── @grpc/grpc-js@0.5.2  deduped
│ └─┬ google-gax@1.6.1
│   └── @grpc/grpc-js@0.5.2  deduped
└── @grpc/grpc-js@0.5.2 

[jakeleventhal]

I'm still experiencing a memory leak potentially related to this. The following is from my yarn.lock:

"@grpc/grpc-js@^0.5.2":
  version "0.5.2"
  resolved "https://registry.yarnpkg.com/@grpc/grpc-js/-/grpc-js-0.5.2.tgz#8e39876033749e1611fe9fa181d9535077805abe"
  integrity sha512-NE1tP/1AF6BqhLdILElnF7aOBfoky+4ZOdZU/0NmKo2d+9F9QD8zGoElpBk/5BfyQZ3u1Zs+wFbDOFpVUzDx1w==
  dependencies:
    semver "^6.0.0"

"@grpc/proto-loader@^0.5.0", "@grpc/proto-loader@^0.5.1":
  version "0.5.1"
  resolved "https://registry.yarnpkg.com/@grpc/proto-loader/-/proto-loader-0.5.1.tgz#48492b53cdda353110b51a4b02f465974729c76f"
  integrity sha512-3y0FhacYAwWvyXshH18eDkUI40wT/uGio7MAegzY8lO5+wVsc19+1A7T0pPptae4kl7bdITL+0cHpnAPmryBjQ==
  dependencies:
    lodash.camelcase "^4.3.0"
    protobufjs "^6.8.6"

I'm not actually seeing the error message described previously (MaxListenersExceededWarning), however, the memory usage on my application slowly and steady is increasing. I've taken several heap snapshots from local tests over the course of several hours and when comparing snapshots from a few hours apart, I notice that the top culprits for memory allocations are all related to grpc.

Here you can clearly see that the top 4 culprits for the memory delta between snapshots 12 and 4 are vastly more than everything else

Here are the contents of each from largest to smallest:

1. (string): This by far is the fastest growing constructor. As you can see, there are 920k new allocations in the comparison between the two snapshots. Practically every single string here is ""(function anonymous( ) { return function BeginTransactionRequest(p){ if(p)for(var ks=Object.keys(p),i=0;i<ks.length;++i)if(p[ks[i]]!=null) this[ks[i]]=p[ks[i]] } })". And this all comes from message.js:13. This is a a file from the package protobufjs which is a dependency of grpc.

2. (system): Essentially everything here seems to be coming from from the same message.js:13.

3. (array): I can't pin down consistent allocation here but basically everything here seems to be tied to grpc

4. Array: There are 235k of these and they all look the same - Array with an alloc size of 32 with some connection to grpc

[jakeleventhal]

I referenced this issue in this new issue
#768

It seems almost certainly related so you might want to check it out