[#MDEV-18302] Assertion `!((new_col->prtype ^ col->prtype) & ~256U)' failed in row_log_table_apply_convert

This problem is not reproducible on

   10.4 55a0c3eb6dc8f8fb4786932901ca74cbb9b8637c 2019-01-15

and seems to valid for

   bb-10.4-MDEV-15563 bedc32d91d3b1e39244c5c235c56480fdda88946 2016-01-16

only.

...

Version: '10.4.2-MariaDB-debug-log'  socket: 'bld_debug/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution

mysqld: storage/innobase/row/row0log.cc:1646: const dtuple_t* row_log_table_apply_convert_mrec(const mrec_t*, dict_index_t*, const ulint*, row_log_t*, mem_heap_t*, dberr_t*): Assertion `!((new_col->prtype ^ col->prtype) & ~256U)' failed.

190118 12:24:57 [ERROR] mysqld got signal 6 ;

...

Query (0x7f4040013020): ALTER TABLE t1 MODIFY col2 BIGINT /* E_R Thread2 QNO 59 CON_ID 15 */

Connection ID (thread ID): 10

Status: NOT_KILLED

...

#3  <signal handler called>

#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51

#5  0x00007f40a56ecf5d in __GI_abort () at abort.c:90

#6  0x00007f40a56e2f17 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55ff5682b4f0 "!((new_col->prtype ^ col->prtype) & ~256U)", file=file@entry=0x55ff5682a9e8 "storage/innobase/row/row0log.cc", line=line@entry=1646, function=function@entry=0x55ff5682df40 <row_log_table_apply_convert_mrec(unsigned char const*, dict_index_t*, unsigned long const*, row_log_t*, mem_block_info_t*, dberr_t*)::__PRETTY_FUNCTION__> "const dtuple_t* row_log_table_apply_convert_mrec(const mrec_t*, dict_index_t*, const ulint*, row_log_t*, mem_heap_t*, dberr_t*)") at assert.c:92

#7  0x00007f40a56e2fc2 in __GI___assert_fail (assertion=0x55ff5682b4f0 "!((new_col->prtype ^ col->prtype) & ~256U)", file=0x55ff5682a9e8 "storage/innobase/row/row0log.cc", line=1646, function=0x55ff5682df40 <row_log_table_apply_convert_mrec(unsigned char const*, dict_index_t*, unsigned long const*, row_log_t*, mem_block_info_t*, dberr_t*)::__PRETTY_FUNCTION__> "const dtuple_t* row_log_table_apply_convert_mrec(const mrec_t*, dict_index_t*, const ulint*, row_log_t*, mem_heap_t*, dberr_t*)") at assert.c:101

#8  0x000055ff560a9c06 in row_log_table_apply_convert_mrec (mrec=0x7f409a81a005 "\200", index=0x7f4040030408, offsets=0x7f40400350f0, log=0x7f4040056de0, heap=0x7f4040045b30, error=0x7f409a9a8dfc) at storage/innobase/row/row0log.cc:1646

#9  0x000055ff560aa341 in row_log_table_apply_insert (thr=0x7f40400395f8, mrec=0x7f409a81a005 "\200", offsets=0x7f40400350f0, offsets_heap=0x7f4040049bc0, heap=0x7f4040045b30, dup=0x7f409a9a91a0) at storage/innobase/row/row0log.cc:1777

#10 0x000055ff560ac8e9 in row_log_table_apply_op (thr=0x7f40400395f8, new_trx_id_col=1, dup=0x7f409a9a91a0, error=0x7f409a9a8f1c, offsets_heap=0x7f4040049bc0, heap=0x7f4040045b30, mrec=0x7f409a81a005 "\200", mrec_end=0x7f409a81a01a "", offsets=0x7f40400350f0) at storage/innobase/row/row0log.cc:2465

#11 0x000055ff560aeb94 in row_log_table_apply_ops (thr=0x7f40400395f8, dup=0x7f409a9a91a0, stage=0x7f40400433a0) at storage/innobase/row/row0log.cc:3022

#12 0x000055ff560af18e in row_log_table_apply (thr=0x7f40400395f8, old_table=0x7f40340550a8, table=0x7f4040036538, stage=0x7f40400433a0, new_table=0x7f404002d148) at storage/innobase/row/row0log.cc:3131

#13 0x000055ff55f719d1 in ha_innobase::inplace_alter_table (this=0x7f403406aa10, altered_table=0x7f4040036538, ha_alter_info=0x7f409a9a9bb0) at storage/innobase/handler/handler0alter.cc:8366

#14 0x000055ff55ae558f in handler::ha_inplace_alter_table (this=0x7f403406aa10, altered_table=0x7f4040036538, ha_alter_info=0x7f409a9a9bb0) at sql/handler.h:4216

#15 0x000055ff55adab00 in mysql_inplace_alter_table (thd=0x7f4040000ce8, table_list=0x7f4040013158, table=0x7f4034069e48, altered_table=0x7f4040036538, ha_alter_info=0x7f409a9a9bb0, inplace_supported=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x7f409a9a9ce0, alter_ctx=0x7f409a9aa8d0) at sql/sql_table.cc:7543

#16 0x000055ff55ae0c0c in mysql_alter_table (thd=0x7f4040000ce8, new_db=0x7f40400053c8, new_name=0x7f4040005798, create_info=0x7f409a9ab4c0, table_list=0x7f4040013158, alter_info=0x7f409a9ab400, order_num=0, order=0x0, ignore=false) at sql/sql_table.cc:9694

#17 0x000055ff55b6ac9a in Sql_cmd_alter_table::execute (this=0x7f40400138b0, thd=0x7f4040000ce8) at sql/sql_alter.cc:491

#18 0x000055ff55a09185 in mysql_execute_command (thd=0x7f4040000ce8) at sql/sql_parse.cc:6314

#19 0x000055ff55a0e34c in mysql_parse (thd=0x7f4040000ce8, rawbuf=0x7f4040013020 "ALTER TABLE t1 MODIFY col2 BIGINT /* E_R Thread2 QNO 59 CON_ID 15 */", length=68, parser_state=0x7f409a9ac5f0, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:8116

#20 0x000055ff559fb1df in dispatch_command (command=COM_QUERY, thd=0x7f4040000ce8, packet=0x7f404000acf9 "ALTER TABLE t1 MODIFY col2 BIGINT /* E_R Thread2 QNO 59 CON_ID 15 */ ", packet_length=69, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1851

#21 0x000055ff559f9bf4 in do_command (thd=0x7f4040000ce8) at sql/sql_parse.cc:1396

#22 0x000055ff55b64cca in do_handle_one_connection (connect=0x55ff59496cc8) at sql/sql_connect.cc:1402

#23 0x000055ff55b64a41 in handle_one_connection (arg=0x55ff59496cc8) at sql/sql_connect.cc:1308

#24 0x000055ff564620d9 in pfs_spawn_thread (arg=0x55ff594c7928) at storage/perfschema/pfs.cc:1862

#25 0x00007f40a638e7fc in start_thread (arg=0x7f409a9ad700) at pthread_create.c:465

#26 0x00007f40a57c8b5f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

How to reproduce the problem?

Please use a Linux because the test invokes a shellscript.

cd <source tree>/mysql-test

tar xvzf ts_12.tgz

./mysql-test-run.pl --mem --mysqld=--debug-sync-timeout=1 ts_12

This is a plain brute force test (two users run a DDL/DML mix and one user observes).

You might need several runs of that test till you get the assert.

But at least  I hit the assert with every run of the test.

The "--mysqld=--debug-sync-timeout=1" is most probably not required for the assert

to show up but it might help to reproduce the problem more likely.

The problem was not reproducible on

10.4.4 commit 10dd290b4b8b8b235c8cf42e100f0a4415629e79 2019-04-01T12:00:56+03:00

Therefore I close the issue.

Regarding the coverage of InnoDB ROW_FORMATs:

1. There should be serious coverage by the existing MTR based tests below <source>/mysql-test.

     Certain MTR tests (like the ts_12.test here) mentioned within my bug reports are

     quite often not suited for frequent use.

     Typical characteristics of such tests:

     - use of mysqltest_background.sh

     - runtime of 60 till 600s, extreme CPU load

     They are just brute force attempts to replay bugs requiring concurrency but without

      using RQG.

2. RQG (git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich1)

     Output of

        egrep -i "REDUNDANT|DYNAMIC|COMPRESSED|COMPACT"  conf/mariadb/* 2>/dev/null

    a bit  edited

conf/mariadb/alter_table.yy:  DEFAULT | DYNAMIC | FIXED | COMPRESSED | REDUNDANT | COMPACT | PAGE

conf/mariadb/alter_table.yy:alt_compressed:

conf/mariadb/alter_table.yy:  | | | | | | COMPRESSED ;

conf/mariadb/concurrency.yy:   # Switch simply every dynamic Innodb related parameter

conf/mariadb/concurrency.yy:   ROW_FORMAT = COMPACT     | # The default since 5.0.3

conf/mariadb/concurrency.yy:   ROW_FORMAT = REDUNDANT   | # The format prior to 5.0.3

conf/mariadb/concurrency.yy:   ROW_FORMAT = DYNAMIC     | # Requires file format Barracuda

conf/mariadb/concurrency.yy:   ROW_FORMAT = COMPRESSED  ; # Requires file format Barracuda and files per table

conf/mariadb/innodb_compression_encryption.yy:    encrypted | encryption_key | row_format | page_compressed ;

conf/mariadb/innodb_compression_encryption.yy:    COMPRESSED | COMPRESSED | COMPRESSED | COMPRESSED | COMPACT | DYNAMIC ;

conf/mariadb/innodb_compression_encryption.yy:page_compressed:

conf/mariadb/innodb_compression_encryption.yy:    PAGE_COMPRESSED=zero_one;

conf/mariadb/innodb_upgrade_compression.zz:            'ROW_FORMAT=REDUNDANT',

conf/mariadb/innodb_upgrade_compression.zz:            'ROW_FORMAT=COMPRESSED',

conf/mariadb/innodb_upgrade_compression.zz:            '/*!100100 PAGE_COMPRESSED=1 */',

conf/mariadb/innodb_upgrade_compression.zz:            '/*!100100 PAGE_COMPRESSED=1 PAGE_COMPRESSION_LEVEL=1 */',

conf/mariadb/innodb_upgrade_compression.zz:            '/*!100100 PAGE_COMPRESSED=1 PAGE_COMPRESSION_LEVEL=9 */',

conf/mariadb/innodb_upgrade_compression.zz:            'ROW_FORMAT=DYNAMIC /*!100100 PAGE_COMPRESSED=1 */',

conf/mariadb/innodb_upgrade_compression.zz:            'ROW_FORMAT=DYNAMIC /*!100100 PAGE_COMPRESSED=1 PAGE_COMPRESSION_LEVEL=1 */',

conf/mariadb/innodb_upgrade_compression.zz:            'ROW_FORMAT=DYNAMIC /*!100100 PAGE_COMPRESSED=1 PAGE_COMPRESSION_LEVEL=9 */',

conf/mariadb/innodb_upgrade_compression.zz:            'ROW_FORMAT=COMPACT /*!100100 PAGE_COMPRESSED=1 */',

conf/mariadb/innodb_upgrade_compression.zz:            'ROW_FORMAT=COMPACT /*!100100 PAGE_COMPRESSED=1 PAGE_COMPRESSION_LEVEL=1 */',

conf/mariadb/innodb_upgrade_compression.zz:            'ROW_FORMAT=COMPACT /*!100100 PAGE_COMPRESSED=1 PAGE_COMPRESSION_LEVEL=9 */',

conf/mariadb/innodb_upgrade.zz:        row_formats => [ undef, 'DYNAMIC', 'REDUNDANT', 'COMPACT', 'COMPRESSED' ],

conf/mariadb/instant_add.yy:  ROW_FORMAT=COMPACT | ROW_FORMAT=COMPRESSED | ROW_FORMAT=DYNAMIC | ROW_FORMAT=REDUNDANT

conf/mariadb/instant_add.yy:ia_compressed:

conf/mariadb/instant_add.yy:  | | | | | | COMPRESSED ;

conf/mariadb/oltp_and_ddl.yy:  | ROW_FORMAT=COMPACT | ROW_FORMAT=COMPRESSED | ROW_FORMAT=DYNAMIC | ROW_FORMAT=REDUNDANT

conf/mariadb/table_stress.yy:   c_t_begin t0 c_t_mid ENGINE = MyISAM ; c_t_begin t1 c_t_mid ENGINE = InnoDB ROW_FORMAT = Dynamic ; c_t_begin t2 c_t_mid ENGINE = InnoDB ROW_FORMAT = Compressed ; c_t_begin t3 c_t_mid ENGINE = InnoDB ROW_FORMAT = Compact ; c_t_begin t4 c_t_mid ENGINE = InnoDB ROW_FORMAT = Redundant ; c_t_begin t5 c_t_mid ENGINE = Aria ;

conf/mariadb/table_stress.yy:   ENGINE = InnoDB ROW_FORMAT = Dynamic    |

conf/mariadb/table_stress.yy:   ENGINE = InnoDB ROW_FORMAT = Compressed |

conf/mariadb/table_stress.yy:   ENGINE = InnoDB ROW_FORMAT = Compact    |

conf/mariadb/table_stress.yy:   ENGINE = InnoDB ROW_FORMAT = Redundant  ;

conf/mariadb/versioning.yy:  ROW_FORMAT=COMPACT | ROW_FORMAT=COMPRESSED | ROW_FORMAT=DYNAMIC | ROW_FORMAT=REDUNDANT

conf/mariadb/versioning.yy:vers_ia_compressed:

conf/mariadb/versioning.yy:  | | | | | | COMPRESSED ;

My main workhorses which detected the majority of bugs reported are:

   table_stress

   alter_table

   instant_add

   concurrency

[MDEV-18302] Assertion `!((new_col->prtype ^ col->prtype) & ~256U)' failed in row_log_table_apply_convert_mrec row0log.cc:1646 Created: 2019-01-18 Updated: 2019-04-01 Resolved: 2019-04-01
Status:	Closed
Project:	MariaDB Server
Component/s:	Storage Engine - InnoDB
Affects Version/s:	None
Fix Version/s:	N/A

[MDEV-18302] Assertion `!((new_col->prtype ^ col->prtype) & ~256U)' failed in row_log_table_apply_convert_mrec row0log.cc:1646 Created: 2019-01-18 Updated: 2019-04-01 Resolved: 2019-04-01