Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
dgpc opened this issue Apr 24, 2022 · 3 comments

Comments

@dgpc
Copy link

dgpc commented Apr 24, 2022

[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
Copy link
Contributor

joehan commented Apr 25, 2022

@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
Copy link

dereekb commented May 7, 2022

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
Copy link

dereekb commented May 7, 2022

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.

dereekb/dbx-components@2d448c5

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.

@fredzqm fredzqm removed their assignment Jul 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants