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 client does not retry on contention errors #827

Closed
mad-it opened this issue Dec 18, 2019 · 12 comments · Fixed by #883 or #953
Closed

Firestore client does not retry on contention errors #827

mad-it opened this issue Dec 18, 2019 · 12 comments · Fixed by #883 or #953
Assignees
Labels
api: firestore Issues related to the googleapis/nodejs-firestore API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.

Comments

@mad-it
Copy link

mad-it commented Dec 18, 2019

Current behavior

We are using Google cloud functions in combination with Firestore. When multiple, in this example 2, cloud function instances attempt to process different data on the same documents within a transaction 1 of the instances throws a contention error. This is inline with what is documented here.

Expected behavior

Instance A & B both read document X inside of a transaction. Instance A updates document X before instance B can commit its changes. The expected behavior would be for the transaction on instance B to be retried because it cannot commit its changes due to the X being a "dirty read".

Environment details

  • OS: Ubuntu 19.10
  • Node.js version: 10.18.0
  • npm version:6.12
  • @google-cloud/firestore version: 2.6.1

Steps to reproduce

Even though we dont have clear reproduction steps, but after some investigation of the code, the culprit is seems clear.

Looking at this line in the code, it looks like contention caused inside of the updateFunction for example caused by reading a document, will never trigger a retry.

Additional information

Below is a log output of 2 functions "colliding" and no retry being triggered.

The logs have been sanitized by removing all project references, document structures and data being sent over the wire.

