[MDEV-22637] Rollback of insert fails when column reorder happens Created: 2020-05-19  Updated: 2021-09-23  Resolved: 2020-05-26

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.7
Fix Version/s: 10.5.4, 10.3.24, 10.4.14

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
duplicates MDEV-18334 Assertion `len <= col->len || ((col->... Closed

 Description    

MariaDB origin/10.4 ea912d1605b463a16a0c186bf10e61c4af519439 2020-05-18T12:14:50+02:00
 
 
 
Version: '10.4.14-MariaDB-debug-log'  socket: ....
 
mysqld: /storage/innobase/row/row0log.cc:1183: dberr_t row_log_table_get_pk_col(const dict_field_t*, const dict_index_t*, dfield_t*, mem_heap_t*, const rec_t*, const rec_offs*, ulint, ulint, ulint, const row_log_t*): Assertion `0' failed.
 
...
 
Query (0x7f1b90011470): ROLLBACK
 
Connection ID (thread ID): 45
 
Status: NOT_KILLED
 
 
 
(rr) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#1  0x00007f1ca5426801 in __GI_abort () at abort.c:79
 
#2  0x00007f1ca541639a in __assert_fail_base (fmt=0x7f1ca559d7d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x563d88969df1 "0", file=file@entry=0x563d8896b5a8 "/home/mleich/10.4/storage/innobase/row/row0log.cc", 
    line=line@entry=1183,
 
    function=function@entry=0x563d8896e6a0 <row_log_table_get_pk_col(dict_field_t const*, dict_index_t const*, dfield_t*, mem_block_info_t*, unsigned char const*, unsigned short const*, unsigned long, unsigned long, unsigned long, row_log_t const*)::__PRETTY_FUNCTION__> "dberr_t row_log_table_get_pk_col(const dict_field_t*, const dict_index_t*, dfield_t*, mem_heap_t*, const rec_t*, const rec_offs*, ulint, ulint, ulint, const row_log_t*)") at assert.c:92
 
#3  0x00007f1ca5416412 in __GI___assert_fail (assertion=0x563d88969df1 "0", file=0x563d8896b5a8 "/home/mleich/10.4/storage/innobase/row/row0log.cc", line=1183, 
    function=0x563d8896e6a0 <row_log_table_get_pk_col(dict_field_t const*, dict_index_t const*, dfield_t*, mem_block_info_t*, unsigned char const*, unsigned short const*, unsigned long, unsigned long, unsigned long, row_log_t const*)::__PRETTY_FUNCTION__> "dberr_t row_log_table_get_pk_col(const dict_field_t*, const dict_index_t*, dfield_t*, mem_heap_t*, const rec_t*, const rec_offs*, ulint, ulint, ulint, const row_log_t*)") at assert.c:101
 
#4  0x0000563d88077005 in row_log_table_get_pk_col (ifield=0x7f1bdc0327b8, index=0x7f1bdc032480, dfield=0x7f1b9001ff88, heap=0x7f1b9001fed0, rec=0x7f1c82b90112 "", offsets=0x7f1b900320f0, i=8, zip_size=0, max_len=3072, log=0x7f1bdc04a160)
 
    at /home/mleich/10.4/storage/innobase/row/row0log.cc:1183
 
#5  0x0000563d88077ac2 in row_log_table_get_pk (rec=0x7f1c82b90112 "", index=0x7f1be0030320, offsets=0x7f1b900320f0, sys=0x0, heap=0x7f1bc9278c68) at /home/mleich/10.4/storage/innobase/row/row0log.cc:1350
 
#6  0x0000563d88074838 in row_log_table_delete (rec=0x7f1c82b90112 "", index=0x7f1be0030320, offsets=0x7f1b900320f0, sys=0x0) at /home/mleich/10.4/storage/innobase/row/row0log.cc:729
 
#7  0x0000563d882f1016 in row_undo_ins_remove_clust_rec (node=0x7f1b90025750) at /home/mleich/10.4/storage/innobase/row/row0uins.cc:123
 
#8  0x0000563d882f2add in row_undo_ins (node=0x7f1b90025750, thr=0x7f1be8025930) at /home/mleich/10.4/storage/innobase/row/row0uins.cc:587
 
#9  0x0000563d880b503e in row_undo (node=0x7f1b90025750, thr=0x7f1be8025930) at /home/mleich/10.4/storage/innobase/row/row0undo.cc:438
 
#10 0x0000563d880b5314 in row_undo_step (thr=0x7f1be8025930) at /home/mleich/10.4/storage/innobase/row/row0undo.cc:499
 
#11 0x0000563d87ff82ee in que_thr_step (thr=0x7f1be8025930) at /home/mleich/10.4/storage/innobase/que/que0que.cc:1037
 
#12 0x0000563d87ff85a1 in que_run_threads_low (thr=0x7f1be8025930) at /home/mleich/10.4/storage/innobase/que/que0que.cc:1101
 
#13 0x0000563d87ff87ef in que_run_threads (thr=0x7f1be8025930) at /home/mleich/10.4/storage/innobase/que/que0que.cc:1141
 
#14 0x0000563d8811c4c5 in trx_rollback_to_savepoint_low (trx=0x7f1c8f6a11a0, savept=0x0) at /home/mleich/10.4/storage/innobase/trx/trx0roll.cc:136
 
#15 0x0000563d8811c960 in trx_rollback_for_mysql_low (trx=0x7f1c8f6a11a0) at /home/mleich/10.4/storage/innobase/trx/trx0roll.cc:210
 
#16 0x0000563d8811ce3d in trx_rollback_for_mysql (trx=0x7f1c8f6a11a0) at /home/mleich/10.4/storage/innobase/trx/trx0roll.cc:240
 
