Google-cloud-node: spanner: Transaction was aborted. It was wounded by a higher priority transaction due to conflict on keys in range

[Chipintoza]

Environment details

• OS: Mac OS Siera 10.12.3
• Node.js 6.9.3:
• npm version: 3.19.19
• google-cloud-node version:
  "@google-cloud/spanner":"^0.3.0",
  "@google-cloud/datastore":"^0.7.0",

I have Users Table:

CREATE TABLE Users (
    userId STRING(36) NOT NULL,
    contactName STRING(300) NOT NULL,
    created INT64 NOT NULL,
    eMail STRING(100) NOT NULL,
    environmentsIds ARRAY<STRING(36)> NOT NULL,
    envLanguage STRING(3) NOT NULL,
    facebookName STRING(300) NOT NULL,
    facebookPictureUrl STRING(2000) NOT NULL,
    facebookProfile STRING(2000) NOT NULL,
    googleName STRING(300) NOT NULL,
    googlePictureUrl STRING(2000) NOT NULL,
    googleProfile STRING(2000) NOT NULL,
    gssClientID STRING(36),
    gssGroupID STRING(36) NOT NULL,
    isActive BOOL,
    mobile STRING(30) NOT NULL,
    modifierId STRING(36) NOT NULL,
    modifierName STRING(300) NOT NULL,
    note STRING(MAX) NOT NULL,
    photoID STRING(36),
    purchasedServicesCasheExpiryDateString STRING(MAX),
    registered BOOL NOT NULL,
    signedInBy STRING(20) NOT NULL,
    timestamp INT64 NOT NULL,
    timeZoneID STRING(100) NOT NULL,
    webBrowserID STRING(36),
) PRIMARY KEY (userId)

first i check user on database and then do upsert

