Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-15872

Crash in online ALTER TABLE…ADD PRIMARY KEY after instant ADD COLUMN…NULL

Details

    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

          Activity

            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_KILLED
             
            Program 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:1308
            

            The 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.

            mleich Matthias Leich added a comment - 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_KILLED   Program 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:1308 The 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.
            mleich Matthias Leich added a comment - - edited

            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

            mleich Matthias Leich added a comment - - edited 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:

            1. Instantly add a column that allows NULL value.
            2. Insert some data, with implicit NULL in the instantly added column
            3. 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.

            marko Marko Mäkelä added a comment - 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;
             	}
             
            

            marko Marko Mäkelä added a comment - 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.
            mleich Matthias Leich added a comment - 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.

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.