Logs
d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.651Z xqgri [Firestore.readStream]: Sending request: {\"database\":\"projects/<OBSCURED>/databases/(default)\",\"transaction\":{\"type\":\"Buffer\",\"data\":[OBSCURED]},\"documents\":[\"projects/<OBSCURED>/databases/(default)/documents/<OBSCURED>\"]}

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.651Z NA6v7 [Firestore.readStream]: Sending request: {\"parent\":\"projects/<OBSCURED>/databases/(default)/documents/<OBSCURED>\",\"structuredQuery\":{\"from\":[OBSCURED]},\"transaction\":{\"type\":\"Buffer\",\"data\":[OBSCURED]}

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.653Z Zajdo [Firestore.readStream]: Sending request: {\"parent\":\"projects/<OBSCURED>/databases/(default)/documents/<OBSCURED>\",\"structuredQuery\":{\"from\":[OBSCURED]},\"transaction\":{\"type\":\"Buffer\",\"data\":[OBSCURED]}}

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.783Z xqgri [Firestore.readStream]: Received response: {\"transaction\":{\"type\":\"Buffer\",\"data\":[]},\"readTime\":{\"seconds\":\"1576597307\",\"nanos\":697669000},\"found\":{OBSCURED},\"name\":\"projects/<OBSCURED>/databases/(default)/documents/<OBSCURED>\",\"createTime\":{\"seconds\":\"1576597302\",\"nanos\":737511000},\"updateTime\":{\"seconds\":\"1576597302\",\"nanos\":737511000}},\"result\":\"found\"}

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.783Z xqgri [Firestore._initializeStream]: Releasing stream

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.784Z xqgri [Firestore.getAll_]: Received document: projects/<OBSCURED>/databases/(default)/documents/<OBSCURED>

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.784Z xqgri [Firestore._initializeStream]: Received stream end

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.784Z xqgri [Firestore.getAll_]: Received 1 results

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.785Z xqgri [Firestore._initializeStream]: Forwarding stream close

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.785Z xqgri [Firestore._initializeStream]: Received stream end

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:47.785Z xqgri [Firestore.getAll_]: Received 1 results

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.813Z YzliZ [Firestore.readStream]: Received response: {\"transaction\":{\"type\":\"Buffer\",\"data\":[]},\"readTime\":{\"seconds\":\"1576597307\",\"nanos\":746009000},\"found\":{OBSCURED},\"name\":\"projects/<OBSCURED>/databases/(default)/documents/<OBSCURED>\",\"createTime\":{\"seconds\":\"1576597302\",\"nanos\":737511000},\"updateTime\":{\"seconds\":\"1576597302\",\"nanos\":737511000}},\"result\":\"found\"}

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.813Z YzliZ [Firestore._initializeStream]: Releasing stream

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.814Z YzliZ [Firestore.getAll_]: Received document: projects/<OBSCURED>/databases/(default)/documents/<OBSCURED>

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.815Z 6NU5q [Firestore.readStream]: Received response: {\"document\":{\"fields\":{OBSCURED},\"readTime\":{\"seconds\":\"1576597307\",\"nanos\":746009000},\"skippedResults\":0}

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.888Z 6NU5q [Firestore._initializeStream]: Releasing stream

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.890Z YzliZ [Firestore._initializeStream]: Received stream end

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.890Z YzliZ [Firestore.getAll_]: Received 1 results

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.891Z 6NU5q [Firestore._initializeStream]: Received stream end

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.892Z YzliZ [WriteBatch.commit]: Sending 2 writes

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.892Z YzliZ [ClientPool.acquire]: Re-using existing client with 100 remaining operations

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.892Z YzliZ [Firestore._initializeStream]: Forwarding stream close

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.892Z YzliZ [Firestore._initializeStream]: Received stream end

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.893Z YzliZ [Firestore.getAll_]: Received 1 results

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.893Z 6NU5q [Firestore._initializeStream]: Forwarding stream close

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.893Z 6NU5q [Firestore._initializeStream]: Received stream end

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:47.895Z YzliZ [Firestore.request]: Sending request: {\"database\":\"projects/<OBSCURED>/databases/(default)\",\"writes\":[{\"update\":{\"name\":\"projects/<OBSCURED>/databases/(default)/documents/<OBSCURED>\",\"fields\":{<OBSCURED>},{\"update\":{\"name\":\"projects/<OBSCURED>/databases/(default)/<path2>\",\"fields\":{<OBSCURED>},\"updateMask\":{\"fieldPaths\":[OBSCURED]},\"currentDocument\":{\"exists\":true}}],\"transaction\":{\"type\":\"Buffer\",\"data\":[OBSCURED]}

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.180Z Zajdo [Firestore._initializeStream]: Received stream error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.\n at callErrorFromStatus (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:30:26)\n at Http2CallStream.call.on (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:79:34)\n at Http2CallStream.emit (events.js:194:15)\n at Http2CallStream.EventEmitter.emit (domain.js:459:23)\n at process.nextTick (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22)\n at process._tickCallback (internal/process/next_tick.js:61:11)\n code: 10,\n details: 'Too much contention on these documents. Please try again.',\n metadata: Metadata { internalRepr: Map {}, options: {} } }

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.180Z Zajdo [Firestore._initializeStream]: Received initial error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.\n at callErrorFromStatus (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:30:26)\n at Http2CallStream.call.on (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:79:34)\n at Http2CallStream.emit (events.js:194:15)\n at Http2CallStream.EventEmitter.emit (domain.js:459:23)\n at process.nextTick (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22)\n at process._tickCallback (internal/process/next_tick.js:61:11)\n code: 10,\n details: 'Too much contention on these documents. Please try again.',\n metadata: Metadata { internalRepr: Map {}, options: {} } }

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.180Z Zajdo [Firestore._retry]: Request failed with unrecoverable error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.\n at callErrorFromStatus (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:30:26)\n at Http2CallStream.call.on (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:79:34)\n at Http2CallStream.emit (events.js:194:15)\n at Http2CallStream.EventEmitter.emit (domain.js:459:23)\n at process.nextTick (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22)\n at process._tickCallback (internal/process/next_tick.js:61:11)\n code: 10,\n details: 'Too much contention on these documents. Please try again.',\n metadata: Metadata { internalRepr: Map {}, options: {} } }

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.181Z xqgri [Firestore.runTransaction]: Rolling back transaction after callback error: { error:\n { Error: 10 ABORTED: Too much contention on these documents. Please try again.\n at callErrorFromStatus (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:30:26)\n at Http2CallStream.call.on (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:79:34)\n at Http2CallStream.emit (events.js:194:15)\n at Http2CallStream.EventEmitter.emit (domain.js:459:23)\n at process.nextTick (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22)\n at process._tickCallback (internal/process/next_tick.js:61:11)\n code: 10,\n details: 'Too much contention on these documents. Please try again.',\n metadata: Metadata { internalRepr: Map {}, options: {} } },\n hooks:\n { abort: [], failure: [ [Function] ], success: [ [Function] ] } }

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.181Z xqgri [ClientPool.acquire]: Re-using existing client with 99 remaining operations

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.182Z NA6v7 [Firestore._initializeStream]: Received stream error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.\n at callErrorFromStatus (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:30:26)\n at Http2CallStream.call.on (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:79:34)\n at Http2CallStream.emit (events.js:194:15)\n at Http2CallStream.EventEmitter.emit (domain.js:459:23)\n at process.nextTick (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22)\n at process._tickCallback (internal/process/next_tick.js:61:11)\n code: 10,\n details: 'Too much contention on these documents. Please try again.',\n metadata: Metadata { internalRepr: Map {}, options: {} } }

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.183Z NA6v7 [Firestore._initializeStream]: Received initial error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.\n at callErrorFromStatus (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:30:26)\n at Http2CallStream.call.on (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:79:34)\n at Http2CallStream.emit (events.js:194:15)\n at Http2CallStream.EventEmitter.emit (domain.js:459:23)\n at process.nextTick (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22)\n at process._tickCallback (internal/process/next_tick.js:61:11)\n code: 10,\n details: 'Too much contention on these documents. Please try again.',\n metadata: Metadata { internalRepr: Map {}, options: {} } }

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.183Z NA6v7 [Firestore._retry]: Request failed with unrecoverable error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.\n at callErrorFromStatus (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:30:26)\n at Http2CallStream.call.on (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call.js:79:34)\n at Http2CallStream.emit (events.js:194:15)\n at Http2CallStream.EventEmitter.emit (domain.js:459:23)\n at process.nextTick (/srv/functions/node_modules/google-gax/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22)\n at process._tickCallback (internal/process/next_tick.js:61:11)\n code: 10,\n details: 'Too much contention on these documents. Please try again.',\n metadata: Metadata { internalRepr: Map {}, options: {} } }

90fwt868bz2k - Firestore (2.6.1) 2019-12-17T15:41:48.189Z YzliZ [Firestore.request]: Received response: {\"writeResults\":[{\"transformResults\":[],\"updateTime\":{\"seconds\":\"1576597308\",\"nanos\":116169000}},{\"transformResults\":[],\"updateTime\":{\"seconds\":\"1576597308\",\"nanos\":116169000}}],\"commitTime\":{\"seconds\":\"1576597308\",\"nanos\":116169000}}

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.214Z xqgri [Firestore.request]: Sending request: {\"database\":\"projects/<OBSCURED>/databases/(default)\",\"transaction\":{\"type\":\"Buffer\",\"data\":[OBSCURED]}}

d82a0kxaae6u - Firestore (2.6.1) 2019-12-17T15:41:48.341Z xqgri [Firestore.request]: Received response: {}
@schmidt-sebastian
Copy link
Contributor

schmidt-sebastian commented Dec 19, 2019

@mad-it Thanks for filing this issue. We currently retry transactions only when the commit fails. Our assumption is that any error that occurs within a transaction block is thrown by the user with the intent to abort the transaction. As shown in your logs, that logic is a little bit oversimplified. We will update the client to ignore errors during document reads. Please bear with us though as we are approaching the holidays and will not be able to address this beforehand.

@yoshi-automation yoshi-automation added the triage me I really want to be triaged. label Dec 19, 2019
@schmidt-sebastian schmidt-sebastian added type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. and removed triage me I really want to be triaged. labels Dec 19, 2019
@yoshi-automation yoshi-automation added triage me I really want to be triaged. 🚨 This issue needs some love. labels Dec 19, 2019
@bcoe bcoe added priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. and removed type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. labels Dec 26, 2019
@yoshi-automation yoshi-automation removed 🚨 This issue needs some love. triage me I really want to be triaged. labels Dec 26, 2019
@schmidt-sebastian schmidt-sebastian self-assigned this Dec 26, 2019
@schmidt-sebastian
Copy link
Contributor

This will be part of the 3.3 release.

@mad-it
Copy link
Author

mad-it commented Jan 7, 2020

@schmidt-sebastian Thanks for the fix, it looks like its actually retrying now! 🎉

It seems that there is still an issue tho. Ran a trace once again to verify what is happening and it seems that the transaction is retried with the exponential backoff introduced in #847 but we are getting contention on re-initializing the transaction.

Added some sanitized logs.

Logs
Firestore (3.3.2) 2020-01-07T12:50:06.089Z EJrXY [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.3.2) 2020-01-07T12:50:06.089Z EJrXY [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.3.2) 2020-01-07T12:50:06.089Z EJrXY [Firestore.request]: Sending request: {"database":"projects/projectId/databases/(default)"}  
Firestore (3.3.2) 2020-01-07T12:50:06.225Z EJrXY [Firestore.request]: Received response: {"transaction":{"type":"Buffer","data":[]}}
{"data":{"message":"Transaction started."},"severity":"INFO"}  
{"data":{"message":"Getting snapshots."},"severity":"INFO"}  
Firestore (3.3.2) 2020-01-07T12:50:06.439Z EJrXY [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.3.2) 2020-01-07T12:50:06.439Z EJrXY [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.3.2) 2020-01-07T12:50:06.439Z PmK0q [ClientPool.acquire]: Re-using existing client with 99 remaining operations  
Firestore (3.3.2) 2020-01-07T12:50:06.440Z PmK0q [ClientPool.acquire]: Re-using existing client with 99 remaining operations  
Firestore (3.3.2) 2020-01-07T12:50:06.447Z ZaUED [ClientPool.acquire]: Re-using existing client with 98 remaining operations  
Firestore (3.3.2) 2020-01-07T12:50:06.447Z ZaUED [ClientPool.acquire]: Re-using existing client with 98 remaining operations  
Firestore (3.3.2) 2020-01-07T12:50:06.448Z EJrXY [Firestore.requestStream]: Sending request: {"database":"projects/projectId/databases/(default)","transaction":{"type":"Buffer","data":[]},"documents":["projects/projectId/databases/(default)/<documentPath>"]}  
Firestore (3.3.2) 2020-01-07T12:50:06.448Z PmK0q [Firestore.requestStream]: Sending request: {"parent":"projects/projectId/databases/(default)/<documentPath>","structuredQuery":{"from":[{}],"where":{"fieldFilter":{}},"transaction":{"type":"Buffer","data":[xxx]}}  
Firestore (3.3.2) 2020-01-07T12:50:06.458Z ZaUED [Firestore.requestStream]: Sending request: {"parent":"projects/projectId/databases/(default)/<documentPath>","structuredQuery":{"from":[],"where":{}}},"transaction":{"type":"Buffer","data":[xxx]}}  
Firestore (3.3.2) 2020-01-07T12:50:06.593Z PmK0q [Firestore.requestStream]: Received response: {"document":null,"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1578401406","nanos":531068000},"skippedResults":0}  
Firestore (3.3.2) 2020-01-07T12:50:06.593Z PmK0q [Firestore._initializeStream]: Releasing stream  
Firestore (3.3.2) 2020-01-07T12:50:06.595Z PmK0q [Firestore._initializeStream]: Received stream end  
Firestore (3.3.2) 2020-01-07T12:50:06.612Z ZaUED [Firestore.requestStream]: Received response: {"document":{},"name":"projects/projectId/databases/(default)/<documentPath2>","createTime":{"seconds":"1555019896","nanos":853245000},"updateTime":{"seconds":"1578143084","nanos":250413000}},"transaction":{"type":"Buffer","data":[xxx]},"readTime":{"seconds":"1578401406","nanos":539724000},"skippedResults":0}  
Firestore (3.3.2) 2020-01-07T12:50:06.612Z ZaUED [Firestore._initializeStream]: Releasing stream  
Firestore (3.3.2) 2020-01-07T12:50:06.615Z ZaUED [Firestore._initializeStream]: Received stream end  
Firestore (3.3.2) 2020-01-07T12:50:07.228Z EJrXY [Firestore._initializeStream]: Received initial error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.  
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24)  
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28)  
    at Http2CallStream.emit (events.js:194:15)  
    at Http2CallStream.EventEmitter.emit (domain.js:459:23)  
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14)  
    at process._tickCallback (internal/process/next_tick.js:61:11)  
  code: 10,  
  details: 'Too much contention on these documents. Please try again.',  
  metadata: Metadata { internalRepr: Map {}, options: {} } }  
