firebase / firebase-tools

The Firebase Command Line Tools
MIT License
3.98k stars 917 forks source link

Firestore emulator v1.14.1 regression: Unknown error returned on transaction.GetAll with an empty list of refs #4473

Open dgpc opened 2 years ago

dgpc commented 2 years ago

[REQUIRED] Environment info

firebase-tools:

firebase-tools 10.7.1 / emulator v1.14.3 fails firebase-tools 10.5.0 / emulator v1.14.1 fails

firebase-tools 10.4.2 / emulator v1.13.1 passes

Platform:

Verified on both macOS and Debian Linux

[REQUIRED] Test case

package main

import (
        "context"
        "os"

        "cloud.google.com/go/firestore"
        "github.com/pkg/errors"
)

func check(err error) {
        if err != nil {
                panic(err)
        }
}

func main() {
        ctx := context.Background()

        if os.Getenv("FIRESTORE_EMULATOR_HOST") == "" {
                panic("Not running under the firestore emulator")
        }
        cli, err := firestore.NewClient(ctx, "test")
        check(errors.Wrap(err, "NewClient"))

        refs := []*firestore.DocumentRef{}

        err = cli.RunTransaction(ctx, func(ctx context.Context, tx *firestore.Transaction) error {
                docs, err := tx.GetAll(refs)
                if err != nil {
                        return errors.Wrap(err, "tx.GetAll")
                }
                if len(docs) > 0 {
                        return errors.New("expected to get zero documents")
                }
                return nil
        })
        check(errors.Wrap(err, "RunTransaction"))
}

[REQUIRED] Steps to reproduce

go build -o demo
firebase emulators:exec --project test './demo'

[REQUIRED] Expected behavior

Under firestore emulator v1.13.1 calling GetAll with an empty slice of refs returns a nil error and an empty list of documents, same behavior as the production firestore.

[REQUIRED] Actual behavior

Under firestore emulator v1.14.1 and v1.14.3 (bundled with the latest firebase-tools release) we now get an Unknown RPC error code:

i  Running script: ./demo
panic: RunTransaction: tx.GetAll: rpc error: code = Unknown desc =
...
Error: Script "./demo" exited with code 2

With full debug info:

 firebase --debug emulators:exec --project test './demo'
[2022-04-24T23:06:54.655Z] > command requires scopes: ["email","openid","https://www.googleapis.com/auth/cloudplatformprojects.readonly","https://www.googleapis.com/auth/firebase","https://www.googleapis.com/auth/cloud-platform"]
[2022-04-24T23:06:54.656Z] > authorizing via signed-in user (--REDACTED--)
[2022-04-24T23:06:54.727Z] openjdk version "17.0.2" 2022-01-18

[2022-04-24T23:06:54.727Z] OpenJDK Runtime Environment Homebrew (build 17.0.2+0)
OpenJDK 64-Bit Server VM Homebrew (build 17.0.2+0, mixed mode, sharing)

[2022-04-24T23:06:54.729Z] Parsed Java major version: 17
i  emulators: Starting emulators: firestore {"metadata":{"emulator":{"name":"hub"},"message":"Starting emulators: firestore"}}
[2022-04-24T23:06:54.750Z] [hub] writing locator at /var/folders/97/mchvl9w11rnbzpvfgw2j5ktm0000gn/T/hub-test.json
⚠  firestore: Did not find a Cloud Firestore rules file specified in a firebase.json config file. {"metadata":{"emulator":{"name":"firestore"},"message":"Did not find a Cloud Firestore rules file specified in a firebase.json config file."}}
⚠  firestore: The emulator will default to allowing all reads and writes. Learn more about this option: https://firebase.google.com/docs/emulator-suite/install_and_configure#security_rules_configuration. {"metadata":{"emulator":{"name":"firestore"},"message":"The emulator will default to allowing all reads and writes. Learn more about this option: https://firebase.google.com/docs/emulator-suite/install_and_configure#security_rules_configuration."}}
[2022-04-24T23:06:54.754Z] Ignoring unsupported arg: projectId {"metadata":{"emulator":{"name":"firestore"},"message":"Ignoring unsupported arg: projectId"}}
[2022-04-24T23:06:54.754Z] Ignoring unsupported arg: auto_download {"metadata":{"emulator":{"name":"firestore"},"message":"Ignoring unsupported arg: auto_download"}}
[2022-04-24T23:06:54.754Z] Starting Firestore Emulator with command {"binary":"java","args":["-Dgoogle.cloud_firestore.debug_log_level=FINE","-Duser.language=en","-jar","/Users/dgc/.cache/firebase/emulators/cloud-firestore-emulator-v1.14.1.jar","--host","localhost","--port",8083],"optionalArgs":["port","webchannel_port","host","rules","functions_emulator","seed_from_export"],"joinArgs":false} {"metadata":{"emulator":{"name":"firestore"},"message":"Starting Firestore Emulator with command {\"binary\":\"java\",\"args\":[\"-Dgoogle.cloud_firestore.debug_log_level=FINE\",\"-Duser.language=en\",\"-jar\",\"/Users/dgc/.cache/firebase/emulators/cloud-firestore-emulator-v1.14.1.jar\",\"--host\",\"localhost\",\"--port\",8083],\"optionalArgs\":[\"port\",\"webchannel_port\",\"host\",\"rules\",\"functions_emulator\",\"seed_from_export\"],\"joinArgs\":false}"}}
i  firestore: Firestore Emulator logging to firestore-debug.log {"metadata":{"emulator":{"name":"firestore"},"message":"Firestore Emulator logging to \u001b[1mfirestore-debug.log\u001b[22m"}}
[2022-04-24T23:06:55.247Z] Apr 24, 2022 4:06:55 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start
INFO: Started WebSocket server on ws://localhost:56864
 {"metadata":{"emulator":{"name":"firestore"},"message":"Apr 24, 2022 4:06:55 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start\nINFO: Started WebSocket server on ws://localhost:56864\n"}}
