apache / apache/pulsar

[Bug] [Txn] The committed transaction may rollback to OPEN status.

Open
#20,150 1 comment 0 reactions 0 assignees View on GitHub
Stale type/bug
Dominant language
Java
Stars
15.3k
Forks
3.8k
Avg merge
1d 14h
Merged PRs (30d)
160

Description

### Search before asking

- [X] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.

### Version

master.

### Minimal reproduce step

just restart brokers.

### What did you expect to see?

`Committed` transactions can not be rollback to previous status.

### What did you see instead?

Some transactions are `committed` before broker's restart, but become `open` status after the broker is restarted.
I add some logs in broker as follows:
- log found from `broker.out.1`, which is the log logged before restarting broker.
```
2023-04-19T12:18:51,396+0800 [pulsar-io-36-8] DEBUG org.apache.pulsar.broker.service.ServerCnx - Receive add published partition to txn request 2376042138963580900 from /164.90.89.87:33256 with txnId (11,155293), topic: [persistent://test/tb1/testTxn10-partition-7]
2023-04-19T12:18:51,400+0800 [pulsar-io-36-8] DEBUG org.apache.pulsar.broker.service.ServerCnx - Receive add published partition to txn request 2376042138963580901 from /164.90.89.87:33256 with txnId (11,155293), topic: [persistent://test/tb1/testTxn10-partition-8]
2023-04-19T12:18:51,408+0800 [pulsar-io-36-1] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - Append buffer to txn (11,155293)
2023-04-19T12:18:51,408+0800 [pulsar-io-36-37] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - Append buffer to txn (11,155293)
2023-04-19T12:18:51,415+0800 [pulsar-io-36-8] DEBUG org.apache.pulsar.broker.service.ServerCnx - Receive end txn request 2376042138963580907 to transaction meta store TransactionCoordinatorID(id=11) for txnId:(11,155293).
2023-04-19T12:18:51,449+0800 [BookKeeperClientWorker-OrderedExecutor-6-0] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TransactionBufferHandlerImpl - [persistent://test/tb1/testTxn10-partition-7] endTxnOnTopic txnId: [(11,155293)], txnAction: [0]
2023-04-19T12:18:51,449+0800 [BookKeeperClientWorker-OrderedExecutor-6-0] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TransactionBufferHandlerImpl - [persistent://test/tb1/testTxn10-partition-8] endTxnOnTopic txnId: [(11,155293)], txnAction: [0]
2023-04-19T12:18:51,449+0800 [pulsar-io-36-32] DEBUG org.apache.pulsar.broker.service.ServerCnx - [persistent://test/tb1/testTxn10-partition-7] handleEndTxnOnPartition txnId: [(11,155293)], txnAction: [0]
2023-04-19T12:18:51,449+0800 [pulsar-io-36-32] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - Transaction (11,155293) commit on topic persistent://test/tb1/testTxn10-partition-7.
2023-04-19T12:18:51,449+0800 [pulsar-io-36-32] DEBUG org.apache.pulsar.broker.service.ServerCnx - [persistent://test/tb1/testTxn10-partition-8] handleEndTxnOnPartition txnId: [(11,155293)], txnAction: [0]
2023-04-19T12:18:51,449+0800 [pulsar-io-36-32] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - Transaction (11,155293) commit on topic persistent://test/tb1/testTxn10-partition-8.
2023-04-19T12:18:51,508+0800 [BookKeeperClientWorker-OrderedExecutor-6-0] DEBUG org.apache.pulsar.transaction.coordinator.impl.MLTransactionMetadataStore - TxnID : (11,155293) update txn status to COMMITTED
```

- log found from `broker.out`, which is the log logged after restarting broker.
```
2023-04-19T12:19:26,414+0800 [BookKeeperClientWorker-OrderedExecutor-6-0] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TransactionBufferHandlerImpl - [persistent://test/tb1/testTxn10-partition-7] endTxnOnTopic txnId: [(11,155293)], txnAction: [1]
2023-04-19T12:19:26,415+0800 [BookKeeperClientWorker-OrderedExecutor-6-0] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TransactionBufferHandlerImpl - [persistent://test/tb1/testTxn10-partition-8] endTxnOnTopic txnId: [(11,155293)], txnAction: [1]
2023-04-19T12:19:26,415+0800 [pulsar-io-36-54] DEBUG org.apache.pulsar.broker.service.ServerCnx - [persistent://test/tb1/testTxn10-partition-7] handleEndTxnOnPartition txnId: [(11,155293)], txnAction: [1]
2023-04-19T12:19:26,415+0800 [pulsar-io-36-54] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - Transaction (11,155293) abort on topic persistent://test/tb1/testTxn10-partition-7.
2023-04-19T12:19:26,415+0800 [pulsar-io-36-54] DEBUG org.apache.pulsar.broker.service.ServerCnx - [persistent://test/tb1/testTxn10-partition-8] handleEndTxnOnPartition txnId: [(11,155293)], txnAction: [1]
2023-04-19T12:19:26,415+0800 [pulsar-io-36-54] DEBUG org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - Transaction (11,155293) abort on topic persistent://test/tb1/testTxn10-partition-8.
2023-04-19T12:19:26,425+0800 [BookKeeperClientWorker-OrderedExecutor-6-0] DEBUG org.apache.pulsar.transaction.coordinator.impl.MLTransactionMetadataStore - TxnID : (11,155293) update txn status to ABORTED
```

and i found some logs in `TransactionRecoverTrackerImpl`.
```
2023-04-19T12:19:24,745+0800 [transaction_coordinator_TransactionCoordinatorID(id=11)_thread_factory-89-1] DEBUG org.apache.pulsar.broker.transaction.recover.TransactionRecoverTrackerImpl - Append open transaction to timeout tracker, tcId: 11, openTransactions: {155294=1681877941414, 155293=1681877941393}
```
Based on logs above, we can see that the transaction `(11,155293)` is rollback to `open` status, and is aborted due to transaction timeout machanism.
**Important clue: Only the TC log batch write feature is enabled will trigger this problem.**

### Anything else?

_No response_

### Are you willing to submit a PR?

- [ ] I'm willing to submit a PR!

Contributor guide

Open the contributing guide

Research direction

Start with TransactionRecoverTrackerImpl and the transaction coordinator recovery path, focusing on behavior when the TC log batch write feature is enabled. Reproduce the broker restart scenario from the issue and verify that a transaction committed before restart is not recovered as open or subsequently aborted; add or update a regression test if the relevant test location is found.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
28/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.