Found uncommitted sync transactions from other instance with id 1

[rosik]

Bug description

While debugging a test we've encountered the error:

Found uncommitted sync transactions from other instance with id 1

It appears after the instance is restarted with an uncommitted sync transaction, during another transaction to a local space.

It looks related to #5440. We don't have to wait for rw, but we wait for leaving orphan mode.

Tarantool version: 2.10.0-29-g1ec2a9d15

Steps to reproduce

I only have a picodata-based repro: https://git.picodata.io/picodata/picodata/picodata/-/issues/129

The test is flaky. Sometimes it also reproduces another problem - #7590.

[sergos]

The problem is node #3 (the i2 in the log) is starting with RAFT disabled, hence making some transaction, while it receives message that the node 1 is a leader in the current term 4:

*** i2  | 2022-10-19 15:17:40.462 [40236] main/123/applier/127.0.0.1:3301 I> RAFT: message {term: 4, vote: 1, leader: 1, state: leader} from 1                                                            
*** i2  | 2022-10-19 15:17:40.462 [40236] main/123/applier/127.0.0.1:3301 I> RAFT: vote request is skipped - RAFT is disabled                                      
i2  | 2022-10-19 15:17:40.462 [40236] main/111/raft_main_loop V> persisted index 14, raft_id: 3                                                                    
i3  | 2022-10-19 15:17:40.462 [40154] main/145/main V> Sending from 2 to 1, msg: msg_type: MsgAppendResponse to: 1 index: 14 commit: 13, to: 1, from: 2, raft_id: 2
i1  | 2022-10-19 15:17:40.462 [40144] relay/127.0.0.1:42662/101/main I> recover from `/tmp/pytest-of-root/pytest-3/test_2_of_3_writable0/i1/00000000000000000000.xlog'
i1  | 2022-10-19 15:17:40.463 [40144] main/239/main V> committing index 14, index: 14, raft_id: 1                                                             
i3  | 2022-10-19 15:17:40.463 [40154] main/116/raft_main_loop V> persisted index 14, raft_id: 2                                                                        
i2  | 2022-10-19 15:17:40.463 [40236] main/122/applier/127.0.0.1:3303 I> RAFT: message {term: 4, vote: 1, leader: 1, leader is seen: true, state: follower} from 2     
i2  | 2022-10-19 15:17:40.463 [40236] main/122/applier/127.0.0.1:3303 I> RAFT: vote request is skipped - RAFT is disabled                                     
i1  | 2022-10-19 15:17:40.463 [40144] main/239/main V> Sending from 1 to 2, msg: msg_type: MsgAppend to: 2 log_term: 2 index: 14 commit: 14, to: 2, from: 1, raft_id: 1                               
i1  | 2022-10-19 15:17:40.463 [40144] main/239/main V> Sending from 1 to 3, msg: msg_type: MsgAppend to: 3 log_term: 2 index: 14 commit: 14, to: 3, from: 1, raft_id: 1                               
i3  | 2022-10-19 15:17:40.464 [40154] relay/127.0.0.1:44124/101/main I> recover from `/tmp/pytest-of-root/pytest-3/test_2_of_3_writable0/i3/00000000000000000018.xlog'                                
i2  | 2022-10-19 15:17:40.465 [40236] main/103/interactive V> broadcast, event: raft.status-changed                                                           
i1  | 2022-10-19 15:17:40.465 [40144] main/111/raft_main_loop V> broadcast, event: raft.topology-changed                                                                                              
i2  | 2022-10-19 15:17:40.465 [40236] main/110/main V> Sending from 3 to 1, msg: msg_type: MsgAppendResponse to: 1 index: 14 commit: 14, to: 1, from: 3, raft_id: 3
i3  | 2022-10-19 15:17:40.465 [40154] main/145/main V> Sending from 2 to 1, msg: msg_type: MsgAppendResponse to: 1 index: 14 commit: 14, to: 1, from: 2, raft_id: 2                                   
*** i2  | 2022-10-19 15:17:40.465 [40236] main/111/raft_main_loop node.rs:668 E> Transaction failed: Unknown: Found uncommitted sync transactions from other instance with id 1
i2  | thread 'main' panicked at 'This shouldn't be', src/traft/node.rs:668:9                                                                                                                          
i2  | note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace                                                                           

To avoid such problems you should start node with RAFT enabled, so the node will be readonly if leader is available.

[gmoshkin]

@sergos what do you mean by start node with RAFT enabled, if we start with election_mode = 'manual'? the same error happens