[2022-04-24T23:06:55.257Z] API endpoint: http:// {"metadata":{"emulator":{"name":"firestore"},"message":"API endpoint: http://"}}
[2022-04-24T23:06:55.257Z] localhost:8083
If you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:

   export FIRESTORE_EMULATOR_HOST=localhost:8083

Dev App Server is now running.

 {"metadata":{"emulator":{"name":"firestore"},"message":"localhost:8083\nIf you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:\n\n   export FIRESTORE_EMULATOR_HOST=localhost:8083\n\nDev App Server is now running.\n\n"}}
i  Running script: ./demo
[2022-04-24T23:06:55.266Z] Running ./demo with environment {"TERM_SESSION_ID":"w0t0p0:CC3A0B6E-323A-4ABF-B2AA-834B4CD7DA3B","SSH_AUTH_SOCK":"/Users/dgc/Library/Containers/com.maxgoedjen.Secretive.SecretAgent/Data/socket.ssh","LC_TERMINAL_VERSION":"3.4.15","COLORFGBG":"7;0","ITERM_PROFILE":"Default","XPC_FLAGS":"0x0","LANG":"en_US.UTF-8","PWD":"--REDACTED--/cmd/demo","SHELL":"/bin/zsh","__CFBundleIdentifier":"com.googlecode.iterm2","SECURITYSESSIONID":"186b7","TERM_PROGRAM_VERSION":"3.4.15","TERM_PROGRAM":"iTerm.app","PATH":"/opt/homebrew/opt/node@14/bin:/Users/dgc/go/bin:/opt/homebrew/opt/openjdk/bin:/opt/homebrew/Caskroom/google-cloud-sdk/latest/google-cloud-sdk/bin:/opt/homebrew/bin:/opt/homebrew/sbin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:/opt/homebrew/opt/fzf/bin","LC_TERMINAL":"iTerm2","COLORTERM":"truecolor","COMMAND_MODE":"unix2003","TERM":"xterm-256color","HOME":"/Users/dgc","TMPDIR":"/var/folders/97/mchvl9w11rnbzpvfgw2j5ktm0000gn/T/","USER":"dgc","XPC_SERVICE_NAME":"0","LOGNAME":"dgc","LaunchInstanceID":"E33E5CCF-3AD5-4C1E-A528-49CF71A04880","__CF_USER_TEXT_ENCODING":"0x1F5:0x0:0x0","ITERM_SESSION_ID":"w0t0p0:CC3A0B6E-323A-4ABF-B2AA-834B4CD7DA3B","SHLVL":"1","OLDPWD":"--REDACTED--","HOMEBREW_PREFIX":"/opt/homebrew","HOMEBREW_CELLAR":"/opt/homebrew/Cellar","HOMEBREW_REPOSITORY":"/opt/homebrew","MANPATH":"/opt/homebrew/share/man::","INFOPATH":"/opt/homebrew/share/info:","PS1":"%n@%m %1~ $(parse_git_branch)%# ","_":"/opt/homebrew/bin/firebase","DEBUG":"true","IS_FIREBASE_CLI":"true","GCLOUD_PROJECT":"test","FIRESTORE_EMULATOR_HOST":"localhost:8083","FIREBASE_FIRESTORE_EMULATOR_ADDRESS":"localhost:8083","FIREBASE_EMULATOR_HUB":"localhost:4400"}
[2022-04-24T23:06:55.312Z] Apr 24, 2022 4:06:55 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Apr 24, 2022 4:06:55 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected HTTP/2 connection.\n"}}
[2022-04-24T23:06:55.592Z] Apr 24, 2022 4:06:55 PM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError
INFO: operation failed: No value present
java.util.NoSuchElementException: No value present
        at java.base/java.util.Optional.get(Optional.java:143)
        at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.transactionalRead(CloudFirestoreV1.java:1030)
        at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.lambda$read$26(CloudFirestoreV1.java:1016)
        at com.google.cloud.datastore.emulator.impl.transactions.EmulatorTransactionManager$ReadWriteTransaction.fold(EmulatorTransactionManager.java:356)
        at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.read(CloudFirestoreV1.java:1014)
        at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.batchGetDocuments(CloudFirestoreV1.java:397)
        at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1Router.batchGetDocuments(CloudFirestoreV1Router.java:126)
        at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter$1.lambda$batchGetDocuments$6(FirestoreV1GrpcAdapter.java:146)
        at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter.streaming(FirestoreV1GrpcAdapter.java:79)
        at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter.access$100(FirestoreV1GrpcAdapter.java:41)
        at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter$1.batchGetDocuments(FirestoreV1GrpcAdapter.java:146)
        at com.google.firestore.v1.FirestoreGrpc$MethodHandlers.invoke(FirestoreGrpc.java:1278)
        at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
        at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
        at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
        at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
        at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
        at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
        at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
        at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
        at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
        at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:340)
        at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:866)
        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)

 {"metadata":{"emulator":{"name":"firestore"},"message":"Apr 24, 2022 4:06:55 PM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError\nINFO: operation failed: No value present\njava.util.NoSuchElementException: No value present\n\tat java.base/java.util.Optional.get(Optional.java:143)\n\tat com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.transactionalRead(CloudFirestoreV1.java:1030)\n\tat com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.lambda$read$26(CloudFirestoreV1.java:1016)\n\tat com.google.cloud.datastore.emulator.impl.transactions.EmulatorTransactionManager$ReadWriteTransaction.fold(EmulatorTransactionManager.java:356)\n\tat com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.read(CloudFirestoreV1.java:1014)\n\tat com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.batchGetDocuments(CloudFirestoreV1.java:397)\n\tat com.google.cloud.datastore.emulator.impl.CloudFirestoreV1Router.batchGetDocuments(CloudFirestoreV1Router.java:126)\n\tat com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter$1.lambda$batchGetDocuments$6(FirestoreV1GrpcAdapter.java:146)\n\tat com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter.streaming(FirestoreV1GrpcAdapter.java:79)\n\tat com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter.access$100(FirestoreV1GrpcAdapter.java:41)\n\tat com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter$1.batchGetDocuments(FirestoreV1GrpcAdapter.java:146)\n\tat com.google.firestore.v1.FirestoreGrpc$MethodHandlers.invoke(FirestoreGrpc.java:1278)\n\tat io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)\n\tat io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)\n\tat io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)\n\tat io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)\n\tat io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)\n\tat io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)\n\tat io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)\n\tat io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)\n\tat io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)\n\tat io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:340)\n\tat io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:866)\n\tat io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)\n\tat io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n\tat java.base/java.lang.Thread.run(Thread.java:833)\n\n"}}