database.runTransaction((err, tx) => {
    if (err) {
    ... error
    }

    tx.run(`SELECT * FROM Users WHERE eMail = '${user.eMail}' AND isActive = TRUE`,
        (err, rows) => {
            if (err) {
            ... log error
            }
            ...
            console.log('-- upsert - userId = ' + ola.userId + ' - isActive = ' + ola.isActive);
            tx.upsert("Users", user);
            ...
            tx.commit((err, apiResponse) => {
                if (err) {
                ... log error
                }
                console.log('commited - userId = ' + user.userId);
            }

When i call many requests at same time - a Error occurs:

Error occurred on sometime on - select sometime on - commit
log:

http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = a3e85cdf-9a79-4940-8ac0-075a344a5db3 - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = ef62be27-b553-4b4f-ba45-11cdb4785713 - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = ac48ad39-45ce-4102-948b-11af2ddd4659 - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 04d9c1a2-66ff-4fa1-9388-17dfd20dac1c - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = e40881d1-e3be-438b-89a7-48124ccd12e5 - isActive = true
-- upsert - userId = a3e85cdf-9a79-4940-8ac0-075a344a5db3 - isActive = true
-- upsert - userId = ef62be27-b553-4b4f-ba45-11cdb4785713 - isActive = true
-- upsert - userId = 04d9c1a2-66ff-4fa1-9388-17dfd20dac1c - isActive = true
-- upsert - userId = e40881d1-e3be-438b-89a7-48124ccd12e5 - isActive = true
-- upsert - userId = ac48ad39-45ce-4102-948b-11af2ddd4659 - isActive = true
commited - userId = ef62be27-b553-4b4f-ba45-11cdb4785713
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 13a0f431-2451-4e20-a6bd-5e7e7bb644fe - isActive = true
-- upsert - userId = 13a0f431-2451-4e20-a6bd-5e7e7bb644fe - isActive = true
commited - userId = 13a0f431-2451-4e20-a6bd-5e7e7bb644fe
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = cd64b4be-217e-41b4-808a-61eb984e30b9 - isActive = true
-- upsert - userId = a3e85cdf-9a79-4940-8ac0-075a344a5db3 - isActive = true
-- upsert - userId = ac48ad39-45ce-4102-948b-11af2ddd4659 - isActive = true
commited - userId = a3e85cdf-9a79-4940-8ac0-075a344a5db3
-- upsert - userId = 04d9c1a2-66ff-4fa1-9388-17dfd20dac1c - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = ebadcf2f-7657-4d08-80f5-72af47c30d5e - isActive = true
-- upsert - userId = e40881d1-e3be-438b-89a7-48124ccd12e5 - isActive = true
commited - userId = e40881d1-e3be-438b-89a7-48124ccd12e5
-- upsert - userId = cd64b4be-217e-41b4-808a-61eb984e30b9 - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 126e9b3d-3f60-4731-9bcd-7b79f2b86480 - isActive = true
-- upsert - userId = ebadcf2f-7657-4d08-80f5-72af47c30d5e - isActive = true
commited - userId = cd64b4be-217e-41b4-808a-61eb984e30b9
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 9f9cec23-121d-466a-b747-89685acc6e8e - isActive = true
-- upsert - userId = 126e9b3d-3f60-4731-9bcd-7b79f2b86480 - isActive = true
-- upsert - userId = ac48ad39-45ce-4102-948b-11af2ddd4659 - isActive = true
commited - userId = ac48ad39-45ce-4102-948b-11af2ddd4659
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = e6ec38c9-24e5-4497-8303-90b994a7c916 - isActive = true
-- upsert - userId = 9f9cec23-121d-466a-b747-89685acc6e8e - isActive = true
commited - userId = 9f9cec23-121d-466a-b747-89685acc6e8e
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 889df848-9a2e-4ed9-8126-a45c0c33a101 - isActive = true
-- upsert - userId = ebadcf2f-7657-4d08-80f5-72af47c30d5e - isActive = true
commited - userId = ebadcf2f-7657-4d08-80f5-72af47c30d5e
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = f7405e25-e78c-4d81-b3ed-bace7490ef20 - isActive = true
-- upsert - userId = 04d9c1a2-66ff-4fa1-9388-17dfd20dac1c - isActive = true
-- upsert - userId = e6ec38c9-24e5-4497-8303-90b994a7c916 - isActive = true
commited - userId = 04d9c1a2-66ff-4fa1-9388-17dfd20dac1c
-- upsert - userId = 126e9b3d-3f60-4731-9bcd-7b79f2b86480 - isActive = true
-- upsert - userId = 889df848-9a2e-4ed9-8126-a45c0c33a101 - isActive = true
-- upsert - userId = f7405e25-e78c-4d81-b3ed-bace7490ef20 - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 1e62b2fd-5170-45a5-a139-bf58389cec46 - isActive = true
commited - userId = 126e9b3d-3f60-4731-9bcd-7b79f2b86480
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 25eadd95-0960-412f-9706-c57c05c1f903 - isActive = true
-- upsert - userId = 1e62b2fd-5170-45a5-a139-bf58389cec46 - isActive = true
commited - userId = 1e62b2fd-5170-45a5-a139-bf58389cec46
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = f43adb89-f0fc-4898-b367-c6d6fe2795da - isActive = true
-- upsert - userId = e6ec38c9-24e5-4497-8303-90b994a7c916 - isActive = true
commited - userId = e6ec38c9-24e5-4497-8303-90b994a7c916
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 140da3b6-f213-4627-938a-d3b93f6f101f - isActive = true
-- upsert - userId = 25eadd95-0960-412f-9706-c57c05c1f903 - isActive = true
commited - userId = 25eadd95-0960-412f-9706-c57c05c1f903
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 29d6dc5e-a1bb-4390-948b-d417db53537b - isActive = true
-- upsert - userId = f7405e25-e78c-4d81-b3ed-bace7490ef20 - isActive = true
-- upsert - userId = f43adb89-f0fc-4898-b367-c6d6fe2795da - isActive = true
-- upsert - userId = 889df848-9a2e-4ed9-8126-a45c0c33a101 - isActive = true
commited - userId = 889df848-9a2e-4ed9-8126-a45c0c33a101

req.url - http://chipintozamac.local:9001/gss-api/users/upsert
InternalServerError: err.code: 10
err.message: Transaction was aborted. It was wounded by a higher priority transaction due to conflict on keys in range [[889df848-9a2e-4ed9-8126-a45c0c33a101], [889df848-9a2e-4ed9-8126-a45c0c33a101]), column isActive in table users.
err.status: undefined
err location:
User.upsert\select Users...eMail...
data:
{"userId":"140da3b6-f213-4627-938a-d3b93f6f101f","isActive":true,"created":1384853268917,"timestamp":1491156814361,"modifierId":"system-id","modifierName":"system","eMail":"[email protected]","contactName":"ka:ალექსანდრე მიულერი","mobile":"","webBrowserID":"8a0d1345-d688-43eb-8f48-a3239aae23f0","photoID":null,"gssGroupID":"0267345b-a116-4879-9990-81f22d1db9ad","timeZoneID":"Georgian Standard Time","gssClientID":null,"purchasedServicesCasheExpiryDateString":"{\"B09DE416-A2EA-4419-B5F0-70B9CE956007\":{\"e9e5b8c9-bc25-4925-9b86-329928c3583e\":\"28/02/2014\"}}","note":"","environmentsIds":[],"googleName":"","googlePictureUrl":"","googleProfile":"","facebookName":"","facebookPictureUrl":"","facebookProfile":"","signedInBy":"eMail","envLanguage":"ka","registered":false}
apiResponse:

    at Object.getDsError (/Users/Chipintoza/GSS Projects/accounts.gss.ge/server/node_modules/database-utils.js:186:20)
    at error (/Users/Chipintoza/GSS Projects/accounts.gss.ge/server/tables/system/users-table.js:924:64)
    at DestroyableTransform.tx.run.err (/Users/Chipintoza/GSS Projects/accounts.gss.ge/server/tables/system/users-table.js:947:35)
    at emitOne (events.js:101:20)
    at DestroyableTransform.emit (events.js:188:7)
    at /Users/Chipintoza/GSS Projects/accounts.gss.ge/node_modules/through2/through2.js:19:12
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)
-- upsert - userId = 29d6dc5e-a1bb-4390-948b-d417db53537b - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 2b264cff-5a31-4481-97ce-d7da401a0db2 - isActive = true
commited - userId = 29d6dc5e-a1bb-4390-948b-d417db53537b
-- upsert - userId = f43adb89-f0fc-4898-b367-c6d6fe2795da - isActive = true
commited - userId = f43adb89-f0fc-4898-b367-c6d6fe2795da
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 094d4afd-2ce9-464e-9fd3-e7e6efbd0401 - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 22a4305a-6670-4de2-8de0-eeed85fe4227 - isActive = true
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = 92545fa4-356e-4219-881c-fddae5be8888 - isActive = true
-- upsert - userId = 2b264cff-5a31-4481-97ce-d7da401a0db2 - isActive = true
commited - userId = 2b264cff-5a31-4481-97ce-d7da401a0db2
http://chipintozamac.local:9001/gss-api/users/upsert
post - userId = bab0f638-55c5-4c8d-b2bc-ff1462dc77cf - isActive = true
-- upsert - userId = 094d4afd-2ce9-464e-9fd3-e7e6efbd0401 - isActive = true
-- upsert - userId = 22a4305a-6670-4de2-8de0-eeed85fe4227 - isActive = true
-- upsert - userId = 92545fa4-356e-4219-881c-fddae5be8888 - isActive = true
-- upsert - userId = f7405e25-e78c-4d81-b3ed-bace7490ef20 - isActive = true

req.url - http://chipintozamac.local:9001/gss-api/users/upsert
InternalServerError: err.code: 10
err.message: Transaction was aborted. It was wounded by a higher priority transaction due to conflict on keys in range [[92545fa4-356e-4219-881c-fddae5be8888], [92545fa4-356e-4219-881c-fddae5be8888]), column isActive in table users.
err.status: undefined
err location:
User.upsert\select Users...eMail...
data:
{"userId":"bab0f638-55c5-4c8d-b2bc-ff1462dc77cf","isActive":true,"created":1384507909720,"timestamp":1491156817894,"modifierId":"system-id","modifierName":"system","eMail":"[email protected]","contactName":"ka:თინათინ ცირეკიძე|ru:Тинатин Цирекидзе","mobile":"995 32 555333350","webBrowserID":"534474e9-6e05-4f03-9dda-441933797cff","photoID":"ba34529c-955f-4fa3-be23-873fcdc6a8fe","gssGroupID":"0267345b-a116-4879-9990-81f22d1db9ad","timeZoneID":"Georgian Standard Time","gssClientID":null,"purchasedServicesCasheExpiryDateString":"{\"40454df0-59ed-4e11-a914-4340bc97cbf6\":{\"e9e5b8c9-bc25-4925-9b86-329928c3583e\":\"28/02/2014\"},\"b97e23bf-07a5-4ad4-b925-2b8003e971cc\":{}}","note":"","environmentsIds":[],"googleName":"","googlePictureUrl":"","googleProfile":"","facebookName":"","facebookPictureUrl":"","facebookProfile":"","signedInBy":"eMail","envLanguage":"ka","registered":false}
apiResponse:

    at Object.getDsError (/Users/Chipintoza/GSS Projects/accounts.gss.ge/server/node_modules/database-utils.js:186:20)
    at error (/Users/Chipintoza/GSS Projects/accounts.gss.ge/server/tables/system/users-table.js:924:64)
    at DestroyableTransform.tx.run.err (/Users/Chipintoza/GSS Projects/accounts.gss.ge/server/tables/system/users-table.js:947:35)
    at emitOne (events.js:101:20)
    at DestroyableTransform.emit (events.js:188:7)
    at /Users/Chipintoza/GSS Projects/accounts.gss.ge/node_modules/through2/through2.js:19:12
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)
commited - userId = f7405e25-e78c-4d81-b3ed-bace7490ef20
-- upsert - userId = 22a4305a-6670-4de2-8de0-eeed85fe4227 - isActive = true
-- upsert - userId = 92545fa4-356e-4219-881c-fddae5be8888 - isActive = true
commited - userId = 92545fa4-356e-4219-881c-fddae5be8888
-- upsert - userId = 094d4afd-2ce9-464e-9fd3-e7e6efbd0401 - isActive = true
commited - userId = 094d4afd-2ce9-464e-9fd3-e7e6efbd0401
-- upsert - userId = 22a4305a-6670-4de2-8de0-eeed85fe4227 - isActive = true
commited - userId = 22a4305a-6670-4de2-8de0-eeed85fe4227

when selecting - "userId":"140da3b6-f213-4627-938a-d3b93f6f101f"
error is:
conflict on keys in range [[889df848-9a2e-4ed9-8126-a45c0c33a101], [889df848-9a2e-4ed9-8126-a45c0c33a101]), column isActive in table users

if i remove
tx.run(SELECT * FROM ${tableName} WHERE eMail = '${user.eMail}' AND isActive = TRUE,
(err, rows) =>

everything is ok

Thank you

[Chipintoza]

when i change select by userId (primary key) Condition everything is ok
SELECT * FROM Users WHERE userId = '${user.id}'
I wonder what's going on.
I have same issues with other tables and transaction :( ...

[lukesneeringer]

I am amused by "it was wounded" as part of the error message. :-p

My best assessment here is that this is the API working in the way it is supposed to work. Think about transactions: they are concurrent groups of reads and writes on the same data. If you are running concurrent transactions on the same data and the database can not figure out how to resolve the conflict, then you are going to get an error like the one you see here.

If you think this is still a bug, I recommend opening a ticket with the support for the API itself. This repository is for the client library specifically, but you are getting a backend API error.

[Chipintoza]

@lukesneeringer
Sorry for my english i just use google translate :)

I open one transaction by - database.runTransaction((err, tx)
all reads and writes i am doing by tx.

"they are concurrent groups of reads and writes on the same data"

what you meen by groups? inside two transaction i read and write difference records you can see this in log (there are difference userId)

when i select by eMail - spanner start look all records in transaction and that this may be the cause???

Thank you

[Chipintoza]

According this spanner must resolve:
https://cloud.google.com/spanner/docs/transactions#rw_transaction_interface

When you use a transaction in the Cloud Spanner API, you define the body of a transaction (i.e., the reads and writes to perform on one or more tables in a database) in the form of a function object. Under the hood, Cloud Spanner runs the function repeatedly until the transaction commits or a non-retryable error is encountered.

[vkedia]

@Chipintoza You are right. The client should retry on such errors and they should not be propagated up to the user.
@lukesneeringer @callmehiphop @stephenplusplus This might be a bug in the retry logic in the client.

[vkedia]

@lukesneeringer wounded refers to the standards "wound and wait" algorithm used by Cloud Spanner to resolve deadlocks:
https://cloud.google.com/spanner/docs/transactions#rw_transaction_performance

[callmehiphop]

@vkedia I suspect this is because we implemented a custom backoff for retrying transactions, we may be giving up too soon. @landrito do we know if the retry info is accessible from grpc/gapic yet? I think at the time we were implementing this it was not available

[vkedia]

@callmehiphop irrespective of how we compute the backoff, we should still retry till the user specified deadline and after that we should fail with deadline exceeded rather than the abort error.
Another possibility is that one of the read/query methods in the transaction fails with ABORTED error. How do we handle that? Do we just bubble that up to the user? We need to retry the transaction in that case as well just like we do if commit fails with aborted.

[Chipintoza]

@lukesneeringer i do not know what meens - priority: p2
i need to export some data into spanner and I would be grateful if you'll quickly correct.

I have one questions:
if i have Table
Table

CREATE TABLE Users (
    userId STRING(36) NOT NULL,
    contactName STRING(300) NOT NULL,
    eMail STRING(100) NOT NULL,
    ....
) PRIMARY KEY (userId)

and secondary index

CREATE NULL_FILTERED INDEX ActiveUsersByEMail 
ON Users (
    eMail,
    isActive,
)

and i select record by:
SELECT * FROM Users WHERE eMail = '[email protected]' AND isActive = TRUE

spanner will automatically look at index, take userId and give me a record ?.

or i need to create

CREATE NULL_FILTERED INDEX ActiveUsersByEMail_01 
ON Users (
    eMail,
    isActive,
    userId
)

and first take userId by:
`SELECT userId from Users@{FORCE_INDEX=ActiveUsersByEMail_01} WHERE eMail = '[email protected]' AND isActive = TRUE``

and then i take a record by:
`SELECT * FROM Users WHERE userId = '${userId}'``

Question is automatically use or not spanner secondary indices for standard select if condition match secondary index keys?

Thank you

[vkedia]

You do not need to explicitly store userId in the index since spanner indexes contain all key columns. But you do need to add the FORCE_INDEX directive to your query. So your query would be:

SELECT * FROM Users@{FORCE_INDEX=ActiveUsersByEMail}
 WHERE eMail = '[email protected]' AND isActive = TRUE

This page talks more about indexes
https://cloud.google.com/spanner/docs/secondary-indexes

[vkedia]

@callmehiphop @lukesneeringer Any updates here. I agree with @Chipintoza here that the whole point of runTransaction is that it should automatically retry on such errors and this kind of error should never be bubbled up to the user.

[Chipintoza]

@vkedia thank you very much

[stephenplusplus]

I think Dave is still waiting on some info from @landrito: https://github.com/GoogleCloudPlatform/google-cloud-node/issues/2176#issuecomment-291223307

[callmehiphop]

@vkedia actually I think it is retrying, however I'm guessing it was assumed that the retry info would be available from gRPC (which it is not) and I did not know that we would need to throw a different error after the deadline was exceeded. We need some changes to this code for sure, however if retry info is coming to gRPC soon then I'd think that we could punt on this.

[Chipintoza]

Tank you, @stephenplusplus @vkedia
Please look at #2356