Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.3.2, 10.4.7
-
None
Description
Problem found during RQG testing on
|
10.4.7 commit 61cc932781cae3864be8f964c3893cfc3f059ff6 2019-07-15
|
|
|
Version: '10.4.7-MariaDB-debug-log' socket: '/home/mleich/Server/10.4/bld_debug/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution
|
2019-07-15 17:38:34 0x7f50803e8700 InnoDB: Assertion failure in file /home/mleich/Server/10.4/storage/innobase/row/row0ins.cc line 267
|
InnoDB: Failing assertion: !cursor->index->is_committed()
|
InnoDB: We intentionally generate a memory trap.
|
...
|
mysys/stacktrace.c:269(my_print_stacktrace)[0x55826a12ba7d]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x13150)[0x7f508da59150]
|
linux/raise.c:51(__GI_raise)[0x7f508cba60bb]
|
stdlib/abort.c:92(__GI_abort)[0x7f508cba7f5d]
|
/home/mleich/Server/10.4/bld_debug/sql/mysqld(+0xf8e65f)[0x55826a58865f]
|
ut/ut0mem.cc:42(ut_strlcpy(char*, char const*, unsigned long))[0x55826a4a2189]
|
row/row0ins.cc:268(row_ins_sec_index_entry_by_modify(unsigned long, unsigned long, btr_cur_t*, unsigned long**, mem_block_info_t*, mem_block_info_t*, dtuple_t const*, que_thr_t*, mtr_t*))[0x55826a4a9b6b]
|
row/row0ins.cc:3133(row_ins_sec_index_entry_low(unsigned long, unsigned long, dict_index_t*, mem_block_info_t*, mem_block_info_t*, dtuple_t*, unsigned long, que_thr_t*, bool))[0x55826a4aa570]
|
row/row0ins.cc:3352(row_ins_sec_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, bool))[0x55826a5198f3]
|
row/row0upd.cc:2516(row_upd_sec_index_entry(upd_node_t*, que_thr_t*))[0x55826a519ade]
|
row/row0upd.cc:2543(row_upd_sec_step(upd_node_t*, que_thr_t*))[0x55826a51c4aa]
|
row/row0upd.cc:3319(row_upd(upd_node_t*, que_thr_t*))[0x55826a51c811]
|
row/row0upd.cc:3434(row_upd_step(que_thr_t*))[0x55826a4cbf36]
|
row/row0mysql.cc:1890(row_update_for_mysql(row_prebuilt_t*))[0x55826a36570a]
|
handler/ha_innodb.cc:8872(ha_innobase::update_row(unsigned char const*, unsigned char const*))[0x55826a140665]
|
sql/handler.cc:6727(handler::ha_update_row(unsigned char const*, unsigned char const*))[0x558269efafcc]
|
sql/sql_update.cc:1045(mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, bool, unsigned long long*, unsigned long long*))[0x558269df61b7]
|
sql/sql_parse.cc:4369(mysql_execute_command(THD*))[0x558269e02819]
|
sql/sql_parse.cc:7908(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558269deeaad]
|
sql/sql_parse.cc:1842(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x558269ded1f2]
|
sql/sql_parse.cc:1359(do_command(THD*))[0x558269f6620e]
|
sql/sql_connect.cc:1404(do_handle_one_connection(CONNECT*))[0x558269f65f5d]
|
sql/sql_connect.cc:1307(handle_one_connection)[0x55826a88f308]
|
nptl/pthread_create.c:465(start_thread)[0x7f508da4d7fc]
|
x86_64/clone.S:97(clone)[0x7f508cc83b5f]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7f5018011440): UPDATE t3 SET col1 = 7 LIMIT 2
|
Connection ID (thread ID): 13
|
Status: NOT_KILLED
|
|
|
No replay on
|
10.3.11commit 07b1a26c33b28812a4fd8c814de0fe7d943bbd6b 2019-07-10
|
|
|
Please note that virtual columns are not involved.
|
Attachments
Issue Links
- is blocked by
-
-
- Closed
-
- is caused by
-
MDEV-11369 Instant add column for InnoDB
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
Activity
The diagnostics for del-mark both in the previous logs and the following log was misleading, because it is not showing the new value of the flag, and it is being displayed even when there is no change.
I analyzed another crash, with an explicit trace of persistent transaction commit (undo_no>0) or rollback (undo_no=0).
Again, we crash on DELETE (transaction 0x57), while other transactions 0x59,0x5a are blocked before making any changes.
And again, the table contents is the same, except for transaction identifiers and undo log pointers.
According to the available information that I gathered from the new crash, the clustered index should have contained the record (7,0) instead of (7,77), after the UPDATE t3 SET col1 = 7, transaction 0x53.
Similarly for the earlier case, the record (0,4) was not delete-marked by the UPDATE (transaction 0x66); it was a null change performed by a rollback that was made due to duplicate primary key. Also in that case, it looks like the clustered index should have contained (7,0) instead of (7,77).
I reran with more diagnostics (also including operations on the clustered index), to get a similar crash again, at DELETE, transaction 0xac. In the undo log record for that transaction, the DB_TRX_ID had been zeroed out by row_purge_reset_trx_id(). I might disable that, so that we can try to cross-reference the undo log records with the diagnostic output.
TL;DR: Here is a deterministic test case that does not repeat any crash, but shows error in CHECK TABLE even with innodb_force_recovery=2 (purge disabled):
--source include/have_innodb.inc
|
CREATE TABLE t1(a INT PRIMARY KEY, b INT NOT NULL) ENGINE=InnoDB; |
INSERT INTO t1 VALUES (7,77); |
|
|
ALTER TABLE t1 DROP COLUMN b, ADD COLUMN c INT NOT NULL DEFAULT 0; |
ALTER TABLE t1 ADD INDEX (c); |
|
|
BEGIN; |
DELETE FROM t1; |
INSERT INTO t1 VALUES (4,0),(7,77); |
COMMIT; |
BEGIN; |
DELETE FROM t1 WHERE a=7; |
UPDATE t1 SET a=7; |
COMMIT; |
DELETE FROM t1; |
CHECK TABLE t1; |
DROP TABLE t1; |
How did I arrive at that?
After disabling row_purge_reset_trx_id(), I can follow the history from the undo log page for failures of mmr_MDEV-20066.test
with btr-instr.patch.
With this crash, the DELETE is transaction 0x64. The record (7,77) was previously updated by the second and last undo log record of transaction 0x5f, which recorded TRX_UNDO_DEL_MARK_REC for (4,0) and TRX_UNDO_UPD_DEL_REC for (7,77) that had been delete-marked by the only undo log record of transaction 0x60, and previously inserted by transaction 0x5e, which is where the history starts by TRX_UNDO_INSERT_REC.
The ADD INDEX (transaction 0x2b) was committed long before 0x5e started. So, the clustered index record with col1=7 must have carried the value col_text=77 from this point on, and a previous entry must have been purged before 0x5e started. The log confirms this: there was a DELETE and purge right before the INSERT.
According to the following, the index did contain a record (col1,col_text)=(4,0) since this point:
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 4 fields): {[1] (0x04),[6] E(0x000000000045),[7] I /(0x9700000149012F),[1] (0x00)} by 0x45,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x45,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x45,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: commit 0x45,2
|
The DB_ROLL_PTR=0x9700000149012F points to the second and last record of a transaction that logged TRX_UNDO_DEL_MARK_REC for col1=7 that had been modified by transaction 0x43, and TRX_UNDO_INSERT_REC for the (4,0). There is a chain of undo log records, pointing to transactions 0x43, 0x40, 0x3d, 0x3b, 0x39, 0x37, 0x35, 0x33, 0x31, 0x2f, 0x24, which was the initial INSERT of the record col1=7 before the ALTER TABLE (0x28 and 0x2b). After the first ALTER, the record should be interpreted as (col1,dropped_col_text,col_text)=(7,77,DEFAULT=0), that is, (7,0).
So, the record value (4,0) after the long chain of UPDATE seems to be legitimate. The original record (7,0) with dropped_col_text=77 was purged already between transaction 0x2f and 0x31:
2019-08-30 11:03:49 9 [Note] InnoDB: insert TUPLE (info_bits=0, 5 fields): {[8] (0x000000000000001A),[4] (0x00000000),[6] +(0x00000000002B),[7] < (0x880000013C029F),[8]col_text(0x636F6C5F74657874)} by 0x2b,ALTER TABLE t3 ADD INDEX uidx3 ( col_text ), ALGORITHM = NOCOPY, LOCK = EXCLUSIVE
|
2019-08-30 11:03:49 9 [Note] InnoDB: commit 0x2b,2
|
2019-08-30 11:03:49 9 [Note] InnoDB: commit 0x2d,1
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 4 fields): {[1] (0x04),[6] /(0x00000000002F),[7] = (0x8A0000013D02D2),[1] (0x00)} by 0x2f,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x2f,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x2f,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: commit 0x2f,2
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x07)}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x07)}:1
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] /(0x00000000002F),[7] = (0x0A0000013D02B3),[1]M(0x4D),DEFAULT}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purged RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] /(0x00000000002F),[7] = (0x0A0000013D02B3),[1]M(0x4D),DEFAULT}
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 4 fields): {[1] (0x07),[6] 1(0x000000000031),[7] > O(0x8B0000013E024F),[1] (0x00)} by 0x31,UPDATE t3 SET col1 = 7
|
Here is the end of the log:
2019-08-30 11:03:50 10 [Note] InnoDB: uip RECORD(info_bits=32, 5 fields): {[1] (0x04),[6] Q(0x000000000051),[7] O (0x1E0000014F0110),[1] (0x00),DEFAULT} to RECORD(info_bits=0, 5 fields): {[1] (0x04),[6] (0x000000000000),[7] (0x80000000000000),[1] (0x00),DEFAULT} by 0x51,UPDATE t3 SET col1 = 7
|
2019-08-30 11:03:50 10 [Note] InnoDB: commit 0x51,0
|
2019-08-30 11:03:50 11 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x55,DELETE FROM t3 WHERE col1=7
|
2019-08-30 11:03:50 11 [Note] InnoDB: commit 0x55,1
|
2019-08-30 11:03:50 12 [Note] InnoDB: uip RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] U(0x000000000055),[7] P (0x20000001500110),[1] (0x00),[1]M(0x4D)} to RECORD(info_bits=0, 5 fields): {[1] (0x07),[6] T(0x000000000054),[7] Q (0x1F000001510110),[1] (0x00),[1]M(0x4D)} by 0x54,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 11:03:50 12 [Note] InnoDB: uip RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)} to RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x54,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 11:03:50 12 [Note] InnoDB: commit 0x54,1
|
2019-08-30 11:03:50 11 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x59,DELETE FROM t3 WHERE col1=7
|
2019-08-30 11:03:50 11 [Note] InnoDB: commit 0x59,1
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}:1
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] Y(0x000000000059),[7]! R (0x21000001520110),[1] (0x00),[1]M(0x4D)}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purged RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] Y(0x000000000059),[7]! R (0x21000001520110),[1] (0x00),[1]M(0x4D)}
|
2019-08-30 11:03:50 12 [Note] InnoDB: insert TUPLE (info_bits=0, 5 fields): {[1] (0x07),[6] ^(0x00000000005E),[7] S (0xA5000001530110),[1] (0x00),[1]M(0x4D)} by 0x5e,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 11:03:50 12 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x5e,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 11:03:50 12 [Note] InnoDB: commit 0x5e,1
|
2019-08-30 11:03:50 11 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x60,DELETE FROM t3 WHERE col1=7
|
2019-08-30 11:03:50 11 [Note] InnoDB: commit 0x60,1
|
2019-08-30 11:03:50 4 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}
|
2019-08-30 11:03:50 4 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}:1
|
2019-08-30 11:03:50 10 [Note] InnoDB: uip RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] `(0x000000000060),[7]' T (0x27000001540110),[1] (0x00),[1]M(0x4D)} to RECORD(info_bits=0, 5 fields): {[1] (0x07),[6] _(0x00000000005F),[7]& U /(0x2600000155012F),[1] (0x00),[1]M(0x4D)} by 0x5f,UPDATE t3 SET col1 = 7
|
2019-08-30 11:03:50 10 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x5f,UPDATE t3 SET col1 = 7
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x5f,UPDATE t3 SET col1 = 7
|
2019-08-30 11:03:50 10 [Note] InnoDB: commit 0x5f,2
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x04)}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x04)}:1
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 5 fields): {[1] (0x04),[6] _(0x00000000005F),[7]& U (0x26000001550110),[1] (0x00),DEFAULT}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purged RECORD(info_bits=32, 5 fields): {[1] (0x04),[6] _(0x00000000005F),[7]& U (0x26000001550110),[1] (0x00),DEFAULT}
|
2019-08-30 11:03:50 11 [ERROR] [FATAL] InnoDB: Record in index `uidx3` of table `test`.`t3` was not found on update: TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} at: RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)}
|
Let me reconstruct the clustered index contents from the start of transaction 0x5e:
- (4,0),(7,77) at the start of transaction 0x51 (rolled back)
- (4,0),delete-marked(7,77) after DELETE, transaction 0x55 (committed)
- (4,0),(7,77) after INSERT, transaction 0x54 (committed)
- (4,0),delete-marked(7,77) after DELETE, transaction 0x59 (committed)
- (4,0) after purge (in both indexes)
- (4,0),(7,77) after INSERT, transaction 0x5e (committed)
- (4,0),delete-marked(7,77) after DELETE, transaction 0x60 (committed)
- unchanged after (77,7) was purged from secondary index
- delete-marked(4,0),(7,77) after UPDATE, transaction 0x5f
- (7,77) after purge (in both indexes)
- crash on DELETE because the record should have been (7,0)
The logging for clustered index operations is not complete, but the evidence for the corruption is there, wrongly using update-in-place and inserting (7,77) instead of (7,0) when updating (4,0):
2019-08-30 11:03:50 10 [Note] InnoDB: uip RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] `(0x000000000060),[7]' T (0x27000001540110),[1] (0x00),[1]M(0x4D)} to RECORD(info_bits=0, 5 fields): {[1] (0x07),[6] _(0x00000000005F),[7]& U /(0x2600000155012F),[1] (0x00),[1]M(0x4D)} by 0x5f,UPDATE t3 SET col1 = 7
|
The corruption is repeatable on 10.3, which does not support instant DROP COLUMN:
--source include/have_innodb.inc
|
CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB; |
INSERT INTO t1 VALUES (7); |
|
|
ALTER TABLE t1 ADD COLUMN c INT NOT NULL DEFAULT 0; |
ALTER TABLE t1 ADD INDEX (c); |
|
|
BEGIN; |
DELETE FROM t1; |
INSERT INTO t1 VALUES (4,0),(7,77); |
COMMIT; |
BEGIN; |
DELETE FROM t1 WHERE a=7; |
UPDATE t1 SET a=7; |
COMMIT; |
SELECT * FROM t1 FORCE INDEX(PRIMARY); |
SELECT * FROM t1 FORCE INDEX(c); |
DELETE FROM t1; |
CHECK TABLE t1; |
DROP TABLE t1; |
The problem is that row_upd_build_difference_binary() fails to account for index->n_fields > entry->n_fields. Hence, the UPDATE of (4,0) to (7,0) will write the wrong value (7,77) to the clustered index and the correct value (0,7) to the secondary index.
Note that until MDEV-19783 is fixed, it may be risky to use instant ADD COLUMN.
Another day, another crash, this time with some more diagnostics:
2019-08-30 8:58:21 9 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[8] (0x0000000000000014),[7]test/t3(0x746573742F7433)} by 0x22,CREATE TABLE t3 (col1 TINYINT UNSIGNED PRIMARY KEY, col_text TINYINT UNSIGNED NOT NULL DEFAULT 0) ENGINE=InnoDB ROW_FORMAT=REDUNDANT2019-08-30 8:58:22 12 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x63,UPDATE t3 SET col1 = 42019-08-30 8:58:22 12 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x63,UPDATE t3 SET col1 = 42019-08-30 8:58:22 10 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x64,INSERT INTO t3 VALUES (7,77)2019-08-30 8:58:22 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x07)}2019-08-30 8:58:22 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x07)}:12019-08-30 8:58:22 12 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x66,UPDATE t3 SET col1 = 72019-08-30 8:58:22 11 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x69,DELETE FROM t3 WHERE col1=72019-08-30 8:58:22 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}2019-08-30 8:58:22 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}:12019-08-30 8:58:22 12 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x6d,UPDATE t3 SET col1 = 72019-08-30 8:58:22 12 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x6d,UPDATE t3 SET col1 = 72019-08-30 8:58:22 4 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x04)}2019-08-30 8:58:22 4 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x04)}:12019-08-30 8:58:22 4 [Note] InnoDB: purged RECORD(info_bits=32, 5 fields): {[1] (0x04),[6] m(0x00000000006D),[7]D I (0x44000001490110),[1] (0x00),DEFAULT}2019-08-30 8:58:22 11 [ERROR] [FATAL] InnoDB: Record in index `uidx3` of table `test`.`t3` was not found on update: TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} at: RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)}(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata record with purged history),delete-marked(7,0x6f,0x460000014a0110,0,77)
(col_text,col1)=(0,7), PAGE_MAX_TRX_ID=0x6d
Again, instead of finding a delete-marked record (77,7), we find the non-delete-marked (0,7) in the secondary index.
The history of the record (77,7) is as follows:
(other transactions 0x71,0x72 are waiting for locks, did not modify anything)
The history of the record (0,7) is as follows:
Let us reconstruct the complete contents of the secondary index (col_text,col1) at each step of the log:
The last UPDATE is attempting to delete-mark an already delete-marked record (0,4). The corruption seems to have been caused earlier, by UPDATE t3 SET col1 = 7, transaction 0x66, which did not attempt to insert the record (0,7) as expected. Actually, that transaction should have been rolled back, because the record (7,77) already existed in the clustered index, so the attempt to update (4,0) to (7,0) should have violated the uniqueness of the PRIMARY KEY(col1).
I must add more diagnostics to cover transaction rollback. The bug appears to be in the UPDATE or its rollback.