Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.3.9
-
Linux Ubuntu 17.10 but most probably not important.
Description
https://api.travis-ci.org/v3/job/364729376/log.txt
|
10.3 8334aced009e9748e17ce697191e00c9f14e78b9 |
#3 <signal handler called>
|
#4 0x00007fe726dd1d06 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
|
#5 0x0000000000e081ef in mem_heap_dup (heap=0x7fe6b429c340, data=0x7fe7150040ae, len=4294967294) at /home/travis/src/storage/innobase/include/mem0mem.h:306
|
#6 0x0000000000f51294 in row_log_table_get_pk_col (col=0x7fe6e40ec050, ifield=0x7fe6d8079b30, dfield=0x7fe6b429c410, heap=0x7fe6b429c340, rec=0x7fe71500409a "", offsets=0x7fe7244a5e90, i=6, page_size=..., max_len=3072) at /home/travis/src/storage/innobase/row/row0log.cc:1187
|
#7 0x0000000000f51a91 in row_log_table_get_pk (rec=0x7fe71500409a "", index=0x7fe6e40b05f8, offsets=0x7fe7244a5e90, sys=0x0, heap=0x7fe7244a56f8) at /home/travis/src/storage/innobase/row/row0log.cc:1326
|
#8 0x0000000000f4f460 in row_log_table_delete (rec=0x7fe71500409a "", index=0x7fe6e40b05f8, offsets=0x7fe7244a5e90, sys=0x0) at /home/travis/src/storage/innobase/row/row0log.cc:694
|
#9 0x000000000104f05a in btr_cur_del_mark_set_clust_rec (block=0x7fe711400e00, rec=0x7fe71500409a "", index=0x7fe6e40b05f8, offsets=0x7fe7244a5e90, thr=0x7fe6b423ac40, entry=0x7fe6b42a0f28, mtr=0x7fe7244a6210) at /home/travis/src/storage/innobase/btr/btr0cur.cc:5064
|
#10 0x0000000000fa15d9 in row_upd_del_mark_clust_rec (node=0x7fe6b423a8d8, index=0x7fe6e40b05f8, offsets=0x7fe7244a5e90, thr=0x7fe6b423ac40, referenced=0, foreign=false, mtr=0x7fe7244a6210) at /home/travis/src/storage/innobase/row/row0upd.cc:2979
|
#11 0x0000000000fa1f4b in row_upd_clust_step (node=0x7fe6b423a8d8, thr=0x7fe6b423ac40) at /home/travis/src/storage/innobase/row/row0upd.cc:3161
|
#12 0x0000000000fa2447 in row_upd (node=0x7fe6b423a8d8, thr=0x7fe6b423ac40) at /home/travis/src/storage/innobase/row/row0upd.cc:3282
|
#13 0x0000000000fa2936 in row_upd_step (thr=0x7fe6b423ac40) at /home/travis/src/storage/innobase/row/row0upd.cc:3426
|
#14 0x0000000000f4061b in row_update_for_mysql (prebuilt=0x7fe6b423a0c8) at /home/travis/src/storage/innobase/row/row0mysql.cc:1882
|
#15 0x0000000000df0097 in ha_innobase::delete_row (this=0x7fe6b429c5e8, record=0x7fe6b436e8b8 "\377") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:8957
|
#16 0x0000000000acf3e1 in handler::ha_delete_row (this=0x7fe6b429c5e8, buf=0x7fe6b436e8b8 "\377") at /home/travis/src/sql/handler.cc:6285
|
#17 0x0000000000c623cd in TABLE::delete_row (this=0x7fe6b4334e00) at /home/travis/src/sql/sql_delete.cc:253
|
#18 0x0000000000c5f78b in mysql_delete (thd=0x7fe6b40155c0, table_list=0x7fe6b402c060, conds=0x0, order_list=0x7fe6b4019df8, limit=9, options=549755813888, result=0x0) at /home/travis/src/sql/sql_delete.cc:748
|
#19 0x00000000007dc725 in mysql_execute_command (thd=0x7fe6b40155c0) at /home/travis/src/sql/sql_parse.cc:4918
|
#20 0x00000000007e6364 in mysql_parse (thd=0x7fe6b40155c0, rawbuf=0x7fe6b402bf38 "DELETE FROM `oltp1` LIMIT 9 /* QNO 44526 CON_ID 15 */", length=53, parser_state=0x7fe7244a8450, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:7991
|
#21 0x00000000007d38d8 in dispatch_command (command=COM_QUERY, thd=0x7fe6b40155c0, packet=0x7fe6b4032841 "DELETE FROM `oltp1` LIMIT 9 /* QNO 44526 CON_ID 15 */ ", packet_length=54, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1841
|
#22 0x00000000007d230b in do_command (thd=0x7fe6b40155c0) at /home/travis/src/sql/sql_parse.cc:1386
|
#23 0x00000000009338df in do_handle_one_connection (connect=0x497d3a0) at /home/travis/src/sql/sql_connect.cc:1402
|
#24 0x0000000000933661 in handle_one_connection (arg=0x497d3a0) at /home/travis/src/sql/sql_connect.cc:1308
|
#25 0x00007fe727860e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
|
#26 0x00007fe726d7c2ed in clone () from /lib/x86_64-linux-gnu/libc.so.6
|
#27 0x0000000000000000 in ?? ()
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7fe6b402bf38): DELETE FROM `oltp1` LIMIT 9 /* QNO 44526 CON_ID 15 */
|
Connection ID (thread ID): 15
|
Status: NOT_KILLED
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
|
|
experimental 4feb78e17fbecf7fc7f2847b49b8c66b54879629 |
perl /home/travis/rqg/runall-new.pl --duration=350 --threads=6 --redefine=conf/mariadb/instant_add.yy --reporters=Backtrace,ErrorLog,Deadlock --engine=InnoDB --seed=1523411054 --basedir=/home/travis/server --mysqld=--max-statement-time=30 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --grammar=conf/mariadb/oltp.yy --gendata=conf/mariadb/oltp.zz --duration=300 --mysqld=--innodb-flush-log-at-trx-commit=0 --vardir=/home/travis/logs/vardir1_4
|
Could not reproduce so far.
Attachments
Issue Links
- is caused by
-
-
- Closed
-
Activity
Replay again with
10.3 commit 5e7496e2eaf01d3be79fca3f199a8d3e597af208 2018-08-12T14:52:37+02:00
The server claims to be a 10.3.9-MariaDB-debug-log.
Instructions for replay attempts
---------------------------------------
git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich1
cd RQG_mleich1
tar xvzf <Path_to_MDEV-15872.tgz>
Edit MDEV-15872.sh so that BASEDIR points to your binaries
./MDEV-15872.sh
PRIMARY KEY columns are supposed to be NOT NULL, but here we seem to be trying to copy a NULL value:
#5 mem_heap_dup (len=4294967295, data=0x0, heap=<optimized out>) at storage/innobase/include/mem0mem.h:306
|
#6 row_log_table_get_pk_col (log=0x7f2d4c05cb00, log=0x7f2d4c05cb00, max_len=3072, page_size=..., i=<optimized out>, offsets=0x7f2d4003f110, rec=0x7f2dcbe7c07e <error: Cannot access memory at address 0x7f2dcbe7c07e>, heap=<optimized out>, dfield=0x7f2d4003af10, ifield=0x7f2d4c05c118) at storage/innobase/row/row0log.cc:1170
|
The problem should be that this code for handling instantly added columns is not checking if the initial default value of the instantly added column was NULL:
field = static_cast<const byte*>( |
log->defaults->fields[n_default_cols].data); |
len = log->defaults->fields[i - DATA_N_SYS_COLS].len; |
I believe that the scenario must be something like this:
- Instantly add a column that allows NULL value.
- Insert some data, with implicit NULL in the instantly added column
- Execute DELETE (or a ROLLBACK of an INSERT) while ALTER TABLE…ADD PRIMARY KEY is in progress.
Unfortunately, I was unable to trigger this. I am getting "Invalid use of NULL value" flagged for the ALTER TABLE before the DELETE gets a chance to be logged.
A necessary condition that was present in MDEV-11369 and was modified in MDEV-14168 was inadvertently deleted by MDEV-16365, which was a follow-up fix of MDEV-14168.
The test requires ALTER IGNORE. Here is a deterministic test (which crashes the server) and the fix:
diff --git a/mysql-test/suite/innodb/t/instant_alter_debug.test b/mysql-test/suite/innodb/t/instant_alter_debug.test
|
index 5a73ed65d72..ff1650ea191 100644
|
--- a/mysql-test/suite/innodb/t/instant_alter_debug.test
|
+++ b/mysql-test/suite/innodb/t/instant_alter_debug.test
|
@@ -232,6 +232,30 @@ INSERT INTO t1 SET a=1;
|
INSERT INTO t1 SET a=2,b=3,c=4;
|
SET DEBUG_SYNC = 'now SIGNAL logged';
|
|
+connection ddl;
|
+reap;
|
+
|
+connection default;
|
+SET DEBUG_SYNC = RESET;
|
+SELECT * FROM t1;
|
+
|
+--echo #
|
+--echo # MDEV-15872 Server crashed in row_log_table_delete
|
+--echo #
|
+ALTER TABLE t1 ADD COLUMN d INT, ALGORITHM=INSTANT;
|
+UPDATE t1 SET d=1;
|
+
|
+connection ddl;
|
+SET DEBUG_SYNC='row_log_table_apply1_before SIGNAL copied WAIT_FOR logged';
|
+send ALTER IGNORE TABLE t1 DROP PRIMARY KEY, ADD PRIMARY KEY (a,d);
|
+
|
+connection default;
|
+SET DEBUG_SYNC = 'now WAIT_FOR copied';
|
+BEGIN;
|
+INSERT INTO t1 SET a=3;
|
+ROLLBACK;
|
+SET DEBUG_SYNC = 'now SIGNAL logged';
|
+
|
connection ddl;
|
reap;
|
disconnect ddl;
|
diff --git a/storage/innobase/row/row0log.cc b/storage/innobase/row/row0log.cc
|
index 386bd2786a0..a6e35744446 100644
|
--- a/storage/innobase/row/row0log.cc
|
+++ b/storage/innobase/row/row0log.cc
|
@@ -1164,7 +1164,6 @@ row_log_table_get_pk_col(
|
field = rec_get_nth_field(rec, offsets, i, &len);
|
|
if (len == UNIV_SQL_NULL) {
|
-
|
if (!log->allow_not_null) {
|
return(DB_INVALID_NULL);
|
}
|
@@ -1173,6 +1172,9 @@ row_log_table_get_pk_col(
|
|
field = static_cast<const byte*>(
|
log->defaults->fields[n_default_cols].data);
|
+ if (!field) {
|
+ return(DB_INVALID_NULL);
|
+ }
|
len = log->defaults->fields[i - DATA_N_SYS_COLS].len;
|
}
|
|
|
10.3 + the MDEV-15782 patch "survived"
- 1.5 hours high load with ~ 110 RQG tests in parallel
- in sum ~ 900 RQG tests (replay setup and grammar, 300s duration)
without any bad effect showing up
== The bug had his "chance" and seems to be fixed.
I have an already simplified RQG test which replays at least the begin of the stacktrace above.
| Version: '10.3.9-MariaDB-log' ...| 2018-07-23 16:13:07 18 [Note] Detected table cache mutex contention at instance 1: 23% waits. Additional table cache instance activated. Number of instances after activation: 2.| 180723 16:18:56 [ERROR] mysqld got signal 11 ;...# 2018-07-23T16:19:02 [60510] | Query (0x7f2d40011640): INSERT INTO t1 (col1,col2,col3,col4) VALUES (NULL,NULL,NULL,REPEAT(CAST( NULL AS CHAR(1)), @fill_amount) ), (NULL,NULL,NULL,REPEAT(CAST( NULL AS CHAR(1)), @fill_amount) ) /* E_R Thread4 QNO 381662 CON_ID 18 */| Connection ID (thread ID): 18| Status: NOT_KILLEDProgram terminated with signal SIGSEGV, Segmentation fault.#0 __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62[Current thread is 1 (Thread 0x7f2dd580e700 (LWP 60606))]#3 <signal handler called>#4 0x000055ddd7b21373 in memcpy (__len=4294967295, __src=0x0, __dest=0x7f2d4003af58) at /usr/include/x86_64-linux-gnu/bits/string3.h:53#5 mem_heap_dup (len=4294967295, data=0x0, heap=<optimized out>) at storage/innobase/include/mem0mem.h:306#6 row_log_table_get_pk_col (log=0x7f2d4c05cb00, log=0x7f2d4c05cb00, max_len=3072, page_size=..., i=<optimized out>, offsets=0x7f2d4003f110, rec=0x7f2dcbe7c07e <error: Cannot access memory at address 0x7f2dcbe7c07e>, heap=<optimized out>, dfield=0x7f2d4003af10, ifield=0x7f2d4c05c118) at storage/innobase/row/row0log.cc:1170#7 row_log_table_get_pk (rec=0x7f2dcbe7c07e <error: Cannot access memory at address 0x7f2dcbe7c07e>, index=0x7f2d44052f90, offsets=offsets@entry=0x7f2d4003f110, sys=sys@entry=0x0, heap=heap@entry=0x7f2dd580b468) at storage/innobase/row/row0log.cc:1307#8 0x000055ddd7b21592 in row_log_table_delete (rec=rec@entry=0x7f2dcbe7c07e <error: Cannot access memory at address 0x7f2dcbe7c07e>, index=index@entry=0x7f2d44052f90, offsets=0x7f2d4003f110, sys=sys@entry=0x0) at storage/innobase/row/row0log.cc:718#9 0x000055ddd81326c9 in row_undo_ins_remove_clust_rec (node=node@entry=0x7f2d4005b180) at storage/innobase/row/row0uins.cc:120#10 0x000055ddd813355c in row_undo_ins (node=<optimized out>, thr=<optimized out>) at storage/innobase/row/row0uins.cc:613#11 0x000055ddd7fec679 in row_undo (thr=0x7f2d4005afb8, node=0x7f2d4005b180) at storage/innobase/row/row0undo.cc:303#12 row_undo_step (thr=thr@entry=0x7f2d4005afb8) at storage/innobase/row/row0undo.cc:362#13 0x000055ddd7f97376 in que_thr_step (thr=0x7f2d4005afb8) at storage/innobase/que/que0que.cc:1044#14 que_run_threads_low (thr=0x7f2d4005afb8) at storage/innobase/que/que0que.cc:1108#15 que_run_threads (thr=<optimized out>) at storage/innobase/que/que0que.cc:1148#16 0x000055ddd8028e9a in trx_rollback_to_savepoint_low (trx=trx@entry=0x7f2dd58a4008, savept=savept@entry=0x7f2dd58a4230) at storage/innobase/trx/trx0roll.cc:145#17 0x000055ddd80291c0 in trx_rollback_to_savepoint (savept=0x7f2dd58a4230, trx=0x7f2dd58a4008) at storage/innobase/trx/trx0roll.cc:193#18 trx_rollback_last_sql_stat_for_mysql (trx=trx@entry=0x7f2dd58a4008) at storage/innobase/trx/trx0roll.cc:326#19 0x000055ddd7f08292 in innobase_rollback (hton=<optimized out>, thd=0x7f2d400009a8, rollback_trx=<optimized out>) at storage/innobase/handler/ha_innodb.cc:4745#20 0x000055ddd7dac0c1 in ha_rollback_trans (thd=thd@entry=0x7f2d400009a8, all=all@entry=false) at sql/handler.cc:1721#21 0x000055ddd7cc4a57 in trans_rollback_stmt (thd=thd@entry=0x7f2d400009a8) at sql/transaction.cc:583#22 0x000055ddd7bebc72 in mysql_execute_command (thd=thd@entry=0x7f2d400009a8) at sql/sql_parse.cc:6328#23 0x000055ddd7bf40f9 in mysql_parse (thd=thd@entry=0x7f2d400009a8, rawbuf=<optimized out>, length=210, parser_state=parser_state@entry=0x7f2dd580d650, is_com_multi=<optimized out>, is_next_command=<optimized out>) at sql/sql_parse.cc:8073#24 0x000055ddd7bf68d4 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f2d400009a8, packet=packet@entry=0x7f2d40009349 "INSERT INTO t1 (col1,col2,col3,col4) VALUES (NULL,NULL,NULL,REPEAT(CAST( NULL AS CHAR(1)), @fill_amount) ), (NULL,NULL,NULL,REPEAT(CAST( NULL AS CHAR(1)), @fill_amount) ) /* E_R Thread4 QNO 381662 CON_ID 18 */ ", packet_length=packet_length@entry=211, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at sql/sql_parse.cc:1847#25 0x000055ddd7bf7546 in do_command (thd=0x7f2d400009a8) at sql/sql_parse.cc:1391#26 0x000055ddd7cb8114 in do_handle_one_connection (connect=connect@entry=0x55dddb3681f8) at sql/sql_connect.cc:1402#27 0x000055ddd7cb8294 in handle_one_connection (arg=0x55dddb3681f8) at sql/sql_connect.cc:1308The likelihood to replay has become better because of the simplification but
nevertheless 16 - 32 trials are required.
Replay on
10.3 commit 141a5b24843c626f545a0c2f49013b54da194c0d compiled without debug
The server claims to be a 10.3.9-MariaDB-log.
Never a replay on
10.2 commit d0d073b1aaa30997307bc7aa686d3715f8c22da0 compiled without debug
The server claims to be a 10.2.17-MariaDB
I will upload the files required for replay.