Firestore (3.3.2) 2020-01-07T12:50:07.228Z EJrXY [Firestore._initializeStream]: Received stream end  
Firestore (3.3.2) 2020-01-07T12:50:07.229Z EJrXY [Firestore._initializeStream]: Releasing stream  
Firestore (3.3.2) 2020-01-07T12:50:07.229Z EJrXY [Firestore._retry]: Retrying request that failed with error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.  
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24)  
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28)  
    at Http2CallStream.emit (events.js:194:15)  
    at Http2CallStream.EventEmitter.emit (domain.js:459:23)  
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14)  
    at process._tickCallback (internal/process/next_tick.js:61:11)  
  code: 10,  
  details: 'Too much contention on these documents. Please try again.',  
  metadata: Metadata { internalRepr: Map {}, options: {} } }  
Firestore (3.3.2) 2020-01-07T12:50:07.229Z ##### [ExponentialBackoff.backoffAndWait]: Backing off for 515.5268090625104 ms (base delay: 1000 ms)  
Firestore (3.3.2) 2020-01-07T12:50:07.746Z EJrXY [Firestore.requestStream]: Sending request: {"database":"projects/projectId/databases/(default)","transaction":{"type":"Buffer","data":[xxx]},"documents":["projects/projectId/databases/(default)/<documentPath>"]}  
Firestore (3.3.2) 2020-01-07T12:50:07.904Z EJrXY [Firestore._initializeStream]: Received initial error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.  
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24)  
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28)  
    at Http2CallStream.emit (events.js:194:15)  
    at Http2CallStream.EventEmitter.emit (domain.js:459:23)  
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14)  
    at process._tickCallback (internal/process/next_tick.js:61:11)  
  code: 10,  
  details: 'Too much contention on these documents. Please try again.',  
  metadata: Metadata { internalRepr: Map {}, options: {} } }  
