Deadline exceeding when saving updates

[jakeleventhal]

Environment details

• OS: Linux b8b01391ee38 4.9.125-linuxkit Fix export documentation. #1 SMP Fri Sep 7 08:20:28 UTC 2018 x86_64 GNU/Linux (this is from the node:latest docker image)
• Node.js version: v12.9.0
• @google-cloud/firestore version: 2.2.8

Steps to reproduce

I have a function that iterates through a file and updates documents with the corresponding ids.
the updates are nothing complicated - im just doing:
await firestore.doc('some path').update(some small 2-3 line payload)
and i get the following error

Error: Deadline exceeded
    at Http2CallStream.<anonymous> (/api/node_modules/@grpc/grpc-js/build/src/client.js:96:45)
    at Http2CallStream.emit (events.js:214:15)
    at /api/node_modules/@grpc/grpc-js/build/src/call-stream.js:71:22
    at processTicksAndRejections (internal/process/task_queues.js:75:11)
    at runNextTicks (internal/process/task_queues.js:62:3)
    at listOnTimeout (internal/timers.js:501:9)
    at processTimers (internal/timers.js:475:7)

I can't get it to reliably reproduce. It just happens sometimes. And it isn't a network issue because this is happening on a container on GCP.

Within a second after I get this error that is fatal and restarts the server. This has happened several times (all following the Deadline exceeded error):

