[SERVER-62685] WiredTigerIdIndex has write conflict when prepared transaction is aborted and immediately retried Created: 16/Jan/22  Updated: 29/Oct/23  Resolved: 22/Feb/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 5.3 Required
Fix Version/s: 5.3.0-rc1

Type: Bug Priority: Major - P3
Reporter: Andrew Shuvalov (Inactive) Assignee: Andrew Morton
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File bad.json     File debug.diff     File ok.json     File test.js    
Issue Links:
Depends
depends on WT-8753 Add tombstone when rolling back in-me... Closed
Related
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

The error is reproducible. Diff:

diff --git a/jstests/core/txns/commit_prepared_transaction_errors.js b/jstests/core/txns/commit_prepared_transaction_errors.js
index 64b27f3c16c..9fee9fd7870 100644
--- a/jstests/core/txns/commit_prepared_transaction_errors.js
+++ b/jstests/core/txns/commit_prepared_transaction_errors.js
@@ -23,6 +23,10 @@ const doc = {
     _id: 1
 };
 
+const ITERS=1000;
+for (var i=0; i<ITERS; i++) {
+jsTestLog("ITERATION " + i);
+
 jsTestLog("Test committing a prepared transaction with no 'commitTimestamp'.");
 session.startTransaction();
 assert.commandWorked(sessionColl.insert(doc));
@@ -69,4 +73,6 @@ jsTestLog("Test committing an unprepared transaction with an invalid 'commitTime
 session.startTransaction();
 assert.commandWorked(sessionColl.insert(doc));
 assert.commandFailedWithCode(PrepareHelpers.commitTransaction(session, 5), ErrorCodes.TypeMismatch);
+
+}
 }());

Participants:
Case:
Linked BF Score: 19

 Description   

The commit_prepared_transaction_errors.js test is reproducing the situation when a prepared transaction fails because it has no commitTimestamp and then is aborted with `abortTransaction_forTesting()`. The next transaction started for the same data entry fails in WiredTigerIdIndex::_insert with:

"WiredTigerIdIndex::_insert: index: _id_; uri: table:index-161--1657325371758770379 :: caused by :: WriteConflict

I verified that the conflict happens in the C-level code `__wt_cursor int __F(insert)(WT_CURSOR *cursor)`. I verified that the `WiredTigerItem keyItem` passed to both transactions is identical, so almost certainly it means the previous index key was not removed from WT table when the transaction abort already returned.



 Comments   
Comment by Andrew Morton [ 22/Feb/22 ]

Thanks andrew.shuvalov!

Comment by Andrew Shuvalov (Inactive) [ 22/Feb/22 ]

Hi andrew.morton, conservatively speaking the repro I attached in the description was reproducing the problem with 50% probability. I've run it 8 times without failure with the probability that the bug is actually fixed 99.6%. This is ~3 standard deviations so consider it done. Thanks a lot!

Comment by Andrew Morton [ 31/Jan/22 ]

Thanks gregory.wlodarek! With your success/failure examples I can create a WiredTiger replicator that shows the same results.
It's weirdly consistent and almost always fails on the 1088th iteration which will be fun to investigate, and only occurs when WiredTiger is in-memory.
WT-8753 has been created for further investigation.

Comment by Gregory Wlodarek [ 27/Jan/22 ]

Yes, tammy.bailey, it would be helpful to see what's happening in the WiredTiger layer. I'll assign this to the Storage Engines backlog. I'm happy to work with whoever picks this up.

Comment by Daniel Gottlieb (Inactive) [ 27/Jan/22 ]

That debugging information is great gregory.wlodarek!

What you observed in the failure case does not jive with my understanding of rolling back a transaction. To my knowledge, rolling back a transaction sets the txnid to -1 on every update. I expect that's associated with the log line (trimmed):

