Bug #121314 MTS recovery silently skips transactions, leaving holes in gtid_executed
Submitted: 18 Sep 10:03
Reporter: olivia xu Email Updates:
Status: Open Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:8.0.40/5.7.44 OS:Any
Assigned to: CPU Architecture:Any

[18 Sep 10:03] olivia xu
Description:
Affected versions: verified by code inspection in 5.7.44, 8.0.40 and current trunk — the code has been unchanged since the 5.7 MTS recovery implementation, so all 5.7/8.0/9.x releases are affected.

MTS recovery decides, group by group, whether a relay-log transaction must be re-executed or can be skipped, using a bitmap plus a cursor:

* `Relay_log_info::recovery_groups` (the bitmap) is **recomputed from scratch on every `START SLAVE`** by `mts_recovery_groups()`. Slot 0 of the bitmap is the group sitting at the **current LWM** (coordinator checkpoint). A **set** bit means "this group was already executed by some worker in the previous session"; a **clear** bit means "this group is a gap and must be re-executed".
* `Relay_log_info::mts_recovery_index` (the cursor) is the index used by the applier to read that bitmap. It is incremented once per group the applier walks past (5.7 `sql/rpl_slave.cc:5151`, 8.0 `sql/rpl_replica.cc:4728`) and is reset to 0 **only when recovery runs to full completion** (5.7 `rpl_slave.cc:5154`, 8.0 `rpl_replica.cc:4730`).

The invariant this design relies on is: *the bitmap origin and the cursor origin must be the same LWM* — when the applier processes the 1st group after the LWM, the cursor must be 0, because the applier always resumes reading the relay log at the LWM.

`clear_mts_recovery_groups()` (sql/rpl_rli.h, 5.7 line 808) frees the bitmap and zeroes `mts_recovery_group_cnt`, but **does not reset `mts_recovery_index`**:

```cpp
inline void clear_mts_recovery_groups()
{
  if (recovery_groups_inited)
  {
    bitmap_free(&recovery_groups);
    mts_recovery_group_cnt= 0;
    recovery_groups_inited= false;
    // mts_recovery_index is NOT reset
  }
}
```

The full lifecycle of `mts_recovery_index` is: constructor (5.7 sql/rpl_rli.cc:119) → 0; `++` per recovered group; reset to 0 only on full recovery completion. There is no other assignment anywhere (verified in 5.7, 8.0 branch tip and trunk).

Consequently, when the SQL thread stops **in the middle of recovery** and is started again, `mts_recovery_groups()` builds a fresh bitmap whose slot 0 is the group at the *new* LWM, while the cursor still carries its accumulated value `k` from the previous round. The applier then reads `bit[k]` while processing slot 0 — **the whole bitmap is read shifted by `k`**.

The corrupted lookup is consumed in `Log_event::apply_event()` (5.7 sql/log_event.cc:3602, 8.0 sql/log_event.cc:3085):

```cpp
if (rli->is_mts_recovery())
{
  bool skip= bitmap_is_set(&rli->recovery_groups, rli->mts_recovery_index) && ...;
  if (skip)
    DBUG_RETURN(0);              // whole group silently dropped
  else
    DBUG_RETURN(do_apply_event(rli));
}
```

For a gap group at slot 0 whose shifted neighbor at slot `k` is an already-executed group (bit set), `skip` becomes true: the group is dropped **without being applied, without acquiring GTID ownership, without the GTID entering `gtid_executed`, and without any warning or error in the log**. Replication continues and reports healthy; the transaction is lost permanently. Downstream transactions that depend on the lost rows later fail with ER_KEY_NOT_FOUND (1032), or diverge silently.

Already-executed groups shifted into "execute" slots are harmless (the GTID filter skips them), which is why in practice **each misalignment silently loses exactly the one gap group sitting at slot 0** — the loss is narrow and therefore easy to miss.

### Why existing tests do not catch it

A **process restart re-initializes the cursor** in the `Relay_log_info` constructor, so the classic crash-recovery tests (server killed + `START SLAVE UNTIL SQL_AFTER_MTS_GAPS`, e.g. rpl_mts_logical_clock_recovery, rpl_gtid_mts_recovery_with_missing_relay_log) can never see a stale index. The bug requires the SQL thread to stop **without a mysqld restart** (temporary error abort such as lock wait timeout after `slave_transaction_retries` is exhausted, or `STOP SLAVE`), followed by `START SLAVE`, at least twice, with recovery making partial progress in between — a sequence that HA/failure recovery loops perform routinely.

How to repeat:
Deterministic MTR reproducer (debug build; uses only upstream facilities, incl. the existing `set_commit_parent_100` DBUG point also used by rpl_mts_logical_clock tests). Verified failing on an unpatched 5.7.44 debug build; 8.0 is affected by the same code (only the line numbers differ).

**rpl_mts_gtid_gap_v3.test**:

```mtr
# Reproduce a permanent hole in @@GLOBAL.gtid_executed caused by
# Relay_log_info::mts_recovery_index NOT being reset when the MTS recovery
# bitmap is recomputed.
#
#   G1 (UPDATE t1) blocked by slave-local session S1
#   T  (UPDATE t2) blocked by slave-local session S2   (T comes after G1)
#   8 independent INSERTs into t3 commit normally in round 1
#
#   round 1 : G1 and T become gaps, the INSERTs are executed
#   release S1
#   round 2 : recovery applies G1  -> mts_recovery_index becomes 1
#             then hits T          -> ER_LOCK_WAIT_TIMEOUT -> abort
#   release S2
#   round 3 : bitmap recomputed (slot 0 == T) but mts_recovery_index is still 1
#             -> bit[1] (an executed INSERT) is read for T -> T silently skipped
--source include/not_group_replication_plugin.inc
--source include/have_debug.inc
--source include/have_binlog_format_row.inc
--source include/have_gtid.inc
--source include/have_slave_parallel_type_logical_clock.inc
--source include/only_mts_slave_parallel_workers.inc
--source include/not_valgrind.inc
--source include/master-slave.inc

--source include/rpl_connection_slave.inc
CALL mtr.add_suppression("Slave SQL for channel.*Lock wait timeout exceeded");
CALL mtr.add_suppression("worker thread retried transaction");
CALL mtr.add_suppression("Slave SQL thread retried transaction");
CALL mtr.add_suppression("Error running query, slave SQL thread aborted");
CALL mtr.add_suppression("The slave coordinator and worker threads are stopped");
CALL mtr.add_suppression("Slave worker thread has failed to apply an event");
CALL mtr.add_suppression("Recovery from master pos");

--connect (slave_lock2, 127.0.0.1, root, , test, $SLAVE_MYPORT)

--echo # 1. Schema
--source include/rpl_connection_master.inc
CREATE TABLE t1 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB;
CREATE TABLE t2 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB;
CREATE TABLE t3 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB;
INSERT INTO t1 VALUES (1, 0);
INSERT INTO t2 VALUES (1, 0);
--source include/sync_slave_sql_with_master.inc

--echo # 2. Two slave-local sessions take one row lock each
--source include/rpl_connection_slave1.inc
BEGIN;
SELECT * FROM t1 WHERE a = 1 FOR UPDATE;

--connection slave_lock2
BEGIN;
SELECT * FROM t2 WHERE a = 1 FOR UPDATE;

--echo # 3. Master: G1 (blocked), T (blocked), then independent transactions
--source include/rpl_connection_master.inc
--let $debug_point= set_commit_parent_100
--source include/add_debug_point.inc

UPDATE t1 SET b = 1 WHERE a = 1;
UPDATE t2 SET b = 1 WHERE a = 1;

--disable_query_log
--let $i= 1
while ($i <= 8)
{
  --eval INSERT INTO t3 VALUES ($i, $i)
  --inc $i
}
--enable_query_log

--let $debug_point= set_commit_parent_100
--source include/remove_debug_point.inc

--let $master_gtid_executed= `SELECT @@GLOBAL.gtid_executed`
--source include/sync_slave_io_with_master.inc

--echo # 4. Round 1: both G1 and T become gaps
--source include/rpl_connection_slave.inc
--let $slave_sql_errno= convert_error(ER_LOCK_WAIT_TIMEOUT)
--source include/wait_for_slave_sql_error.inc
--let $ge= `SELECT @@GLOBAL.gtid_executed`
--echo # gtid_executed after round 1: $ge

--echo # 5. Release only the first lock (partial progress in round 2)
--source include/rpl_connection_slave1.inc
ROLLBACK;

--echo # 6. Round 2: recovery applies G1 (index becomes 1) then aborts on T
--source include/rpl_connection_slave.inc
--source include/start_slave_sql.inc
--let $slave_sql_errno= convert_error(ER_LOCK_WAIT_TIMEOUT)
--source include/wait_for_slave_sql_error.inc
--let $ge= `SELECT @@GLOBAL.gtid_executed`
--echo # gtid_executed after round 2 (G1 applied, T still missing): $ge

--echo # 7. Release the second lock: nothing blocks T any more
--connection slave_lock2
ROLLBACK;

--echo # 8. Round 3: T must be applied - with the defect it is silently skipped
--source include/rpl_connection_slave.inc
--source include/start_slave_sql.inc

--source include/rpl_connection_master.inc
--source include/sync_slave_sql_with_master.inc

--echo # 9. Verify
--source include/rpl_connection_slave.inc
--let $ge= `SELECT @@GLOBAL.gtid_executed`
--echo # final gtid_executed: $ge

--let $assert_text= slave gtid_executed must contain every master GTID (no gap)
--let $assert_cond= [SELECT GTID_SUBSET("$master_gtid_executed", @@GLOBAL.gtid_executed)] = 1
--source include/assert.inc

--let $assert_text= T (UPDATE t2) must have been applied on the slave
--let $assert_cond= [SELECT b FROM t2 WHERE a = 1] = 1
--source include/assert.inc

--let $diff_tables= master:t1, slave:t1
--source include/diff_tables.inc
--let $diff_tables= master:t2, slave:t2
--source include/diff_tables.inc
--let $diff_tables= master:t3, slave:t3
--source include/diff_tables.inc

--echo # Cleanup
--disconnect slave_lock2
--source include/rpl_connection_master.inc
DROP TABLE t1, t2, t3;
--source include/sync_slave_sql_with_master.inc

--source include/rpl_end.inc
```