Firestore (3.3.2) 2020-01-07T12:50:07.904Z EJrXY [Firestore._initializeStream]: Received stream end  
Firestore (3.3.2) 2020-01-07T12:50:07.904Z EJrXY [Firestore._initializeStream]: Releasing stream  
Firestore (3.3.2) 2020-01-07T12:50:07.905Z EJrXY [Firestore._retry]: Retrying request that failed with error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.  
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24)  
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
    at Http2CallStream.emit (events.js:194:15) 
    at Http2CallStream.EventEmitter.emit (domain.js:459:23) 
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
    at process._tickCallback (internal/process/next_tick.js:61:11) 
  code: 10, 
  details: 'Too much contention on these documents. Please try again.', 
  metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.3.2) 2020-01-07T12:50:07.905Z ##### [ExponentialBackoff.backoffAndWait]: Backing off for 1420.5420701214282 ms (base delay: 1500 ms) 
Firestore (3.3.2) 2020-01-07T12:50:09.326Z EJrXY [Firestore.requestStream]: Sending request: {"database":"projects/projectId/databases/(default)","transaction":{"type":"Buffer","data":[xxx]},"documents":["projects/projectId/databases/(default)/<documentPath>"]} 
Firestore (3.3.2) 2020-01-07T12:50:09.464Z EJrXY [Firestore._initializeStream]: Received initial error: { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
    at Http2CallStream.emit (events.js:194:15) 
    at Http2CallStream.EventEmitter.emit (domain.js:459:23) 
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
    at process._tickCallback (internal/process/next_tick.js:61:11) 
  code: 10, 
  details: 'Too much contention on these documents. Please try again.', 
  metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.3.2) 2020-01-07T12:50:09.464Z EJrXY [Firestore._initializeStream]: Received stream end 
Firestore (3.3.2) 2020-01-07T12:50:09.465Z EJrXY [Firestore._initializeStream]: Releasing stream 
Firestore (3.3.2) 2020-01-07T12:50:09.465Z EJrXY [Firestore._retry]: Retrying request that failed with error: { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
    at Http2CallStream.emit (events.js:194:15) 
    at Http2CallStream.EventEmitter.emit (domain.js:459:23) 
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
    at process._tickCallback (internal/process/next_tick.js:61:11) 
  code: 10, 
  details: 'Too much contention on these documents. Please try again.', 
  metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.3.2) 2020-01-07T12:50:09.465Z ##### [ExponentialBackoff.backoffAndWait]: Backing off for 2587.952641330125 ms (base delay: 2250 ms) 
