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

Assertion `!((new_col->prtype ^ col->prtype) & ~256U)' failed in row_log_table_apply_convert_mrec

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 10.4, 10.5
    • Fix Version/s: 10.4.12, 10.5.1
    • Labels:
      None
    • Environment:
      Debian Stretch SMP Debian 4.9.168-1+deb9u5 (2019-08-11) x86_64 GNU/Linux, gcc (Debian 6.3.0-18+deb9u1), rr version 5.3.0

      Description

      Notes:
      The test case is non-deterministic, run with --repeat=N with big enough N. It usually fails for me within ~10 attempts, but sometimes takes much longer, so give it enough time. The failure happens both on disk and in shm, I don't have any statistics to say whether one is more probable than the other, so run in shm, the test case itself is much faster there.
      Also note the comment in the test case about the use of SP.
      rr trace from the failure along with mysqld binary can be found here. Produced on Debian Stretch. Source code 25918576.

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (pk INT, f VARCHAR(8), PRIMARY KEY(pk)) ENGINE=InnoDB;
       
      --connect (con1,localhost,root,,test)
      --send
        ALTER TABLE t1 MODIFY f VARCHAR(256) NOT NULL;
       
      --connection default
       
      # SP call is unrelated to the problem, it is here just for timing.
      # SLEEP can be used instead, but on some reason SP call works better
      # for me. In any case it should be replaced by proper synchronization
      --error ER_SP_DOES_NOT_EXIST
      CALL non_existing_sp;
       
      INSERT INTO t1 VALUES (1,'foo');
       
      # Cleanup
      --connection con1
      --reap
      --disconnect con1
      --connection default
      DROP TABLE t1;
      

      10.4 25918576

      mysqld: /data/src/10.4/storage/innobase/row/row0log.cc:1654: const dtuple_t* row_log_table_apply_convert_mrec(const mrec_t*, dict_index_t*, const offset_t*, row_log_t*, mem_heap_t*, dberr_t*): Assertion `!((new_col->prtype ^ col->prtype) & ~256U)' failed.
      200121 13:30:17 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007f574c211f12 in __GI___assert_fail (assertion=0x557914bd4478 "!((new_col->prtype ^ col->prtype) & ~256U)", file=0x557914bd3968 "/data/src/10.4/storage/innobase/row/row0log.cc", line=1654, function=0x557914bd6e00 <row_log_table_apply_convert_mrec(unsigned char const*, dict_index_t*, unsigned short 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 offset_t*, row_log_t*, mem_heap_t*, dberr_t*)") at assert.c:101
      #8  0x00005579143a77ba in row_log_table_apply_convert_mrec (mrec=0x7f5744173004 "\200", index=0x7f56f41cd698, offsets=0x7f56f802e300, log=0x7f56f80315e0, heap=0x7f56f8083ce0, error=0x7f5745591eac) at /data/src/10.4/storage/innobase/row/row0log.cc:1654
      #9  0x00005579143a7fbf in row_log_table_apply_insert (thr=0x7f56f8080088, mrec=0x7f5744173004 "\200", offsets=0x7f56f802e300, offsets_heap=0x7f56f80dbfb0, heap=0x7f56f8083ce0, dup=0x7f5745592250) at /data/src/10.4/storage/innobase/row/row0log.cc:1785
      #10 0x00005579143aae43 in row_log_table_apply_op (thr=0x7f56f8080088, new_trx_id_col=1, dup=0x7f5745592250, error=0x7f5745591fcc, offsets_heap=0x7f56f80dbfb0, heap=0x7f56f8083ce0, mrec=0x7f5744173004 "\200", mrec_end=0x7f5744173018 "", offsets=0x7f56f802e300) at /data/src/10.4/storage/innobase/row/row0log.cc:2478
      #11 0x00005579143adb9f in row_log_table_apply_ops (thr=0x7f56f8080088, dup=0x7f5745592250, stage=0x7f56f8082490) at /data/src/10.4/storage/innobase/row/row0log.cc:3037
      #12 0x00005579143ae2fb in row_log_table_apply (thr=0x7f56f8080088, old_table=0x7f56f419f628, table=0x7f5745593800, stage=0x7f56f8082490, new_table=0x7f56f8080458) at /data/src/10.4/storage/innobase/row/row0log.cc:3143
      #13 0x00005579142388ea in alter_rebuild_apply_log (ctx=0x7f56f8013770, ha_alter_info=0x7f5745593770, altered_table=0x7f5745593800) at /data/src/10.4/storage/innobase/handler/handler0alter.cc:10591
      #14 0x00005579142397de in ha_innobase::commit_inplace_alter_table (this=0x7f56f802f288, altered_table=0x7f5745593800, ha_alter_info=0x7f5745593770, commit=true) at /data/src/10.4/storage/innobase/handler/handler0alter.cc:10790
      #15 0x0000557913fa6f3f in handler::ha_commit_inplace_alter_table (this=0x7f56f802f288, altered_table=0x7f5745593800, ha_alter_info=0x7f5745593770, commit=true) at /data/src/10.4/sql/handler.cc:4568
      #16 0x0000557913d286fa in mysql_inplace_alter_table (thd=0x7f56f8000af0, table_list=0x7f56f8012038, table=0x7f56f80773a0, altered_table=0x7f5745593800, ha_alter_info=0x7f5745593770, inplace_supported=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x7f57455945d0, alter_ctx=0x7f5745595100) at /data/src/10.4/sql/sql_table.cc:7776
      #17 0x0000557913d2f34d in mysql_alter_table (thd=0x7f56f8000af0, new_db=0x7f56f80052b0, new_name=0x7f56f80056b8, create_info=0x7f5745595cf0, table_list=0x7f56f8012038, alter_info=0x7f5745595c30, order_num=0, order=0x0, ignore=false) at /data/src/10.4/sql/sql_table.cc:10119
      #18 0x0000557913dc7441 in Sql_cmd_alter_table::execute (this=0x7f56f8012828, thd=0x7f56f8000af0) at /data/src/10.4/sql/sql_alter.cc:508
      #19 0x0000557913c45e0d in mysql_execute_command (thd=0x7f56f8000af0) at /data/src/10.4/sql/sql_parse.cc:6102
      #20 0x0000557913c4b4cf in mysql_parse (thd=0x7f56f8000af0, rawbuf=0x7f56f8011f30 "ALTER TABLE t1 MODIFY f VARCHAR(256) NOT NULL", length=45, parser_state=0x7f5745597160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7901
      #21 0x0000557913c3669c in dispatch_command (command=COM_QUERY, thd=0x7f56f8000af0, packet=0x7f56f80083a1 "ALTER TABLE t1 MODIFY f VARCHAR(256) NOT NULL", packet_length=45, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
      #22 0x0000557913c34d29 in do_command (thd=0x7f56f8000af0) at /data/src/10.4/sql/sql_parse.cc:1360
      #23 0x0000557913dbdd51 in do_handle_one_connection (connect=0x55791788d8e0) at /data/src/10.4/sql/sql_connect.cc:1412
      #24 0x0000557913dbdaa0 in handle_one_connection (arg=0x55791788d8e0) at /data/src/10.4/sql/sql_connect.cc:1316
      #25 0x00005579147c54b7 in pfs_spawn_thread (arg=0x5579177fa360) at /data/src/10.4/storage/perfschema/pfs.cc:1862
      #26 0x00007f574e19a4a4 in start_thread (arg=0x7f5745598700) at pthread_create.c:456
      #27 0x00007f574c2ced0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      Reproducible on 10.4, 10.5. Couldn't reproduce on 10.3.
      No obvious effect on a non-debug build, but it can be due to a different timing.

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                Created:
                Updated:
                Resolved: