[MDEV-18596] ASAN unknown-crash in row_mysql_store_col_in_innobase_format upon MODIFY / ADD column Created: 2019-02-15  Updated: 2019-02-18  Resolved: 2019-02-18

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Storage Engine - InnoDB
Affects Version/s: 10.4.3
Fix Version/s: 10.4.3

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: regression

Issue Links:
Problem/Incident
is caused by MDEV-15563 Instant failure-free data type conver... Closed
Relates
relates to MDEV-18326 Refactor some ALTER column operations... Stalled

 Description    

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (f TINYINT NOT NULL DEFAULT 0) ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
 
ALTER TABLE t1 MODIFY f INT NOT NULL DEFAULT 0, ADD d DATETIME, ALGORITHM=INPLACE;
 
 
 
# Cleanup
 
DROP TABLE t1;

10.4 a081a998 ASAN

 
==18066==ERROR: AddressSanitizer: unknown-crash on address 0x6190000f6f12 at pc 0x557d25771c97 bp 0x7fc5d6e2e190 sp 0x7fc5d6e2e188
 
READ of size 1 at 0x6190000f6f12 thread T27
 
    #0 0x557d25771c96 in row_mysql_store_col_in_innobase_format(dfield_t*, unsigned char*, unsigned long, unsigned char const*, unsigned long, unsigned long) /data/src/10.4/storage/innobase/row/row0mysql.cc:437
 
    #1 0x557d255375f1 in innobase_build_col_map_add /data/src/10.4/storage/innobase/handler/handler0alter.cc:4151
 
    #2 0x557d2553817d in innobase_build_col_map /data/src/10.4/storage/innobase/handler/handler0alter.cc:4243
 
    #3 0x557d25545aa6 in prepare_inplace_alter_table_dict /data/src/10.4/storage/innobase/handler/handler0alter.cc:6342
 
    #4 0x557d255539b5 in ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) /data/src/10.4/storage/innobase/handler/handler0alter.cc:8091
 
    #5 0x557d24d03e10 in handler::ha_prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) /data/src/10.4/sql/handler.cc:4649
 
    #6 0x557d24777301 in mysql_inplace_alter_table /data/src/10.4/sql/sql_table.cc:7530
 
    #7 0x557d247848c1 in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /data/src/10.4/sql/sql_table.cc:9715
 
    #8 0x557d248d314c in Sql_cmd_alter_table::execute(THD*) /data/src/10.4/sql/sql_alter.cc:499
 
    #9 0x557d24563426 in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:6318
 
    #10 0x557d2456de80 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:8129
 
    #11 0x557d2454607f in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1808
 
    #12 0x557d245430ac in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1358
 
    #13 0x557d248c3a3b in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1399
 
    #14 0x557d248c3434 in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1302
 
    #15 0x557d2547e476 in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
 
    #16 0x7fc5e27d9493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #17 0x7fc5e0bbf93e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x6190000f6f12 is located 146 bytes inside of 1100-byte region [0x6190000f6e80,0x6190000f72cc)
 
allocated by thread T27 here:
 
    #0 0x7fc5e2a4373f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
 
    #1 0x557d25e294e1 in sf_malloc /data/src/10.4/mysys/safemalloc.c:118
 
    #2 0x557d25df9e5e in my_malloc /data/src/10.4/mysys/my_malloc.c:101
 
    #3 0x557d25dd99b9 in alloc_root /data/src/10.4/mysys/my_alloc.c:250
 
    #4 0x557d25ddb3b5 in strmake_root /data/src/10.4/mysys/my_alloc.c:479
 
    #5 0x557d248061e3 in open_table_from_share(THD*, TABLE_SHARE*, st_mysql_const_lex_string const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, List<String>*) /data/src/10.4/sql/table.cc:3219
 
    #6 0x557d243e7234 in open_table(THD*, TABLE_LIST*, Open_table_context*) /data/src/10.4/sql/sql_base.cc:2035
 
    #7 0x557d243eee13 in open_and_process_table /data/src/10.4/sql/sql_base.cc:3728
 
    #8 0x557d243f1c1b in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.4/sql/sql_base.cc:4261
 
    #9 0x557d24749082 in open_tables /data/src/10.4/sql/sql_base.h:257
 
    #10 0x557d24781832 in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /data/src/10.4/sql/sql_table.cc:9111
 
    #11 0x557d248d314c in Sql_cmd_alter_table::execute(THD*) /data/src/10.4/sql/sql_alter.cc:499
 
    #12 0x557d24563426 in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:6318
 
    #13 0x557d2456de80 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:8129
 
    #14 0x557d2454607f in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1808
 
    #15 0x557d245430ac in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1358
 
    #16 0x557d248c3a3b in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1399
 
    #17 0x557d248c3434 in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1302
 
    #18 0x557d2547e476 in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
 
    #19 0x7fc5e27d9493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
Thread T27 created by T0 here:
 
    #0 0x7fc5e2a12bba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x557d2547ea3e in spawn_thread_v1 /data/src/10.4/storage/perfschema/pfs.cc:1912
 
    #2 0x557d24298a36 in inline_mysql_thread_create /data/src/10.4/include/mysql/psi/mysql_thread.h:1268
 
    #3 0x557d242ae260 in create_thread_to_handle_connection(CONNECT*) /data/src/10.4/sql/mysqld.cc:6192
 
    #4 0x557d242ae965 in create_new_thread(CONNECT*) /data/src/10.4/sql/mysqld.cc:6262
 
    #5 0x557d242aecf5 in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /data/src/10.4/sql/mysqld.cc:6360
 
    #6 0x557d242af941 in handle_connections_sockets() /data/src/10.4/sql/mysqld.cc:6518
 
    #7 0x557d242ada9b in mysqld_main(int, char**) /data/src/10.4/sql/mysqld.cc:5850
 
    #8 0x557d242968bf in main /data/src/10.4/sql/main.cc:25
 
    #9 0x7fc5e0af72b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
 
 
 