Firestore (3.3.2) 2020-01-07T12:50:12.054Z EJrXY [Firestore.requestStream]: Sending request: {"database":"projects/projectId/databases/(default)","transaction":{"type":"Buffer","data":[xxx]},"documents":["projects/projectId/databases/(default)/<documentPath>"]} 
Firestore (3.3.2) 2020-01-07T12:50:12.191Z EJrXY [Firestore._initializeStream]: Received initial error: { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
    at Http2CallStream.emit (events.js:194:15) 
    at Http2CallStream.EventEmitter.emit (domain.js:459:23) 
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
    at process._tickCallback (internal/process/next_tick.js:61:11) 
  code: 10, 
  details: 'Too much contention on these documents. Please try again.', 
  metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.3.2) 2020-01-07T12:50:12.191Z EJrXY [Firestore._initializeStream]: Received stream end 
Firestore (3.3.2) 2020-01-07T12:50:12.191Z EJrXY [Firestore._initializeStream]: Releasing stream 
Firestore (3.3.2) 2020-01-07T12:50:12.192Z EJrXY [Firestore._retry]: Retrying request that failed with error: { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
    at Http2CallStream.emit (events.js:194:15) 
    at Http2CallStream.EventEmitter.emit (domain.js:459:23) 
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
    at process._tickCallback (internal/process/next_tick.js:61:11) 
  code: 10, 
  details: 'Too much contention on these documents. Please try again.', 
  metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.3.2) 2020-01-07T12:50:12.192Z ##### [ExponentialBackoff.backoffAndWait]: Backing off for 3871.6061597913904 ms (base delay: 3375 ms) 
Firestore (3.3.2) 2020-01-07T12:50:16.065Z EJrXY [Firestore.requestStream]: Sending request: {"database":"projects/projectId/databases/(default)","transaction":{"type":"Buffer","data":[xxx]},"documents":["projects/projectId/databases/(default)/<documentPath>"]} 
Firestore (3.3.2) 2020-01-07T12:50:16.188Z EJrXY [Firestore._initializeStream]: Received initial error: { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
    at Http2CallStream.emit (events.js:194:15) 
    at Http2CallStream.EventEmitter.emit (domain.js:459:23) 
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
    at process._tickCallback (internal/process/next_tick.js:61:11) 
  code: 10, 
  details: 'Too much contention on these documents. Please try again.', 
  metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.3.2) 2020-01-07T12:50:16.189Z EJrXY [Firestore._initializeStream]: Received stream end 