panic: RunTransaction: tx.GetAll: rpc error: code = Unknown desc =

goroutine 1 [running]:
main.check(...)
        --REDACTED--/demo/main.go:13
main.main()
       --REDACTED--/demo/main.go:38 +0x100
⚠  Script exited unsuccessfully (code 2)
i  emulators: Shutting down emulators. {"metadata":{"emulator":{"name":"hub"},"message":"Shutting down emulators."}}
i  firestore: Stopping Firestore Emulator {"metadata":{"emulator":{"name":"firestore"},"message":"Stopping Firestore Emulator"}}
[2022-04-24T23:06:56.111Z] *** shutting down gRPC server since JVM is shutting down
 {"metadata":{"emulator":{"name":"firestore"},"message":"*** shutting down gRPC server since JVM is shutting down\n"}}
[2022-04-24T23:06:56.124Z] *** server shut down
 {"metadata":{"emulator":{"name":"firestore"},"message":"*** server shut down\n"}}
i  hub: Stopping emulator hub {"metadata":{"emulator":{"name":"hub"},"message":"Stopping emulator hub"}}

Error: Script "./demo" exited with code 2

Having trouble? Try again or contact support with contents of firebase-debug.log
joehan commented 2 years ago

@yuchenshi I think you aren;t the right person for this but probably know who is. Could you pass this along to the firestore team?

