Firestore emulator in deadlock in transaction

[vdvleon]

Environment info

firebase-tools: 8.5.0
Platform: macOS
Node: 10.21.0

Test case

When reading/writing to a document using two simultaneous transactions, the transactions hang (as if in a deadlock).

I added some sample code to illustrate the problem (including some console logs to clarify where the code hangs).

firestore-emulator-bug-showcase.zip

Steps to reproduce

After downloading the sample code run:

npm install
firebase emulators:start --only firestore --debug # Assuming to be at version 8.5.0

While the emulator runs, run the following command in a different terminal:

npm run test

Expected behavior

I would expect all tests to run successfully. This means:

• the 'firestore' test runs successfully.
• in the 'lease single' test true is returned.
• in the 'lease multi' test only one of the transaction returns true while the other returns false.

Actual behavior

But actually the 'lease multi' test hangs and times out. The 'firestore' and 'lease single' tests run as expected.

See the output below:

Output of jest:

> jest

PASS src/firestore.spec.ts
  firestore
    ✓ is able to communicate with emulator (1063 ms)


  console.info
    Before transaction: try to acquire lease in transaction ...

      at acquireLease (src/lease.ts:16:11)

  console.info
    Before transaction: try to acquire lease in transaction ...

      at acquireLease (src/lease.ts:16:11)

  console.info
    Before transaction: try to acquire lease in transaction ...

      at acquireLease (src/lease.ts:16:11)

PASS src/lease.single.spec.ts
  acquireLease single
    ✓ returns true when ran once (1040 ms)

  console.info
    Transaction: acquired a new lease

      at _firestore2.firestore.runTransaction (src/lease.ts:37:15)

  console.info
    Transaction: acquired a new lease

      at _firestore2.firestore.runTransaction (src/lease.ts:37:15)

  console.info
    Transaction: acquired a new lease

      at _firestore2.firestore.runTransaction (src/lease.ts:37:15)

  console.info
    After transaction: will return true

      at acquireLease (src/lease.ts:43:11)

FAIL src/lease.multi.spec.ts
  ● Test suite failed to run

    Timeout - Async callback was not invoked within the 15000 ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 15000 ms timeout specified by jest.setTimeout.

      at mapper (node_modules/jest-jasmine2/build/queueRunner.js:29:45)

A worker process has failed to exit gracefully and has been force exited. This is likely caused by tests leaking due to improper teardown. Try running with --runInBand --detectOpenHandles to find leaks.
Test Suites: 1 failed, 2 passed, 3 total
Tests:       2 passed, 2 total
Snapshots:   0 total
Time:        32.386 s
Ran all test suites.
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! @ test: `jest`
npm ERR! Exit status 1

Output of the emulator:

[2020-07-13T15:28:34.365Z] > 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"]
[2020-07-13T15:28:34.366Z] > authorizing via signed-in user
⚠  Could not find config (firebase.json) so using defaults. 
i  emulators: Starting emulators: firestore {"metadata":{"emulator":{"name":"hub"},"message":"Starting emulators: firestore"}}
⚠  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."}}
[2020-07-13T15:28:34.384Z] Ignoring unsupported arg: projectId {"metadata":{"emulator":{"name":"firestore"},"message":"Ignoring unsupported arg: projectId"}}
[2020-07-13T15:28:34.384Z] Ignoring unsupported arg: auto_download {"metadata":{"emulator":{"name":"firestore"},"message":"Ignoring unsupported arg: auto_download"}}
[2020-07-13T15:28:34.385Z] Starting Firestore Emulator with command {"binary":"java","args":["-Duser.language=en","-jar","/Users/vdvleon/.cache/firebase/emulators/cloud-firestore-emulator-v1.11.4.jar","--host","localhost","--port",8080],"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\":[\"-Duser.language=en\",\"-jar\",\"/Users/vdvleon/.cache/firebase/emulators/cloud-firestore-emulator-v1.11.4.jar\",\"--host\",\"localhost\",\"--port\",8080],\"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"}}
[2020-07-13T15:28:35.488Z] API endpoint: http://localhost {"metadata":{"emulator":{"name":"firestore"},"message":"API endpoint: http://localhost"}}
[2020-07-13T15:28:35.488Z] :8080
If you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:

   export FIRESTORE_EMULATOR_HOST=localhost:8080

Dev App Server is now running.

 {"metadata":{"emulator":{"name":"firestore"},"message":":8080\nIf you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:\n\n   export FIRESTORE_EMULATOR_HOST=localhost:8080\n\nDev App Server is now running.\n\n"}}

┌──────────────────────────────────────────────────────────────┐
│ ✔  All emulators ready! It is now safe to connect your apps. │
└──────────────────────────────────────────────────────────────┘

┌───────────┬────────────────┐
│ Emulator  │ Host:Port      │
├───────────┼────────────────┤
│ Firestore │ localhost:8080 │
└───────────┴────────────────┘
  Other reserved ports: 

Issues? Report them at https://github.com/firebase/firebase-tools/issues and attach the *-debug.log files.
 
[2020-07-13T15:28:53.466Z] Jul 13, 2020 5:28:53 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 13, 2020 5:28:53 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected HTTP/2 connection.\n"}}
[2020-07-13T15:28:53.466Z] Jul 13, 2020 5:28:53 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 13, 2020 5:28:53 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected HTTP/2 connection.\n"}}
[2020-07-13T15:28:53.466Z] Jul 13, 2020 5:28:53 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 13, 2020 5:28:53 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected HTTP/2 connection.\n"}}
[2020-07-13T15:29:24.261Z] Jul 13, 2020 5:29:24 PM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError
INFO: operation failed: transaction timeout
 {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 13, 2020 5:29:24 PM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError\nINFO: operation failed: transaction timeout\n"}}
[2020-07-13T15:29:24.261Z] Jul 13, 2020 5:29:24 PM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError
INFO: operation failed: transaction timeout
 {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 13, 2020 5:29:24 PM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError\nINFO: operation failed: transaction timeout\n"}}

[samtstern]

@vdvleon thank you for the reproduction, I was able to see the same result. Assigning to @avolkovi to check it out

[vdvleon]

I wonder if there is progress on this issue? It seems about a year ago the problem occurred as well. Maybe this is related?

[rosalyntan]

Thanks for filing this issue! Filed b/162265825 for internal tracking.

[mikquinlan]

Related?

[vdvleon]

Related?

Could be related yeah. Could this behaviour be changed or is there a way to influence this timeout time? It's not very realistic to let our tests wait for 30 seconds.

[roblaszczak]

Any update on that @samtstern @rosalyntan ? It's a bit critical because it's making Firestore emulator unusable for any integration tests using transactions. Thanks!

[dunyakirkali]

Any progress on this issue?

[lutogin]

Same problem.
Is there a solution? Or a workaround?

[electricmonk]

Same issue here, apparently