Firestore (3.3.2) 2020-01-07T12:50:16.189Z EJrXY [Firestore._initializeStream]: Releasing stream 
Firestore (3.3.2) 2020-01-07T12:50:16.190Z EJrXY [Firestore._retry]: Request failed with error: { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
    at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
    at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
    at Http2CallStream.emit (events.js:194:15) 
    at Http2CallStream.EventEmitter.emit (domain.js:459:23) 
    at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
    at process._tickCallback (internal/process/next_tick.js:61:11) 
  code: 10, 
  details: 'Too much contention on these documents. Please try again.', 
  metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.3.2) 2020-01-07T12:50:16.193Z EJrXY [Firestore.runTransaction]: Rolling back transaction after callback error: { error: 
   { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
       at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
       at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
       at Http2CallStream.emit (events.js:194:15) 
       at Http2CallStream.EventEmitter.emit (domain.js:459:23) 
       at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
       at process._tickCallback (internal/process/next_tick.js:61:11) 
     code: 10, 
     details: 'Too much contention on these documents. Please try again.', 
     metadata: Metadata { internalRepr: Map {}, options: {} } }, 
Firestore (3.3.2) 2020-01-07T12:50:16.193Z EJrXY [ClientPool.acquire]: Re-using existing client with 100 remaining operations 
Firestore (3.3.2) 2020-01-07T12:50:16.193Z EJrXY [ClientPool.acquire]: Re-using existing client with 100 remaining operations 
Firestore (3.3.2) 2020-01-07T12:50:16.195Z EJrXY [Firestore.request]: Sending request: {"database":"projects/projectId/databases/(default)","transaction":{"type":"Buffer","data":[xxx]}} 
Firestore (3.3.2) 2020-01-07T12:50:16.333Z EJrXY [Firestore.request]: Received response: {} 

@schmidt-sebastian
Copy link
Contributor

@mad-it What is the write rate for the document in question? It is a bit surprising to me that the contention issue exists for so long. We may to investigate with the backend team why your transactions are failing even with retry.

The actual failure that you see is expected though. We only retry five times, after which we will forward the last error to the API surface.

@mad-it
Copy link
Author

mad-it commented Jan 7, 2020

@schmidt-sebastian the document in question is only written to by 1 or 2 instances at most. But the issue does not seem to be the document which is being written to, it seems to be that Firestore cannot acquire a lock( assumption here) to start a transaction.

As you can see in the log I purposely left a log line stating "Transaction started" which is the first thing that happened in the so called "updateFunction".

As you can see in the logs, that line is only printed once meaning it never retries the provided "updateFunction" because it fails on reinitializing the transaction scope.

@schmidt-sebastian
Copy link
Contributor

Do you mind filing a customer support request that contains your project ID, the document path and approximate timestamps? https://cloud.google.com/support/

I am not able to look at the backend logs, but our support team can on request.

@schmidt-sebastian
Copy link
Contributor

We have received all necessary information.

@mad-it
Copy link
Author

mad-it commented Jan 10, 2020

Any new information come to light regarding this issue?

@schmidt-sebastian
Copy link
Contributor

Our backend team took a look at the request logs. It sounds like we didn't really solve the problem yet.

What they are seeing is the following sequence of events:

  • BeginTransaction
  • Read (fail)
  • Read (fail)
  • Read (fail)
  • Read (fail)
  • Read (fail)

This re-reading is done because we changed the configuration. The retries are now happening, but hidden from our SDK and in the networking layer. Instead, we need to modify the SDK to do these retries ourselves so we can rollback the previous transaction. This would then look as such:

  • BeginTransaction
  • Read (fail)
  • Rollback
  • BeginTransaction
  • Read (success)

Please bear with us as we make the necessary changes.

@mad-it
Copy link
Author

mad-it commented Jan 20, 2020

Ran a small test to see if this was fixed. I am not sure its even retrying anymore.

here are some sanitized logs

Logs
Firestore (3.4.0) 2020-01-20T14:25:09.685Z ImLa5 [ClientPool.acquire]: Re-using existing client with 100 remaining operations 
Firestore (3.4.0) 2020-01-20T14:25:09.685Z ImLa5 [Firestore.request]: Sending request: {"database":"projects/<project-id>/databases/(default)"} 
Firestore (3.4.0) 2020-01-20T14:25:09.802Z ImLa5 [Firestore.request]: Received response: {"transaction":{"type":"Buffer","data":[]}} 
Firestore (3.4.0) 2020-01-20T14:25:10.015Z ImLa5 [ClientPool.acquire]: Re-using existing client with 100 remaining operations 
Firestore (3.4.0) 2020-01-20T14:25:10.015Z ImLa5 [Firestore.requestStream]: Sending request: {"database":"projects/<project-id>/databases/(default)","transaction":{"type":"Buffer","data":[]},"documents":["projects/<project-id>/databases/(default)/documents/<document-id>"]} 
Firestore (3.4.0) 2020-01-20T14:25:10.016Z BGcSw [ClientPool.acquire]: Re-using existing client with 99 remaining operations 
Firestore (3.4.0) 2020-01-20T14:25:10.016Z BGcSw [Firestore.requestStream]: Sending request: {"parent":"projects/<project-id>/databases/(default)/documents/<document-id>","structuredQuery":{}},"transaction":{"type":"Buffer","data":[]}} 
Firestore (3.4.0) 2020-01-20T14:25:10.017Z Go3xW [ClientPool.acquire]: Re-using existing client with 98 remaining operations 
Firestore (3.4.0) 2020-01-20T14:25:10.017Z Go3xW [Firestore.requestStream]: Sending request: {"parent":"projects/<project-id>/databases/(default)/documents/<document-id>","structuredQuery":{}},"transaction":{"type":"Buffer","data":[]}} 
Firestore (3.4.0) 2020-01-20T14:25:10.145Z BGcSw [Firestore.requestStream]: Received response: {"document":null,"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1579530310","nanos":86258000},"skippedResults":0} 
Firestore (3.4.0) 2020-01-20T14:25:10.145Z BGcSw [Firestore._initializeStream]: Releasing stream 
Firestore (3.4.0) 2020-01-20T14:25:10.146Z BGcSw [Firestore._initializeStream]: Received stream end 
Firestore (3.4.0) 2020-01-20T14:25:10.541Z Go3xW [Firestore.requestStream]: Received response: {},"name":"projects/<project-id>/databases/(default)/documents/<document-id>","createTime":{"seconds":"1562276254","nanos":362598000},"updateTime":{"seconds":"1579090232","nanos":758903000}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1579530310","nanos":475168000},"skippedResults":0} 
Firestore (3.4.0) 2020-01-20T14:25:10.541Z Go3xW [Firestore._initializeStream]: Releasing stream 
Firestore (3.4.0) 2020-01-20T14:25:10.542Z Go3xW [Firestore._initializeStream]: Received stream end 
Firestore (3.4.0) 2020-01-20T14:25:11.530Z ImLa5 [Firestore._initializeStream]: Received initial error: { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
   at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
   at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
   at Http2CallStream.emit (events.js:203:15) 
   at Http2CallStream.EventEmitter.emit (domain.js:466:23) 
   at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
   at process._tickCallback (internal/process/next_tick.js:61:11) 
 code: 10, 
 details: 'Too much contention on these documents. Please try again.', 
 metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.4.0) 2020-01-20T14:25:11.531Z ImLa5 [Firestore._initializeStream]: Received stream end 
Firestore (3.4.0) 2020-01-20T14:25:11.531Z ImLa5 [Firestore._retry]: Request failed with error: { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
   at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
   at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
   at Http2CallStream.emit (events.js:203:15) 
   at Http2CallStream.EventEmitter.emit (domain.js:466:23) 
   at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
   at process._tickCallback (internal/process/next_tick.js:61:11) 
 code: 10, 
 details: 'Too much contention on these documents. Please try again.', 
 metadata: Metadata { internalRepr: Map {}, options: {} } } 
Firestore (3.4.0) 2020-01-20T14:25:11.531Z ImLa5 [Firestore.runTransaction]: Rolling back transaction after callback error: { error: 
  { Error: 10 ABORTED: Too much contention on these documents. Please try again. 
      at callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24) 
      at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:132:28) 
      at Http2CallStream.emit (events.js:203:15) 
      at Http2CallStream.EventEmitter.emit (domain.js:466:23) 
      at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14) 
      at process._tickCallback (internal/process/next_tick.js:61:11) 
    code: 10, 
    details: 'Too much contention on these documents. Please try again.', 
    metadata: Metadata { internalRepr: Map {}, options: {} } }, 
 hooks: { abort: [], failure: [], success: [] } } 