#17 0x0000563d87eb7292 in innobase_rollback (hton=0x563d8aa89598, thd=0x7f1b90000ce8, rollback_trx=true) at /home/mleich/10.4/storage/innobase/handler/ha_innodb.cc:4690
 
#18 0x0000563d87c727ed in ha_rollback_trans (thd=0x7f1b90000ce8, all=true) at /home/mleich/10.4/sql/handler.cc:1886
 
#19 0x0000563d87ab26e8 in trans_rollback (thd=0x7f1b90000ce8) at /home/mleich/10.4/sql/transaction.cc:341
 
#20 0x0000563d879209ab in mysql_execute_command (thd=0x7f1b90000ce8) at /home/mleich/10.4/sql/sql_parse.cc:5658
 
#21 0x0000563d8792786d in mysql_parse (thd=0x7f1b90000ce8, rawbuf=0x7f1b90011470 "ROLLBACK  /* E_R Thread29 QNO 53 CON_ID 45 */", length=45, parser_state=0x7f1bc927a5a0, is_com_multi=false, is_next_command=false)
 
    at /home/mleich/10.4/sql/sql_parse.cc:7900
 
#22 0x0000563d87913e28 in dispatch_command (command=COM_QUERY, thd=0x7f1b90000ce8, packet=0x7f1b90008119 " ROLLBACK  /* E_R Thread29 QNO 53 CON_ID 45 */ ", packet_length=47, is_com_multi=false, is_next_command=false)
 
    at /home/mleich/10.4/sql/sql_parse.cc:1841
 
#23 0x0000563d879125c9 in do_command (thd=0x7f1b90000ce8) at /home/mleich/10.4/sql/sql_parse.cc:1359
 
#24 0x0000563d87a99bf8 in do_handle_one_connection (connect=0x563d8b583228) at /home/mleich/10.4/sql/sql_connect.cc:1412
 
#25 0x0000563d87a99947 in handle_one_connection (arg=0x563d8b583228) at /home/mleich/10.4/sql/sql_connect.cc:1316
 
#26 0x00007f1ca63216db in start_thread (arg=0x7f1bc927b700) at pthread_create.c:463
 
#27 0x00007f1ca550788f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
(rr)
 
 
 
 
 
 
 
RQG:
 
git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich
 
777f2c8c46aa3df3dab625b02972490b479c0aa8 2020-05-16T18:38:04+02:00
 
 
 
perl rqg.pl \                   
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
 
--grammar=conf/mariadb/table_stress_innodb.yy \
 
--gendata=conf/mariadb/table_stress.zz \
 
--gendata_sql=conf/mariadb/table_stress.sql \
 
--engine=Innodb \
 
--reporters=Deadlock1,ErrorLog,Backtrace \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--lock_wait_timeout=86400 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--loose-max-statement-time=30 \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--mysqld=--log-output=none \
 
--duration=300 \
 
--seed=random \
 
--sqltrace=MarkErrors \
 
--threads=33 \
 
--mysqld=--innodb_adaptive_hash_index=OFF \
 
--mysqld=--innodb_page_size=64K \
 
--mysqld=--innodb-buffer-pool-size=256M \
 
--no_mask \
 
--workdir=...
 
...



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2020-05-20 ]

Test case:

--source include/have_innodb.inc
 
SET @@SQL_MODE = REPLACE(@@SQL_MODE, 'STRICT_TRANS_TABLES', '');
 
SET @@SQL_MODE = REPLACE(@@SQL_MODE, 'STRICT_ALL_TABLES', '');
 
CREATE TABLE t1(f1 int not null, f2 char(100),
 
                f3 char(100),
 
                f4 int not null, f5 int not null,
 
                f6 char(100))engine=innodb;
 
INSERT INTO t1 VALUES(1, "This is column2", "This is f3",
 
                      4, 4, "This is f6");
 
ALTER TABLE t1 DROP COLUMN f4, DROP COLUMN f5;
 
set DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL scanned WAIT_FOR insert_done';
 
--send ALTER TABLE t1 ADD PRIMARY KEY (f6(10), f3(10), f2(10)), ALGORITHM=INPLACE
 
connect(con1,localhost,root,,);
 
SET DEBUG_SYNC = 'now WAIT_FOR scanned';
 
begin;
 
insert into t1(f1, f2) values(2, "This is column2 value");
 
rollback;
 
set DEBUG_SYNC = 'now SIGNAL insert_done';
 
 
 
connection default;
 
reap;
 
SELECT * FROM t1;
 
disconnect con1;
 
DROP TABLE t1;
 
SET SQL_MODE=DEFAULT;

Comment by Marko Mäkelä [ 2020-05-20 ]

Thank you. The proposed fix looks correct to me, but please read and address my comments. I suspect that also 10.3 is affected (and could deliver wrong results). Can you investigate more?

Comment by Thirunarayanan Balathandayuthapani [ 2020-05-25 ]

Patch is in bb-10.3-thiru

Comment by Marko Mäkelä [ 2020-05-25 ]

Thanks! I sent one comment, questioning the access to log->old_table->field. I think that one more review is needed.

Comment by Thirunarayanan Balathandayuthapani [ 2020-05-26 ]

mleich The issues you pasted which're not relevant to this bug. I will check ASAN failure and create it as a seperate issue

Closing this bug with following commit:

commit 7476e8c7cdd73d60294126a2840baee97e7644b6 (HEAD -> 10.3, origin/10.3, 10.3-sample)
 
Author: Thirunarayanan Balathandayuthapani <thiru@mariadb.com>
 
Date:   Mon May 25 21:42:26 2020 +0530
 
 
 
    MDEV-22637 Rollback of insert fails when column reorder happens

Generated at Thu Feb 08 09:16:17 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.