GRPC errors intermittently cause firebase client to fail

[Hoppi164]

[REQUIRED] Describe your environment

• Operating System version: MAC OS Montery 12.4
• Browser version: Node 16.16.0
• Firebase SDK version: 9.12.1
• Firebase Product: Firestore

[REQUIRED] Describe the problem

Our application is experiencing problems with firebase getDocs() never responding, and random grpc connection error messages when writing documents.

At my workplace we were experiencing several issues.
Our application has a lot of reads and writes going on, so i created a test script to simulate this environment without any of our proprietary code; and i was able to semi-reliably replicate the exact error codes we are experiencing.

Steps to reproduce:

• Create a test.js file with the following code
• Update the config with your own values
• Start your own firebase emulator suite
• run node test.js
  • This will iteratively create a bunch of users and read a bunch of users, basically doing a stress test.
  • This SHOULD throw a bunch of GRPC errors, and then throw a custom error of get timeout - read took over 5 seconds
  • Run the test a few times, rarely it will happily work, but most times it repeatably throws the errors

Relevant Code:

const { initializeApp } = require("firebase/app");
const { getFirestore, collection, getDocs, addDoc, doc, deleteDoc, connectFirestoreEmulator } = require('firebase/firestore');

const config = {
    "firestoreEmulatorPort": 9098,
    "firebase": {
      "apiKey": "<<insert>>",
      "projectId": "<<insert>>",
      "appId": "<<insert>>",
    }
}

const app = initializeApp(config.firebase);
const db = getFirestore(app);
connectFirestoreEmulator(db, 'localhost', config.firestoreEmulatorPort);


function timeoutReject (timeMs, message) {
    return new Promise((resolve, reject) => setTimeout(() => reject(new Error(message)), timeMs));
}

async function run (batchIndex, runIndex) {

    // Add user to db
    console.time(`write ${batchIndex}-${runIndex}`)
    const writeDocs = addDoc(collection(db, "users"), {
        first: "Ada",
        last: "Lovelace",
        born: 1815
    });
    writeDocs.catch(error => { console.error('error writing user', error, batchIndex)})
    const user = await writeDocs
    console.timeEnd(`write ${batchIndex}-${runIndex}`)

    // Get all users
    console.time(`read ${batchIndex}-${runIndex}`)
    const query = getDocs(collection(db, "users"));
    query.catch(error => { console.error('error resolving promise', error, batchIndex); });
    const allUsers = await Promise.race([
        query,
        timeoutReject(5000, `Get Timeout - Reading took over 5 seconds ${batchIndex}`)
    ])
    console.log(`read success - ${allUsers.size}`)
    console.timeEnd(`read ${batchIndex}-${runIndex}`)

}

// Run stress test
async function runTest() {
   
    // Run twenty batches
    for (let batchIndex = 0; batchIndex < 20; batchIndex++) {

        // In each batch, do 50 "test runs"
        const runs = new Array(50).fill(null).map( (value, runIndex) => {
            return run(batchIndex, runIndex)
        })
        await Promise.all(runs)

    }
    console.log('stress test complete')
    process.exit()
}

runTest();

Example Errors

[Hoppi164]

Update: This only seems to throw an error when connected to the emulator suite, not when connected to a production firestore database.

[dconeybe]

Thanks for the report. I've reproduced the issue and I'll investigate. I also saw, as you noted, that this only seems to be problematic when using the Firestore Emulator; using production seems to work fine.

[dconeybe]

@Hoppi164 I just wanted to let you know that I haven't forgotten about this issue. Other priorities prevented me from making much progress since I reproduced the bug. I'm not sure when exactly, but I will get to it! Thank you for your patience.

[dconeybe]

This could have the same root cause as firebase/firebase-tools#5197.

[Hoppi164]

Hi Denver.
No problem, i understand these things can take time to debug.

I appreciate your hard work on figuring this out.

I had a look at the other issue you linked but I'm not sure how these two could be related.