dereekb commented 2 years ago

I am also seeing similar regressions dealing with transactions. firebase-tools 10.4.2 / emulator v1.13.1 is the latest version I can use for now.

FWIW here's one of the test runs where some tests fail due to "Transaction is invalid or closed." related errors:

/code/node_modules/@grpc/grpc-js/build/src/call.js:31
    return Object.assign(new Error(message), status);
                         ^

Error: 3 INVALID_ARGUMENT: Transaction is invalid or closed.
    at Object.callErrorFromStatus (/code/node_modules/@grpc/grpc-js/src/call.ts:81:24)
    at Object.onReceiveStatus (/code/node_modules/@grpc/grpc-js/src/client.ts:577:32)
    at Object.onReceiveStatus (/code/node_modules/@grpc/grpc-js/src/client-interceptors.ts:424:48)
    at /code/node_modules/@grpc/grpc-js/src/call-stream.ts:323:24
    at processTicksAndRejections (node:internal/process/task_queues:78:11) {
  code: 3,
  details: 'Transaction is invalid or closed.',
  metadata: Metadata {
    internalRepr: Map(1) { 'content-type' => [ 'application/grpc' ] },
    options: {}
  }
}

https://app.circleci.com/pipelines/github/dereekb/dbx-components/361/workflows/987ab855-a600-4c59-ae8f-32b96c40d561/jobs/756/steps

Here's some firestore-debug.log outputs for a stacktrace one of those tests.

May 07, 2022 7:31:23 AM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError
INFO: operation failed: Can't swap from CLOSED to ACTIVE.
com.google.cloud.datastore.core.exception.DatastoreException: Can't swap from CLOSED to ACTIVE.
    at com.google.cloud.datastore.emulator.impl.transactions.EmulatorTransactionManager.toActive(EmulatorTransactionManager.java:454)
    at com.google.cloud.datastore.emulator.impl.storage.FlatLocalEntityStore$StronglyConsistentReadView.<init>(FlatLocalEntityStore.java:94)
    at com.google.cloud.datastore.emulator.impl.storage.FlatLocalEntityStore$StronglyConsistentReadView.<init>(FlatLocalEntityStore.java:98)
    at com.google.cloud.datastore.emulator.impl.storage.FlatLocalEntityStore.read(FlatLocalEntityStore.java:62)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.transactionalRead(CloudFirestoreV1.java:1026)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.lambda$read$26(CloudFirestoreV1.java:1016)
    at com.google.cloud.datastore.emulator.impl.transactions.EmulatorTransactionManager$ReadWriteTransaction.fold(EmulatorTransactionManager.java:359)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.read(CloudFirestoreV1.java:1014)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.batchGetDocuments(CloudFirestoreV1.java:397)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1Router.batchGetDocuments(CloudFirestoreV1Router.java:125)
    at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter$1.lambda$batchGetDocuments$6(FirestoreV1GrpcAdapter.java:146)
    at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter.streaming(FirestoreV1GrpcAdapter.java:79)
    at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter.access$100(FirestoreV1GrpcAdapter.java:41)
    at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter$1.batchGetDocuments(FirestoreV1GrpcAdapter.java:146)
    at com.google.firestore.v1.FirestoreGrpc$MethodHandlers.invoke(FirestoreGrpc.java:1278)
    at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
    at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:340)
    at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:866)
    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:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)
May 07, 2022 7:35:57 AM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError
INFO: operation failed: Transaction is invalid or closed.
com.google.cloud.datastore.core.exception.DatastoreException: Transaction is invalid or closed.
    at com.google.cloud.datastore.emulator.impl.transactions.EmulatorTransactionManager.reuseExisting(EmulatorTransactionManager.java:207)
    at com.google.cloud.datastore.emulator.impl.transactions.EmulatorTransactionManager.create(EmulatorTransactionManager.java:109)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.batchGetDocuments(CloudFirestoreV1.java:394)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1Router.batchGetDocuments(CloudFirestoreV1Router.java:125)
    at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter$1.lambda$batchGetDocuments$6(FirestoreV1GrpcAdapter.java:146)
    at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter.streaming(FirestoreV1GrpcAdapter.java:79)
    at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter.access$100(FirestoreV1GrpcAdapter.java:41)
    at com.google.cloud.datastore.emulator.firestore.v1.FirestoreV1GrpcAdapter$1.batchGetDocuments(FirestoreV1GrpcAdapter.java:146)
    at com.google.firestore.v1.FirestoreGrpc$MethodHandlers.invoke(FirestoreGrpc.java:1278)
    at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
    at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:340)
    at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:866)
    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:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)