SUMMARY: AddressSanitizer: unknown-crash /data/src/10.4/storage/innobase/row/row0mysql.cc:437 row_mysql_store_col_in_innobase_format(dfield_t*, unsigned char*, unsigned long, unsigned char const*, unsigned long, unsigned long)
 
Shadow bytes around the buggy address:
 
  0x0c3280016d90: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c3280016da0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c3280016db0: f7 f7 f7 f7 f7 f7 f7 f7 f7 04 fa fa fa fa fa fa
 
  0x0c3280016dc0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3280016dd0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
=>0x0c3280016de0: 00 03[02]02 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0c3280016df0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0c3280016e00: 00 00 00 00 00 04 00 00 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c3280016e10: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c3280016e20: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0c3280016e30: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
Shadow byte legend (one shadow byte represents 8 application bytes):
 
  Addressable:           00
 
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
 
  Heap right redzone:      fb
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack partial redzone:   f4
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Contiguous container OOB:fc
 
  ASan internal:           fe
 
==18066==ABORTING

No obvious immediate effect on a non-debug build.
Not reproducible on 10.3. Not reproducible on 10.4 f4f8dd69. Both say instead

mysqltest: At line 4: query 'ALTER TABLE t1 MODIFY f INT NOT NULL DEFAULT 0, ADD d DATETIME, ALGORITHM=INPLACE' failed: 1846: ALGORITHM=INPLACE is not supported. Reason: Cannot change column type INPLACE. Try ALGORITHM=COPY



 Comments   
Comment by Marko Mäkelä [ 2019-02-18 ]

The original plan with MDEV-15563 and MDEV-15564 was to refactor all instant ALTER TABLE operations so that they will go through the same code path. But, MDEV-18326 had to be postponed because of complications that were too hard to fix in the available time.

The test case features a combination of column type change and an instant ADD COLUMN, and InnoDB forgot to adjust the metadata for the column type change.

Comment by Marko Mäkelä [ 2019-02-18 ]

The immediate problem is demonstrated by this patch:

diff --git a/storage/innobase/handler/handler0alter.cc b/storage/innobase/handler/handler0alter.cc
 
index b0f87fdae9e..c47860b3241 100644
 
--- a/storage/innobase/handler/handler0alter.cc
 
+++ b/storage/innobase/handler/handler0alter.cc
 
@@ -4142,6 +4142,7 @@ static void innobase_build_col_map_add(
 
 	}
 
 
 	ulint	size	= field->pack_length();
 
+	DBUG_ASSERT(!old_field || size == old_field->pack_length());
 
 
 	byte*	buf	= static_cast<byte*>(mem_heap_alloc(heap, size));

I would suggest adding the test into innodb.instant_alter (using eval CREATE…$engine). Here is my starting point for the test:

--source include/have_innodb.inc
 
CREATE TABLE t1 (
 
  c VARCHAR(10) NOT NULL DEFAULT '',
 
  f TINYINT NOT NULL DEFAULT -42)
 
ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
 
INSERT INTO t1() VALUES();
 
--enable_info
 
ALTER TABLE t1 MODIFY f INT NOT NULL DEFAULT 1234567,
 
MODIFY c VARCHAR(20) NOT NULL DEFAULT 'foo',
 
ADD d DATETIME;
 
--disable_info
 
INSERT INTO t1() VALUES();
 
SELECT * FROM t1;
 
DROP TABLE t1;

Similar to the MDEV-18598 fix to row_sel_field_store_in_mysql_format_func(), we may have to extend the shorter default value to the longer one.

Comment by Marko Mäkelä [ 2019-02-18 ]

The above assertion also fails in an existing test:

10.4 19c6a7bbd75d8a72716ecba3aa32d4e9f13daebb

 
CURRENT_TEST: innodb.alter_not_null
 
mysqltest: At line 36: query 'ALTER TABLE t1 CHANGE f1 f1 VARCHAR(20) NOT NULL' failed with wrong errno 2013: 'Lost connection to MySQL server during query', instead of 0...
 
…
 
CURRENT_TEST: innodb.alter_varchar_change
 
mysqltest: At line 205: query 'ALTER TABLE t1 MODIFY f2 VARCHAR(200), ADD COLUMN f3 INT, ALGORITHM=INSTANT' failed: 2013: Lost connection to MySQL server during query

Comment by Aleksey Midenkov [ 2019-02-18 ]

Suggested fix:

--- a/storage/innobase/handler/handler0alter.cc
 
+++ b/storage/innobase/handler/handler0alter.cc
 
@@ -4141,12 +4141,11 @@ static void innobase_build_col_map_add(
 
                return;
 
        }
 
 
-       ulint   size    = field->pack_length();
 
-
 
+       const Field*    from = old_field ? old_field : field;
 
+       const byte*     mysql_data = from->ptr;
 
+       ulint   size    = from->pack_length();
 
        byte*   buf     = static_cast<byte*>(mem_heap_alloc(heap, size));
 
 
-       const byte*     mysql_data = old_field ? old_field->ptr : field->ptr;
 
-
 
        row_mysql_store_col_in_innobase_format(
 
                dfield, buf, true, mysql_data, size, comp);
 
 }

Generated at Thu Feb 08 08:45:18 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.