Firestore (3.4.0) 2020-01-20T14:25:11.532Z ImLa5 [ClientPool.acquire]: Re-using existing client with 100 remaining operations 
Firestore (3.4.0) 2020-01-20T14:25:11.532Z ImLa5 [Firestore.request]: Sending request: {"database":"projects/<project-id>/databases/(default)","transaction":{"type":"Buffer","data":[]}} 
Firestore (3.4.0) 2020-01-20T14:25:12.047Z ImLa5 [Firestore.request]: Received response: {} 

@mad-it
Copy link
Author

mad-it commented Jan 22, 2020

After some more investigations, it seems to be working.
However, the above case is still an issue which is blocking me from removing the workarounds that are in place.

1 thing I did notice is that retries do not get a backoff(not sure if this is intentional or not).

Since I cannot reopen the issue, ccing @thebrianchen to increase visibility.

Added some sanatized logs to showcase that in some instances it does work 🎉 👍

Logs
Firestore (3.4.0) 2020-01-22T09:02:46.500Z CE47t [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:46.500Z CE47t [Firestore.request]: Sending request: {"database":"projects/<project-id>/databases/(default)"}  
Firestore (3.4.0) 2020-01-22T09:02:46.619Z CE47t [Firestore.request]: Received response: {"transaction":{"type":"Buffer","data":[]}}  
Firestore (3.4.0) 2020-01-22T09:02:46.851Z CE47t [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:46.851Z CE47t [Firestore.requestStream]: Sending request: {"database":"projects/<project-id>/databases/(default)","transaction":{"type":"Buffer","data":[]}  
Firestore (3.4.0) 2020-01-22T09:02:46.930Z tEwWb [ClientPool.acquire]: Re-using existing client with 99 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:46.933Z tEwWb [Firestore.requestStream]: Sending request: {"parent":"projects/<project-id>/databases/(default)/<document-id>,"structuredQuery":{"from":["transaction":{"type":"Buffer","data":[]}}  
Firestore (3.4.0) 2020-01-22T09:02:46.934Z oDbtv [ClientPool.acquire]: Re-using existing client with 98 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:46.934Z oDbtv [Firestore.requestStream]: Sending request: {"parent":"projects/<project-id>/databases/(default)/<document-id>,"structuredQuery":{"from":["transaction":{"type":"Buffer","data":[]}}  
Firestore (3.4.0) 2020-01-22T09:02:47.454Z tEwWb [Firestore.requestStream]: Received response: {"document":null,"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1579683767","nanos":395555000},"skippedResults":0}  
Firestore (3.4.0) 2020-01-22T09:02:47.454Z tEwWb [Firestore._initializeStream]: Releasing stream  
Firestore (3.4.0) 2020-01-22T09:02:47.455Z tEwWb [Firestore._initializeStream]: Received stream end  
Firestore (3.4.0) 2020-01-22T09:02:47.532Z CE47t [Firestore.requestStream]: Received response: {"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1579683767","nanos":408259000},"found":{"createTime":{"seconds":"1579683762","nanos":88419000},"updateTime":{"seconds":"1579683762","nanos":88419000}},"result":"found"}  
Firestore (3.4.0) 2020-01-22T09:02:47.532Z CE47t [Firestore._initializeStream]: Releasing stream  
Firestore (3.4.0) 2020-01-22T09:02:47.532Z CE47t [Firestore.getAll_]: Received document: projects/<project-id>/databases/(default)<document-id>  
Firestore (3.4.0) 2020-01-22T09:02:47.532Z CE47t [Firestore._initializeStream]: Received stream end  
Firestore (3.4.0) 2020-01-22T09:02:47.532Z CE47t [Firestore.getAll_]: Received 1 results  
Firestore (3.4.0) 2020-01-22T09:02:47.533Z oDbtv [Firestore.requestStream]: Received response: {"document"{}:,"skippedResults":0}  
Firestore (3.4.0) 2020-01-22T09:02:47.534Z oDbtv [Firestore._initializeStream]: Releasing stream  
Firestore (3.4.0) 2020-01-22T09:02:47.534Z oDbtv [Firestore._initializeStream]: Received stream end  
Firestore (3.4.0) 2020-01-22T09:02:47.535Z CE47t [WriteBatch.commit]: Sending 2 writes  
Firestore (3.4.0) 2020-01-22T09:02:47.535Z CE47t [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:47.535Z CE47t [Firestore.request]: Sending request: {"database":"projects/<project-id>/databases/(default)","writes":[{"update":{"name":"projects/<project-id>/databases/(default)/documents-id","fields":{},"currentDocument":{"exists":false}},{"update":{"name":"projects/<project-id>/databases/(default)<document-id>","fields":{}},"updateMask":{"fieldPaths":[]},"currentDocument":{"exists":true}}],"transaction":{"type":"Buffer","data":[]}}  
Firestore (3.4.0) 2020-01-22T09:02:48.066Z CE47t [Firestore.request]: Received error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.  
  at Object.callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24)  
  at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/client.ts:155:18)  
  at Http2CallStream.emit (events.js:203:15)  
  at Http2CallStream.EventEmitter.emit (domain.js:466:23)  
  at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14)  
  at process._tickCallback (internal/process/next_tick.js:61:11)  
code: 10,  
details: 'Too much contention on these documents. Please try again.',  
metadata: Metadata { internalRepr: Map {}, options: {} } }  
Firestore (3.4.0) 2020-01-22T09:02:48.067Z CE47t [Firestore.runTransaction]: Retrying transaction after error: { Error: 10 ABORTED: Too much contention on these documents. Please try again.  
  at Object.callErrorFromStatus (/srv/functions/node_modules/@grpc/grpc-js/src/call.ts:79:24)  
  at Http2CallStream.call.on (/srv/functions/node_modules/@grpc/grpc-js/src/client.ts:155:18)  
  at Http2CallStream.emit (events.js:203:15)  
  at Http2CallStream.EventEmitter.emit (domain.js:466:23)  
  at process.nextTick (/srv/functions/node_modules/@grpc/grpc-js/src/call-stream.ts:183:14)  
  at process._tickCallback (internal/process/next_tick.js:61:11)  
code: 10,  
details: 'Too much contention on these documents. Please try again.',  
metadata: Metadata { internalRepr: Map {}, options: {} } }  
Firestore (3.4.0) 2020-01-22T09:02:48.067Z CE47t [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:48.067Z CE47t [Firestore.request]: Sending request: {"database":"projects/<project-id>/databases/(default)","options":{"readWrite":{"retryTransaction":{"type":"Buffer","data":[]}}}}  
Firestore (3.4.0) 2020-01-22T09:02:48.184Z CE47t [Firestore.request]: Received response: {"transaction":{"type":"Buffer","data":[]}}  
Firestore (3.4.0) 2020-01-22T09:02:48.407Z CE47t [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:48.407Z CE47t [Firestore.requestStream]: Sending request: {"database":"projects/<project-id>/databases/(default)","transaction":{"type":"Buffer","data":[]},"documents":["projects/<project-id>/databases/(default)<document-id>"]}  
Firestore (3.4.0) 2020-01-22T09:02:48.408Z JK98a [ClientPool.acquire]: Re-using existing client with 99 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:48.408Z JK98a [Firestore.requestStream]: Sending request: {"parent":"projects/<project-id>/databases/(default)/<document-id>,"structuredQuery":{},"transaction":{"type":"Buffer","data":[]}}  
Firestore (3.4.0) 2020-01-22T09:02:48.408Z 1FNVa [ClientPool.acquire]: Re-using existing client with 98 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:48.408Z 1FNVa [Firestore.requestStream]: Sending request: {"parent":"projects/<project-id>/databases/(default)/<document-id>,"structuredQuery":{},"transaction":{"type":"Buffer","data":[]}}  
Firestore (3.4.0) 2020-01-22T09:02:48.631Z CE47t [Firestore.requestStream]: Received response: {"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1579683768","nanos":485466000},"found":{},"result":"found"}  
Firestore (3.4.0) 2020-01-22T09:02:48.631Z CE47t [Firestore._initializeStream]: Releasing stream  
Firestore (3.4.0) 2020-01-22T09:02:48.631Z CE47t [Firestore.getAll_]: Received document: projects/<project-id>/databases/(default)<document-id>  
Firestore (3.4.0) 2020-01-22T09:02:48.632Z CE47t [Firestore._initializeStream]: Received stream end  
Firestore (3.4.0) 2020-01-22T09:02:48.632Z CE47t [Firestore.getAll_]: Received 1 results  
Firestore (3.4.0) 2020-01-22T09:02:48.731Z 1FNVa [Firestore.requestStream]: Received response: {"document":{},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1579683768","nanos":485466000},"skippedResults":0}  
Firestore (3.4.0) 2020-01-22T09:02:48.731Z 1FNVa [Firestore._initializeStream]: Releasing stream  
Firestore (3.4.0) 2020-01-22T09:02:48.732Z 1FNVa [Firestore._initializeStream]: Received stream end  
Firestore (3.4.0) 2020-01-22T09:02:48.950Z JK98a [Firestore.requestStream]: Received response: {"document":{}},"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1579683768","nanos":891411000},"skippedResults":0}  
Firestore (3.4.0) 2020-01-22T09:02:48.951Z JK98a [Firestore._initializeStream]: Releasing stream  
Firestore (3.4.0) 2020-01-22T09:02:48.951Z JK98a [Firestore._initializeStream]: Received stream end  
Firestore (3.4.0) 2020-01-22T09:02:48.952Z CE47t [Firestore.runTransaction]: Rolling back transaction after callback error: { error: Abort {},  
hooks: { abort: [], failure: [], success: [] } }  
Firestore (3.4.0) 2020-01-22T09:02:48.952Z CE47t [ClientPool.acquire]: Re-using existing client with 100 remaining operations  
Firestore (3.4.0) 2020-01-22T09:02:48.952Z CE47t [Firestore.request]: Sending request: {"database":"projects/<project-id>/databases/(default)","transaction":{"type":"Buffer","data":[]}}  
Firestore (3.4.0) 2020-01-22T09:02:49.559Z CE47t [Firestore.request]: Received response: {}  

@schmidt-sebastian
Copy link
Contributor

Sorry for the lack of responses. We have had a holiday weekend here and are still digging out from our emails. I will re-open this and we will try to find a fix as soon as we can.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api: firestore Issues related to the googleapis/nodejs-firestore API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.
Projects
None yet
4 participants