I'm not fully versed on your architecture, but it seems we're getting totally different error messages and that we're doing different things..

[dconeybe]

@Hoppi164 The common thread between this issue and firebase/firebase-tools#5197 is that they both regard problems in the Firestore emulator when it is under heavy load. In this issue, it seems that the Firestore emulator is sending back corrupted data and in the other issue it looks like the Firestore emulator is losing its network connection. On the surface, they could be different symptoms of the same problem.

Could you reproduce the issue, and this time attach the firestore-debug.log created by the Firestore emulator?

[Hoppi164]

Hi Denver,

Please see below.

Test Terminal Output:

andrew@Andrewss-MBP client % node test.js
write 0-0: 1.665s
write 0-1: 1.704s
read success - 50
read 0-0: 162.778ms
read success - 50
read 0-1: 126.113ms
write 0-2: 1.836s
write 0-3: 1.849s
[2022-11-16T07:31:06.866Z]  @firebase/firestore: Firestore (9.13.0): Connection GRPC stream error. Code: 13 Message: 13 INTERNAL: Response message parsing error: index out of range: 175 + 10 > 175
write 0-4: 1.876s
write 0-5: 1.885s
[2022-11-16T07:31:06.898Z]  @firebase/firestore: Firestore (9.13.0): Connection GRPC stream error. Code: 13 Message: 13 INTERNAL: Response message parsing error: invalid wire type 4 at offset 9
write 0-6: 1.910s
write 0-7: 1.940s
read success - 50
read 0-2: 107.303ms
read success - 50
read 0-3: 94.829ms
read success - 50
read 0-4: 68.127ms
read success - 50
read 0-5: 60.314ms
read success - 50
read 0-6: 36.294ms
read success - 50
read 0-7: 10.626ms
write 0-8: 1.969s
[2022-11-16T07:31:06.984Z]  @firebase/firestore: Firestore (9.13.0): Connection GRPC stream error. Code: 13 Message: 13 INTERNAL: Response message parsing error: index out of range: 28 + 18 > 34
write 0-9: 1.999s
[2022-11-16T07:31:07.012Z]  @firebase/firestore: Firestore (9.13.0): Connection GRPC stream error. Code: 13 Message: 13 INTERNAL: Response message parsing error: invalid wire type 7 at offset 7
write 0-10: 2.023s
[2022-11-16T07:31:07.040Z]  @firebase/firestore: Firestore (9.13.0): FIRESTORE (9.13.0) INTERNAL ASSERTION FAILED: Unexpected state
/Users/andrew/Documents/app/client/node_modules/@firebase/firestore/dist/index.node.cjs.js:242
    throw new Error(message);
          ^

Error: FIRESTORE (9.13.0) INTERNAL ASSERTION FAILED: Unexpected state
    at fail (/Users/andrew/Documents/app/client/node_modules/@firebase/firestore/dist/index.node.cjs.js:242:11)
    at fromWatchChange (/Users/andrew/Documents/app/client/node_modules/@firebase/firestore/dist/index.node.cjs.js:8498:16)
    at PersistentListenStream.onMessage (/Users/andrew/Documents/app/client/node_modules/@firebase/firestore/dist/index.node.cjs.js:21015:29)
    at /Users/andrew/Documents/app/client/node_modules/@firebase/firestore/dist/index.node.cjs.js:20956:29
    at /Users/andrew/Documents/app/client/node_modules/@firebase/firestore/dist/index.node.cjs.js:20987:28
    at /Users/andrew/Documents/app/client/node_modules/@firebase/firestore/dist/index.node.cjs.js:26250:13
    at /Users/andrew/Documents/app/client/node_modules/@firebase/firestore/dist/index.node.cjs.js:26298:20
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
andrew@Andrewss-MBP client %

Firestore-Debug.log