[sergepetrenko]

Found an easy repro for this. Thanks @rosik for the idea on how to reproduce.

-- Instance 1

-- Step 1
box.cfg{
    listen = 3301,
    replication = {
        3301,
        3302,
    },
    replication_synchro_quorum = 3,
    replication_synchro_timeout = 10,
}

-- Step 3
box.schema.user.grant('guest', 'replication')
box.schema.space.create('sync', {is_sync = true}):create_index('pk')
box.schema.space.create('loc', {is_loc = true}):create_index('pk')
box.ctl.promote()

-- Step 5
box.space.sync:replace{1}

-- Instance 2

-- Step 2
box.cfg{
    listen = 3302,
    replication = {
        3301,
        3302,
    },
}

-- Step 4
box.info.synchro.queue.len -- == 0
box.space.loc:replace{2} -- The replace succeeds, while box.info.synchro.queue is empty.

-- Step 6.
box.info.synchro.queue.len -- == 1
box.space.loc:replace{2} -- this fails.

Here's the output of steps 4 and 6 on instance 2:

tarantool> box.info.synchro.queue.len
---
- 0
...

tarantool> box.space.loc:replace{2}
---
- [2]
...

tarantool> box.info.synchro.queue.len
---
- 1
...

tarantool> box.space.loc:replace{2}
---
- error: Found uncommitted sync transactions from other instance with id 1
...

I can't figure out right away if local space writes on replicas should wait for synchronous transaction commit or not, but the issue is here, indeed.

[sergepetrenko]

I can't figure out right away if local space writes on replicas should wait for synchronous transaction commit or not, but the issue is here, indeed.

It seems all writes to local spaces should bypass the synchro queue and commit without waiting. See #7903 (comment)

[Gerold103]

That would violate serializability. The local txns done after the sync ones might depend on the sync ones in data. The rollback is intentional. The only thing which can be "optimized" here safely is commit local txns even if the synchro queue owner is different but the queue has to be empty then.

Note that dependency by data not necessarily is related to MVCC or anything. It can be application-level dependent. For example, consider the pseudocode:

    data = get_data_from_somewhere()
    f1 = fiber.new(function()
        global_space_vinyl:replace(data)
    end)
    f2 = fiber.new(function()
        local_space_cache_memtx:replace(data)
    end)
    fiber.yield()

Here I rely on the current field to yield when both f1 and f2 data are in the WAL queue. I want to be sure that the local txn won't commit if the global one won't too. On the other hand I am ok, if the local one won't commit but the global one will - it is just a cache anyway.

If here the local txn would commit and the global one wouldn't, then I would have invalid cache, but won't know about it (checking result of the replaces won't help - the instance might crash just after the replaces and I won't be able to revert them).

• MVCC won't abort here anything.
• I can't possibly commit them in one txn, because they are of different engines.
• I could commit them one by one, not in parallel, but it would be slower.

[rosik]

Immediate local transactions doesn't violate serializability, the reason is different - bad code (or dirty reads). You've already provided one example of bad code, here is another one, even simpler:

local dirt
box.begin()
dirt = box.space.test:insert({90, "dirty"})
box.rollback()

box.space.test:replace(dirt)

There are a million ways to commit a dirty read at the application level. And MVCC helps eliminating dirty reads quite well. In the end, it all depends on the code the developer wrote, but it's not an excuse for rolling back all subsequent transactions.

[sergepetrenko]

@Gerold103

The only thing which can be "optimized" here safely is commit local txns even if the synchro queue owner is different but the queue has to be empty then.

This optimisation won't be enough: imagine the majority of nodes is lost, leaving some pending transactions in limbo. Imagine also noone rolls back the transactions (because we are going to set replication_synchro_timeout to infinity and deprecate it. To be closer to Raft). We are in a situation when noone is writeable, noone can clear the limbo. But we promised the user that a read-only replica can write to local spaces.

IMO keeping a promise that local spaces can be written to by read-only replicas is more important than breaking serializability in this particular case.

Besides, cross-engine transactions will be implemented soon, AFAICS. And once this is done, you will either place everything you need in one transaction, or use MVCC to prevent consistency violations. Or simply not mix local and synchronous spaces in one transaction.

[Gerold103]

I don't mind whatever solution will be done. Breaking linearization promises or "writing to local spaces" promises. I am not a user anyway. In that case there is probably not much point in blocking async txns too, indeed. They can break the cluster anyway - just make any of them on an outdated leader which didn't discover a new leader yet. Then would mean only sync txns go to the limbo.