/usr/local/bin/node[33]: ../src/node_http2.cc:892:ssize_t node::http2::Http2Session::ConsumeHTTP2Data(): Assertion `(flags_ & SESSION_STATE_READING_STOPPED) != (0)' failed.
1: 0x9bcac0 node::Abort() [/usr/local/bin/node]
2: 0x9bcb47  [/usr/local/bin/node]
3: 0x9f274a node::http2::Http2Session::ConsumeHTTP2Data() [/usr/local/bin/node]
4: 0x9f3060 node::http2::Http2Session::OnStreamRead(long, uv_buf_t const&) [/usr/local/bin/node]
5: 0xad8e9b node::TLSWrap::ClearOut() [/usr/local/bin/node]
6: 0xadb2f8 node::TLSWrap::OnStreamRead(long, uv_buf_t const&) [/usr/local/bin/node]
7: 0xa71ab6 node::LibuvStreamWrap::OnUvRead(long, uv_buf_t const*) [/usr/local/bin/node]
8: 0x12bb2c9  [/usr/local/bin/node]
9: 0x12bb8f0  [/usr/local/bin/node]
10: 0x12c1428  [/usr/local/bin/node]
11: 0x12afd6b uv_run [/usr/local/bin/node]
12: 0xa002c7 node::NodeMainInstance::Run() [/usr/local/bin/node]
13: 0x993cd8 node::Start(int, char**) [/usr/local/bin/node]
14: 0x7fb91a4432e1 __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
15: 0x932bf5  [/usr/local/bin/node]

which gets immediately followed by:

Aborted (core dumped)
npm ERR! code ELIFECYCLE
npm ERR! errno 134
npm ERR! Exit status 134

[schmidt-sebastian]

@jakeleventhal Hmmm. That looks pretty strange. The stacktrace of the crash is vanilla HTTP2, which is built into Node (and our transport layer). I will follow along on the issue you filed and see if there is anything else we can do. Thank you!

[sambecker]

Same here. This all seems related to the general destabilization seen on firebase firestore/functions over the last month. Seems like you either see things like deadline error using firebase admin 7 or arbitrary onCreate/onUpdate flakiness/crashes using firebase admin 8. The common thread seems to be that error reports have generic node/http stacktraces, something I hadn’t seen before August. Is there anyone working on firebase who has a high level perspective on why the service is degrading?

[limenote135]

I got a similar error with firebase-admin v8. It may only happen in the proxy environment.
firebase-admin v7.4.0 (using firestore v1.3.0) works properly, but firebase-admin v8.0.0 (using firestore v2.0.0) or later does not.

following is my code and logs:

var admin = require("firebase-admin");
var serviceAccount = require("path-to-json");
(async () => {
    admin.initializeApp({
        credential: admin.credential.cert(serviceAccount),
        databaseURL: "database url"
    });

    admin.firestore.setLogFunction((log) => {
        console.log(log);
    });
    console.log("Start");
    const db = admin.firestore();
    let docRef = db.collection('users').doc('alovelace');
    await docRef.set({
        first: 'Ada',
        last: 'Lovelace',
        born: 1815
    });
    console.log("End"); // never called
})();

Start
Firestore (2.3.0) 2019-09-13T01:00:59.371Z ##### [Firestore]: Initialized Firestore
Firestore (2.3.0) 2019-09-13T01:00:59.375Z DM6P0 [WriteBatch.commit]: Sending 1 writes
Firestore (2.3.0) 2019-09-13T01:00:59.376Z DM6P0 [ClientPool.acquire]: Creating a new client
Firestore (2.3.0) 2019-09-13T01:00:59.770Z ##### [Firestore]: Initialized Firestore GAPIC Client
Firestore (2.3.0) 2019-09-13T01:00:59.772Z DM6P0 [Firestore.request]: Sending request: {"database":"projects/testproj/databases/(default)","writes":[{"update":{"name":"projects/testproj/databases/(default)/documents/users/alovelace","fields":{"first":{"stringValue":"Ada"},"last":{"stringValue":"Lovelace"},"born":{"integerValue":1815}}}}]}
Firestore (2.3.0) 2019-09-13T01:01:59.775Z DM6P0 [Firestore.request]: Received error: { Error: Deadline exceeded
    at Http2CallStream.call.on (d:\home\Projects\testproj\node_modules\@grpc\grpc-js\build\src\client.js:96:45)
    at Http2CallStream.emit (events.js:203:15)
    at process.nextTick (d:\home\Projects\testproj\node_modules\@grpc\grpc-js\build\src\call-stream.js:71:22)
    at process._tickCallback (internal/process/next_tick.js:61:11)
  code: 4,
  details: 'Deadline exceeded',
  metadata: Metadata { options: undefined, internalRepr: Map {} } }
Firestore (2.3.0) 2019-09-13T01:01:59.776Z DM6P0 [Firestore._retry]: Request failed with unrecoverable error: { Error: Deadline exceeded
    at Http2CallStream.call.on (d:\home\Projects\testproj\node_modules\@grpc\grpc-js\build\src\client.js:96:45)
    at Http2CallStream.emit (events.js:203:15)
    at process.nextTick (d:\home\Projects\testproj\node_modules\@grpc\grpc-js\build\src\call-stream.js:71:22)
    at process._tickCallback (internal/process/next_tick.js:61:11)
  code: 4,
  details: 'Deadline exceeded',
  metadata: Metadata { options: undefined, internalRepr: Map {} } }
(node:10460) UnhandledPromiseRejectionWarning: Error: Deadline exceeded
    at Http2CallStream.call.on (d:\home\Projects\testproj\node_modules\@grpc\grpc-js\build\src\client.js:96:45)
    at Http2CallStream.emit (events.js:203:15)
    at process.nextTick (d:\home\Projects\testproj\node_modules\@grpc\grpc-js\build\src\call-stream.js:71:22)
    at process._tickCallback (internal/process/next_tick.js:61:11)
(node:10460) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 3)
(node:10460) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

[limenote135]

It might be same as googleapis/nodejs-pubsub#679

[shaibt]

Receiving the same errors and also combined with the one below.
This is constantly happening on all my production servers (GCP) with:
node js 8.15.1
firebase-admin 8.8.0
grpc 0.6.9

(node:23) UnhandledPromiseRejectionWarning: Error [ERR_HTTP2_GOAWAY_SESSION]: New streams cannot be created after receiving a GOAWAY
at ClientHttp2Session.request (internal/http2/core.js:1424:13)
at Subchannel.startCallStream (/app/node_modules/@grpc/grpc-js/build/src/subchannel.js:326:42)
at callStream.filterStack.sendMetadata.then.finalMetadata (/app/node_modules/@grpc/grpc-js/build/src/channel.js:111:51)
at
at process._tickDomainCallback (internal/process/next_tick.js:229:7)

[shaibt]

Update:
Upgraded to new grpc-js 0.6.13 (explicit dependency in package.json) - see this thread.
grpc errors have disappeared (for now).

Update (Edit):
Apparently my explicit requirement of grpc-js 0.6.13 did not work because its parent package (google-gax) had pinned grpc ver 0.6.9 so the actual server code was running 0.6.9 and not 0.6.13. - so my test was no good.

Seems that in the meantime google-gax and @google-cloud/firestore (just yesterday - 3.0.0) packages have been updated to a newer grpc-js. My problem is that I'm under firebase-admin (https://github.com/firebase/firebase-admin-node) and that's still stuck in 2.6.1.

[jakeleventhal]

Is there any update on this?
I'm still experiencing this

[IchordeDionysos]

@schmidt-sebastian I get this error only for some calls, especially when doing a lot of requests at once.
Wouldn't it help to retry at least a couple of times when this error happens to improve the overall reliability of the system?

[criachi]

I am trying to create several records in a database (around 10,000) and each time I run my node script, the firestore database has a few hundred entries which slightly differ each time (a different chunk of the 10,000 records each time) and I get the following log:

[19132]: c:\ws\src\node_http2.cc:893: Assertion (flags_ & SESSION_STATE_READING_STOPPED) != (0)' failed.                                         
1: 00007FF723D9DD8A v8::internal::GCIdleTimeHandler::GCIdleTimeHandler+4506    
2: 00007FF723D78886 node::MakeCallback+4534                                                                                                       
3: 00007FF723D7893F node::MakeCallback+4719       
4: 00007FF723D1CA35 EVP_CIPHER_CTX_get_cipher_data+114517                                                                                         
5: 00007FF723D20BD1 EVP_CIPHER_CTX_get_cipher_data+131313                                                                                         
6: 00007FF723C66D76 DH_get0_q+14022                                                                                                               
7: 00007FF723C64AD8 DH_get0_q+5160                                                                                                                
8: 00007FF723C67D61 DH_get0_q+18097                                                                                                               
9: 00007FF723CC10B1 RSA_meth_get_flags+753                                                                                                       
10: 00007FF723DCE203 uv_tcp_getpeername+1315                                                                                                      
11: 00007FF723DE1457 uv_dlerror+2007                                                                                                              
12: 00007FF723DE23E8 uv_run+232                                                                                                                   
13: 00007FF723D7FE7E node::NewContext+1390                                                                                                        
14: 00007FF723D8048B node::NewIsolate+603                                                                                                         
15: 00007FF723D808E7 node::Start+823                                                                                                              
16: 00007FF723C2F3CC node::MultiIsolatePlatform::MultiIsolatePlatform+604                                                                         
17: 00007FF72487863C v8::internal::compiler::OperationTyper::ToBoolean+129516                                                                     
18: 00007FFECF8E7BD4 BaseThreadInitThunk+20                                                                                                       
19: 00007FFED10CCED1 RtlUserThreadStart+33

[jakeleventhal]

I'm seeing this error over and over with large batch updates (an array of batches)

This is nearly a year old... is there any update here?

[w0nche0l]

I ran into this issue today (exact same error as @criachi), and it stopped happening when I put a 50ms pause between every firestore call, which is pretty annoying to have to reason around. That might be helpful for other folks here.

Would it be possible to at least get an update on whether this as intended or not, @schmidt-sebastian ?

[jakeleventhal]

a 50ms pause seems untenable for larger applications like mine. especially with batch updates as described in my example above. having a batch update limit requires multiple batch updates to be made and it could have thousands of updates. having 50ms updates can grind an application to a halt if there are enough operations

[chrisfischer]

Keep running into this issue when trying to run a script trying to read a few hundred documents from Firestore.

node[88663]: ../src/node_http2.cc:893:ssize_t node::http2::Http2Session::ConsumeHTTP2Data(): Assertion `(flags_ & SESSION_STATE_READING_STOPPED) != (0)' failed.
 1: 0x10003b348 node::Abort() [/usr/local/opt/node@10/bin/node]
 2: 0x10003a440 node::AddEnvironmentCleanupHook(v8::Isolate*, void (*)(void*), void*) [/usr/local/opt/node@10/bin/node]
 3: 0x100076c1a node::http2::Http2Session::ConsumeHTTP2Data() [/usr/local/opt/node@10/bin/node]
 4: 0x100079d9c node::http2::Http2Session::OnStreamRead(long, uv_buf_t const&) [/usr/local/opt/node@10/bin/node]
 5: 0x10011b0ee node::TLSWrap::ClearOut() [/usr/local/opt/node@10/bin/node]
 6: 0x10011cadc node::TLSWrap::OnStreamRead(long, uv_buf_t const&) [/usr/local/opt/node@10/bin/node]
 7: 0x1000da41c node::LibuvStreamWrap::OnUvRead(long, uv_buf_t const*) [/usr/local/opt/node@10/bin/node]
 8: 0x10075b9c4 uv__stream_io [/usr/local/opt/node@10/bin/node]
 9: 0x100763091 uv__io_poll [/usr/local/opt/node@10/bin/node]