Nov 16, 2022 5:30:28 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start
INFO: Started WebSocket server on ws://[0.0.0.0:9150](http://0.0.0.0:9150/)
API endpoint: http://0.0.0.0:9078/
If you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:

   export FIRESTORE_EMULATOR_HOST=[0.0.0.0:9078](http://0.0.0.0:9078/)

Dev App Server is now running.

Nov 16, 2022 5:31:05 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
Nov 16, 2022 5:31:05 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
Multiple projectIds are not recommended in single project mode. Requested project ID gritlifeapp-staging, but the emulator is configured for gritlifeapp-test. This warning will become an error in the future. To opt-out of single project mode add/set the '"single_project_mode": false' property in the firebase.json emulators config.
Multiple projectIds are not recommended in single project mode. Requested project ID gritlifeapp-staging, but the emulator is configured for gritlifeapp-test. This warning will become an error in the future. To opt-out of single project mode add/set the '"single_project_mode": false' property in the firebase.json emulators config.
Multiple projectIds are not recommended in single project mode. Requested project ID gritlifeapp-staging, but the emulator is configured for gritlifeapp-test. This warning will become an error in the future. To opt-out of single project mode add/set the '"single_project_mode": false' property in the firebase.json emulators config.
Multiple projectIds are not recommended in single project mode. Requested project ID gritlifeapp-staging, but the emulator is configured for gritlifeapp-test. This warning will become an error in the future. To opt-out of single project mode add/set the '"single_project_mode": false' property in the firebase.json emulators config.
Nov 16, 2022 5:31:06 PM io.grpc.internal.SerializingExecutor run
SEVERE: Exception while executing runnable io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable@ff06602
com.google.cloud.datastore.emulator.impl.util.StreamTransportClosedException: java.lang.IllegalStateException: call is closed
at com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver.onNext(WrappedStreamObserver.java:33)
at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1ListenStream.notifySynced(CloudFirestoreV1ListenStream.java:138)
at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1ListenStream.addTarget(CloudFirestoreV1ListenStream.java:302)
at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1ListenStream.onNext(CloudFirestoreV1ListenStream.java:164)
at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1ListenStream.onNext(CloudFirestoreV1ListenStream.java:57)
at io.grpc.stub.ServerCalls$StreamingServerCallHandler$StreamingServerCallListener.onMessage(ServerCalls.java:262)
at io.grpc.ForwardingServerCallListener.onMessage(ForwardingServerCallListener.java:33)
at io.grpc.Contexts$ContextualizedServerCallListener.onMessage(Contexts.java:76)
at io.grpc.ForwardingServerCallListener.onMessage(ForwardingServerCallListener.java:33)
at io.grpc.Contexts$ContextualizedServerCallListener.onMessage(Contexts.java:76)
at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailableInternal(ServerCallImpl.java:333)
at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailable(ServerCallImpl.java:316)
at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable.runInContext(ServerImpl.java:835)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.IllegalStateException: call is closed
at com.google.common.base.Preconditions.checkState(Preconditions.java:512)
at io.grpc.internal.ServerCallImpl.sendMessageInternal(ServerCallImpl.java:162)
at io.grpc.internal.ServerCallImpl.sendMessage(ServerCallImpl.java:154)
at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onNext(ServerCalls.java:380)
at com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver.onNext(WrappedStreamObserver.java:31)
... 17 more

Multiple projectIds are not recommended in single project mode. Requested project ID gritlifeapp-staging, but the emulator is configured for gritlifeapp-test. This warning will become an error in the future. To opt-out of single project mode add/set the '"single_project_mode": false' property in the firebase.json emulators config.
Nov 16, 2022 5:31:07 PM io.netty.util.ReferenceCountUtil safeRelease
WARNING: Failed to release a message: UnpooledSlicedByteBuf(freed)
io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
at io.netty.util.internal.ReferenceCountUpdater.toLiveRealRefCnt(ReferenceCountUpdater.java:83)
at io.netty.util.internal.ReferenceCountUpdater.release(ReferenceCountUpdater.java:147)
at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:101)
at io.netty.buffer.CompositeByteBuf$Component.free(CompositeByteBuf.java:1959)
at io.netty.buffer.CompositeByteBuf.deallocate(CompositeByteBuf.java:2264)
at io.netty.buffer.AbstractReferenceCountedByteBuf.handleRelease(AbstractReferenceCountedByteBuf.java:111)
at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:101)
at io.netty.buffer.AbstractDerivedByteBuf.release0(AbstractDerivedByteBuf.java:98)
at io.netty.buffer.AbstractDerivedByteBuf.release(AbstractDerivedByteBuf.java:94)
at io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:90)
at io.netty.util.ReferenceCountUtil.safeRelease(ReferenceCountUtil.java:116)
at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:271)
at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352)
at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:438)
at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:931)
at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354)
at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:895)
at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372)
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:742)
at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728)
at io.netty.handler.codec.http2.Http2ConnectionHandler.flush(Http2ConnectionHandler.java:197)
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:742)
at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728)
at io.netty.channel.DefaultChannelPipeline.flush(DefaultChannelPipeline.java:967)
at io.netty.channel.AbstractChannel.flush(AbstractChannel.java:254)
at io.grpc.netty.WriteQueue.flush(WriteQueue.java:147)
at io.grpc.netty.WriteQueue.access$000(WriteQueue.java:34)
at io.grpc.netty.WriteQueue$1.run(WriteQueue.java:46)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:833)