I ran into this earlier when firebase-tools 10.5.0 / emulator v1.14.1 was released and figured out it was probably more related to the emulator rather than firebase-tools. Emulator v1.14.1 had more transactional timeout related issues in my tests.

dereekb commented 2 years ago

This is probably enough for a separate report, but:

I'm guessing the way the emulator communicated via grpc changed which caused some timings in promises to change. I fixed most of the tests, but there's still one that seems to have a weird race condition left related to terminating a '@google-cloud/firestore' Firestore instance after the tests end.

It causes this relatively simple test to "sometimes" fail:

it('should create a new document accessor instance that uses the passed transaction context.', async () => {
  let ref: DocumentReference<MockItem>;

  await firestore.runTransaction(async (transaction: Transaction) => {
    const documentAccessor = firestoreCollection.documentAccessorForTransaction(transaction);

    const document = documentAccessor.newDocument();
    ref = document.documentRef as DocumentReference<MockItem>;

    await document.accessor.set({ test: true });
  });

  expect(ref!).toBeDefined();

  const loadedDoc = firestoreCollection.documentAccessor().loadDocument(ref!);
  const loadedData: DocumentSnapshot<MockItem> = await loadedDoc.accessor.get() as DocumentSnapshot<MockItem>;

  expect(loadedData).toBeDefined();
  expect(loadedData.data()).toBeDefined();
  expect(loadedData.data()?.test).toBe(true);
});

The following setup/teardown code is also executed before/after the test:

  setupInstance: async (config) => {
    const drivers = makeTestingFirestoreDrivers(googleCloudFirestoreDrivers());

    const projectId = 'firebase-server-test-' + new Date().getTime();
    const firestore = new Firestore({
      projectId,
      host: config.host,
      port: config.port,
      maxIdleChannels: 0
    });

    return new GoogleCloudTestFirestoreInstance(drivers, firestore);
  },
  teardownInstance: async (instance, config) => {
    await (instance.firestore as Firestore).terminate();
  }

Here is the error that is popping up and sometimes causing the tests to fail:

/code/node_modules/@grpc/grpc-js/build/src/call.js:31
    return Object.assign(new Error(message), status);
                         ^

Error: 3 INVALID_ARGUMENT: Transaction is invalid or closed.
    at Object.callErrorFromStatus (/code/node_modules/@grpc/grpc-js/src/call.ts:81:24)
    at Object.onReceiveStatus (/code/node_modules/@grpc/grpc-js/src/client.ts:577:32)
    at Object.onReceiveStatus (/code/node_modules/@grpc/grpc-js/src/client-interceptors.ts:424:48)
    at /code/node_modules/@grpc/grpc-js/src/call-stream.ts:323:24
    at processTicksAndRejections (node:internal/process/task_queues:78:11) {
  code: 3,
  details: 'Transaction is invalid or closed.',
  metadata: Metadata {
    internalRepr: Map(1) { 'content-type' => [ 'application/grpc' ] },
    options: {}
  }
}

However, this happens inconsistently. Sometimes the tests passes without this occurring, other times it fails.

  ● FirestoreCollection › documentAccessor() › should create a new document accessor instance that uses the passed batch context.

    3 INVALID_ARGUMENT: Transaction is invalid or closed.

      at Object.callErrorFromStatus (../../node_modules/@grpc/grpc-js/src/call.ts:81:24)
      at Object.onReceiveStatus (../../node_modules/@grpc/grpc-js/src/client.ts:577:32)
      at Object.onReceiveStatus (../../node_modules/@grpc/grpc-js/src/client-interceptors.ts:424:48)
      at ../../node_modules/@grpc/grpc-js/src/call-stream.ts:323:24

https://app.circleci.com/pipelines/github/dereekb/dbx-components/363/workflows/d142478c-dec5-4046-9a07-23c5c4ca98c9/jobs/761/parallel-runs/0/steps/0-106

Removing the teardown code helps the transaction test above, but other issues seem to pop up. These issues don't occur in firebase-tools 10.4.2 / emulator v1.13.1.

It seems like there are promises internally that are resolving too early or resolving inconsistently, potentially as a result of transaction changes in the emulator.

EDIT

I ran across a random post somewhere saying you have to perform a read and a write for a transaction. In retrospect that makes sense. After updating those effected tests they pass properly now.

https://github.com/dereekb/dbx-components/commit/2d448c5c3deea8feb82180c5aeaedb2fdf9a105a

Ignore my post, unless you hand similar issues, in which case I'd tell you to double check that you're using transactions/write batches correctly.