{"msg":"WiredTiger message","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}

Meaning the WT_UPDATE structure should no longer remember the value 3236. We can (indirectly) observe that by rolling back a conflicting write after a second writer has begun its transaction:

| W1         | W2        |
|------------+-----------|
| Begin      |           |
| Write A 1  |           |
|            | Begin     |
| Rollback   |           |
|            | Write A 2 |
|            | Commit    |
| Begin      |           |
| Read A (2) |           |

To be clear, this example is more extreme than what your experiment was observing. In your case "W2"'s begin_transaction happens after the rollback of "W1".

I agree with gregory.wlodarek's assessment this seems to be a data race.

Comment by Tammy Bailey (Inactive) [ 27/Jan/22 ]

gregory.wlodarek I'm fairly certain this is not a known issue. Please let me know if it would be helpful for one of our team to work with you on this!

Comment by Gregory Wlodarek [ 26/Jan/22 ]

I took a more in-depth look at this today and here are my findings.

Timeline for a successful execution:

(1) Create a collection (with an _id index).
 
(2) Start a transaction, do an insert and prepare.
    - WT_SESSION::begin_transaction() 
        - {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x5587763a6710","snapshotId":311}}
    - insert {_id: 1}
    - WT_SESSION::prepare_transaction()
        - {"msg":"(1) WT_SESSION::prepare_transaction","attr":{"config":"prepare_timestamp=61F188A20000001B","session":"0x5587763a6710","snapshotId":311,"prepTS":{"$timestamp":{"t":1643219106,"i":27}}}}
        - {"msg":"(2) WT_SESSION::prepare_transaction","attr":{"session":"0x5587763a6710"}}
 
(3) Try to insert {_id: 1} in another transaction. 
    - WT_SESSION::begin_transaction()
        - {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x5587763a6af8","snapshotId":327}}
    - insert {_id: 1} --> WT_ROLLBACK (write conflict)
    - WT_SESSION::rollback_transaction()
        - {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x5587763a6af8","snapshotId":327}}
        - {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x5587763a6af8"}}
    - User gets an error (expected) 
        - {"msg":"User assertion","attr":{"error":"WriteConflict: WiredTigerIdIndex::_insert: index: _id_; uri: table:index-41-531312270660082275 :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."}}
 
(4) Abort the prepared transaction from (2).
    - {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x5587763a6710","snapshotId":311}}
    - {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219106,"ts_usec":557843,"thread":"11558:0x7f26c928d700","session_dhandle_name":"file:index-41-531312270660082275.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 176and timestamp:(1643219106, 27)"}}}
    - {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219106,"ts_usec":557874,"thread":"11558:0x7f26c928d700","session_dhandle_name":"file:collection-40-531312270660082275.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 176and timestamp:(1643219106, 27)"}}}
    - {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x5587763a6710"}}
 
(5) Start a transaction, do an insert, and abort.
    - WT_SESSION::begin_transaction()
        - {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x5587763a6710","snapshotId":345}}
    - insert {_id: 1}
    - WT_SESSION::rollback_transaction()
        - {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x5587763a6710","snapshotId":345}}
        - {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x5587763a6710"}}

Timeline for a failed execution:

(1) Create a collection (with an _id index).
 
(2) Start a transaction, do an insert and prepare.
    - WT_SESSION::begin_transaction() 
        - {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x55a07bd6e710","snapshotId":27179}}
    - insert {_id: 1}
    - WT_SESSION::prepare_transaction()
        - {"msg":"(1) WT_SESSION::prepare_transaction","attr":{"config":"prepare_timestamp=61F189A800000091","session":"0x55a07bd6e710","snapshotId":27179,"prepTS":{"$timestamp":{"t":1643219368,"i":145}}}}
        - {"msg":"(2) WT_SESSION::prepare_transaction","attr":{"session":"0x55a07bd6e710"}}
 
(3) Try to insert {_id: 1} in another transaction. 
    - WT_SESSION::begin_transaction()
        - {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x55a07bd6eaf8","snapshotId":27199}}
    - insert {_id: 1} --> WT_ROLLBACK (write conflict)
    - WT_SESSION::rollback_transaction()
        - {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x55a07bd6eaf8","snapshotId":27199}}
        - {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x55a07bd6eaf8"}}
    - User gets an error (expected) 
        - {"msg":"User assertion","attr":{"error":"WriteConflict: WiredTigerIdIndex::_insert: index: _id_; uri: table:index-41-5942478661676268792 :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."}}
 
(4) Abort the prepared transaction from (2).
    - {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x55a07bd6e710","snapshotId":27179}} 
    - {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":313459,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}
    - {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":313538,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:collection-40-5942478661676268792.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}
    - {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x55a07bd6e710"}}
 
(5) Start a transaction, do an insert, hit an unexpected write conflict.
    - WT_SESSION::begin_transaction()
        - {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x55a07bd6e710","snapshotId":27217}}
    - insert {_id: 1} --> WT_ROLLBACK (write conflict, unexpected)
        - {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315338,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"Conflict with update 3236 at start timestamp: (1643219368, 145)"}}}
        - {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315368,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"snapshot_min=3240, snapshot_max=3240, snapshot_count=0"}}}
        - {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315384,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"Rollback reason: conflict between concurrent operations"}}}
    - WT_SESSION::rollback_transaction()
        - {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x55a07bd6e710","snapshotId":27217}}
        - {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x55a07bd6e710"}}
    - User gets an error (unexpected)
        - {"msg":"User assertion","attr":{"error":"WriteConflict: WiredTigerIdIndex::_insert: index: _id_; uri: table:index-41-5942478661676268792 :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."}}

 

In the failed execution, on step (4), we see that the prepared transaction gets rolled back:

{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":313459,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}
{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":313538,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:collection-40-5942478661676268792.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}

 

But in step (5), when trying to index the record, we run into a write conflict of what was already rolled back:

{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315338,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"Conflict with update 3236 at start timestamp: (1643219368, 145)"}}}
{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315368,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"snapshot_min=3240, snapshot_max=3240, snapshot_count=0"}}}
{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315384,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"Rollback reason: conflict between concurrent operations"}}}

 

 

This is what caused the test to fail. We begin a new transaction in step (5) after rolling back in step (4) and hit an unexpected prepare conflict. Could we be hitting some sort of race in WiredTiger? I've only been able to reproduce this on an optimized build while running WiredTiger in-memory mode after ~500-750 executions of the attached test.

I attached more verbose logging and a git diff with my debug logging. It can be run using this command:

python3 buildscripts/resmoke.py --storageEngine=inMemory --suites=core_txns jstests/core/txns/commit_prepared_transaction_errors.js

 

I should also point out that if step (3) is removed ("Block 2" in the attached jstest), this is no longer reproducible.

 

Comment by Gregory Wlodarek [ 25/Jan/22 ]

I've only been able to reproduce this when WiredTiger is running in-memory. The BF has also been failing on the in-memory variant only.

Using the provided test diff, I ran the test using this command:

python3 buildscripts/resmoke.py --storageEngine=inMemory --suites=logical_session_cache_replication_1sec_refresh_jscore_passthrough --repeatTests=50 jstests/core/txns/commit_prepared_transaction_errors.js

wiredtiger-escalation are there any known issues that could explain this behaviour?

Comment by Louis Williams [ 18/Jan/22 ]

Is this maybe related to WT-8461?

Generated at Thu Feb 08 05:55:47 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.