Multiple projectIds are not recommended in single project mode. Requested project ID gritlifeapp-staging, but the emulator is configured for gritlifeapp-test. This warning will become an error in the future. To opt-out of single project mode add/set the '"single_project_mode": false' property in the firebase.json emulators config.
Nov 16, 2022 5:31:07 PM io.grpc.internal.SerializingExecutor run
SEVERE: Exception while executing runnable io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable@242e0af9
com.google.cloud.datastore.emulator.impl.util.StreamTransportClosedException: java.lang.IllegalStateException: call is closed
at com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver.onNext(WrappedStreamObserver.java:33)
at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1ListenStream.notify(CloudFirestoreV1ListenStream.java:117)
at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1ListenStream.addTarget(CloudFirestoreV1ListenStream.java:297)
at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1ListenStream.onNext(CloudFirestoreV1ListenStream.java:164)
at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1ListenStream.onNext(CloudFirestoreV1ListenStream.java:57)
at io.grpc.stub.ServerCalls$StreamingServerCallHandler$StreamingServerCallListener.onMessage(ServerCalls.java:262)
at io.grpc.ForwardingServerCallListener.onMessage(ForwardingServerCallListener.java:33)
at io.grpc.Contexts$ContextualizedServerCallListener.onMessage(Contexts.java:76)
at io.grpc.ForwardingServerCallListener.onMessage(ForwardingServerCallListener.java:33)
at io.grpc.Contexts$ContextualizedServerCallListener.onMessage(Contexts.java:76)
at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailableInternal(ServerCallImpl.java:333)
at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailable(ServerCallImpl.java:316)
at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable.runInContext(ServerImpl.java:835)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.IllegalStateException: call is closed
at com.google.common.base.Preconditions.checkState(Preconditions.java:512)
at io.grpc.internal.ServerCallImpl.sendMessageInternal(ServerCallImpl.java:162)
at io.grpc.internal.ServerCallImpl.sendMessage(ServerCallImpl.java:154)
at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onNext(ServerCalls.java:380)
at com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver.onNext(WrappedStreamObserver.java:31)
... 17 more

Nov 16, 2022 5:31:07 PM io.netty.channel.DefaultChannelPipeline onUnhandledInboundException
WARNING: An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.net.SocketException: Connection reset
at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:258)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:833)

Nov 16, 2022 5:31:27 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketChannelHandler initChannel
INFO: Connected to new websocket client