10: 0x10075389b uv_run [/usr/local/opt/node@10/bin/node]

[IchordeDionysos]

When I switch to Node 10, the issue disappears

[sambecker]

@IchordeDionysos didn’t realize that Node 10 was available! Have you run into any stability issues? I know Firebase considers it beta.

I also just realized you can set specific timeout/memory configurations on each function:

https://firebase.google.com/docs/functions/manage-functions

Might those options help mitigate deadline exceeded errors @schmidt-sebastian?

[jakeleventhal]

I am and have been running node's official docker image with the :latest tag for a long time and this still persists

[IchordeDionysos]

@sambecker Well, we haven't run into this issue in our Cloud Functions for Firebase environment running on Node 8.
I experience the issue on my MacBook when running Node scripts locally. My colleague on Windows and one other also on macOS, they both don't run into this problem with the exact same script.
I came across the idea of switching to Node 10 because of some hint in one of the many issues over at https://github.com/nodejs/node.

So when I switched the node version using nvm, I haven't had the problem anymore.
I can't make any promises if this will also work for you...

Additional hint, we use yarn as a package manager.

[criachi]

I also added pauses and now all the records I need are being added.

[ckip]

This has been solved in Node 8.16.2, 10.17.0 and 12.11.0

[jjaburke91]

Upgrading my Node version to 10.17.0 (from 10.16.3) solved this issue for me too.

[sambecker]

Upgrading to Node 10 (beta) from Node 8 on Firebase functions seemed to have helped me too!

[anasanzari]

Happening with us too.
Docker image: node:10.16.3-alpine
firebase-admin@8.13.0

[IchordeDionysos]

@anasanzari did you try to update to Node 10.17.0?

This has been solved in Node 8.16.2, 10.17.0 and 12.11.0

[schmidt-sebastian]

I am going to close this issue for now since it seems to be resolved in newer Node versions. If this issue re-appears, we can re-open this issue.