**rpl_mts_gtid_gap_v3.cnf** (put alongside the test file in mysql-test/suite/rpl/t/):

```ini
!include include/default_mysqld.cnf
!include include/default_client.cnf

[mysqld.1]
gtid-mode=on
enforce-gtid-consistency=on
log-slave-updates
binlog-format=row
slave-parallel-workers=4
slave-parallel-type=logical_clock

[mysqld.2]
gtid-mode=on
enforce-gtid-consistency=on
log-slave-updates
binlog-format=row
slave-parallel-workers=4
slave-parallel-type=logical_clock
slave-preserve-commit-order=OFF
slave-transaction-retries=1
relay-log-info-repository=FILE
master-info-repository=FILE
innodb-lock-wait-timeout=2
sync-relay-log-info=1
```

### Expected result on an unpatched server

Measured on an unpatched 5.7.44 debug build (GTIDs: 6 = G1, 7 = T, 8..15 = the INSERTs):

| after | gtid_executed on slave | comment |
|---|---|---|
| round 1 | `1-5:8-15` | G1 and T are gaps |
| round 2 | `1-6:8-15` | G1 recovered by the coordinator, `mts_recovery_index` becomes 1; abort on T |
| round 3 | `1-6:8-15` | **T silently skipped** (bitmap recomputed: slot 0 = T, `SKIP_bits={1..8}`, but cursor still 1, so T reads bit[1] = "already executed") |

The final assertions fail: `GTID_SUBSET(master, slave)` is false and `SELECT b FROM t2 WHERE a = 1` returns 0 instead of 1. No error or warning about T is written anywhere. (On 8.0 the same logic applies; line refs: sql/rpl_replica.cc:4728-4730, sql/log_event.cc:3085.)

Suggested fix:
Reset the cursor together with the bitmap, e.g.:

```cpp
inline void clear_mts_recovery_groups()
{
  if (recovery_groups_inited)
  {
    bitmap_free(&recovery_groups);
    mts_recovery_group_cnt= 0;
    mts_recovery_index= 0;          // <-- add this
    recovery_groups_inited= false;
  }
}
```

The bitmap computation in `mts_recovery_groups()` is correct (the per-worker `group_executed` shift window is computed correctly against the new LWM); only the cursor keeps a stale origin. Resetting `mts_recovery_index` wherever the bitmap is cleared (or at the start of `mts_recovery_groups()`) restores the invariant "bitmap origin == cursor origin" for every START SLAVE.