[MDEV-12827] Assertion failure when reporting duplicate key error in online table rebuild Created: 2017-05-17  Updated: 2020-08-25  Resolved: 2017-12-21

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Storage Engine - InnoDB
Affects Version/s: 10.0.23, 10.1.10, 10.2.0, 10.1.19, 10.3.0
Fix Version/s: 10.0.34, 10.1.30, 10.2.12, 10.3.4

Type: Bug Priority: Critical
Reporter: Hartmut Holzgraefe Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: upstream

Issue Links:
Blocks
blocks MDEV-13900 Testing for MDEV-11369 (instant ADD C... Closed
Duplicate
is duplicated by MDEV-10602 [Draft] Assertion failed: err_key < h... Closed
is duplicated by MDEV-10706 [Draft] Assertion failed: prebuilt->t... Closed
is duplicated by MDEV-15312 Crash during OPTIMIZE TABLE Closed
Relates
relates to MDEV-5406 add index to an innodb table with a u... Closed
Sprint: 10.2.12

 Description   

During OPTIMIZE TABLE a crash occurred with a backtrace that looks the same as in MDEV-5406.

The fix back then included a comment saying

            HACK HACK HACK
 
            Prepare the list of keys for an error message. 
            It must match what the engine does internally in ::add_index().
            Here we emulate what innobase_create_key_def() does.
            Luckily, in 10.0 this will go away.

The code indeed seems to have changed in 10.1, so maybe the problem resurfaced this way?

170514 2:50:40 [ERROR] mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
 
Server version: 10.1.19-MariaDB
key_buffer_size=16777216
read_buffer_size=262144
max_used_connections=525
max_threads=1002
thread_count=246
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 806479 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x7f7d954eb008
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7eef5265b208 thread_stack 0x48400
(my_addr_resolve failure: fork)
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(my_print_stacktrace+0x2e) [0xc0e2fe]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(handle_fatal_signal+0x4ba) [0x76836a]
/lib64/libpthread.so.0() [0x3fe2a0f7e0]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(key_unpack(String*, TABLE*, st_key*)+0x95) [0x831c35]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(print_keydup_error(TABLE*, st_key*, char const*, unsigned long)+0x76) [0x76e136]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld() [0x91c3e3]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld() [0x63ce0b]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool)+0x3c42) [0x644812]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(mysql_recreate_table(THD*, TABLE_LIST*, bool)+0x196) [0x644a26]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld() [0x69ba5e]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld() [0x69d4da]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(Sql_cmd_optimize_table::execute(THD*)+0xe6) [0x69e5d6]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(mysql_execute_command(THD*)+0x13db) [0x5b38bb]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(mysql_parse(THD*, char*, unsigned int, Parser_state*)+0x354) [0x5bbe54]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld() [0x5bbee8]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x14e5) [0x5bdfc5]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(do_command(THD*)+0x2a7) [0x5bf297]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(do_handle_one_connection(THD*)+0x183) [0x68e853]
/apps/mariadb/instances/sysmdbblpfrm/bin/mysqld(handle_one_connection+0x42) [0x68ea72]
/lib64/libpthread.so.0() [0x3fe2a07aa1]
/lib64/libc.so.6(clone+0x6d) [0x3fe22e8aad]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f7d80b92020): OPTIMIZE TABLE some_db.some_table
Connection ID (thread ID): 10354269
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=off



 Comments   
Comment by Sergei Golubchik [ 2017-05-23 ]

Do you have a test case? Test case from MDEV-5406 is in the test suite and it doesn't crash.

Comment by Hartmut Holzgraefe [ 2017-07-11 ]

No, this was a single incident so far and we only have the error log snippet and backtrace above ...

Comment by Elena Stepanova [ 2017-07-21 ]

Please let's request the obvious – the config file, table structure, data dump or at least SHOW INDEX IN.
And the portion of the error log prior to the crash.

Comment by Elena Stepanova [ 2017-09-24 ]

Test case

# Run with --repeat=N if it doesn't fail right away. 
# I also recommend --mysqld=--lock-wait-timeout=3 --mysqld=--innodb-lock-wait-timeout=2, 
# as it seems that sometimes it can lock up until the timeout is exceeded.
 
--source include/have_innodb.inc
 
CREATE OR REPLACE TABLE t1 (i INT UNIQUE) ENGINE=InnoDB;
--send
  OPTIMIZE TABLE t1;
 
--connect (con1,localhost,root,,test)
--error ER_DUP_ENTRY
INSERT INTO t1 VALUES (1),(1);
 
--connection default
--reap
 
# Cleanup
--disconnect con1
--connection default
DROP TABLE t1;

10.0 78b63425a3f17214b non-debug

#2  <signal handler called>
#3  0x000000000076c626 in field_unpack (to=to@entry=0x7fef60d66710, field=0x7fef60d654b0, rec=0x7fef4b041020 "\375\001", max_length=0, prefix_key=false) at /data/src/10.0/sql/key.cc:359
#4  0x000000000076c77d in key_unpack (to=to@entry=0x7fef60d66710, table=table@entry=0x7fef4b174008, key=key@entry=0x7fef4b1c8670) at /data/src/10.0/sql/key.cc:441
#5  0x00000000006e48d9 in print_keydup_error (table=table@entry=0x7fef4b174008, key=0x7fef4b1c8670, msg=0x7fef5a3aecaa "Duplicate entry '%-.64s' for key '%-.192s'", errflag=errflag@entry=0) at /data/src/10.0/sql/handler.cc:3348
#6  0x00000000006e4a20 in print_keydup_error (table=table@entry=0x7fef4b174008, key=<optimized out>, errflag=errflag@entry=0) at /data/src/10.0/sql/handler.cc:3368
#7  0x00007fef574a081b in commit_try_rebuild (table_name=0x7fef4b02108d "t1", trx=0x7fef4b134c68, old_table=<optimized out>, altered_table=<optimized out>, ctx=<optimized out>, ha_alter_info=<optimized out>) at /data/src/10.0/storage/innobase/handler/handler0alter.cc:5122
#8  ha_innodb::commit_inplace_alter_table (this=0x7fef4b086020, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>) at /data/src/10.0/storage/innobase/handler/handler0alter.cc:5817
#9  0x000000000062044d in mysql_inplace_alter_table (target_mdl_request=<optimized out>, alter_ctx=<optimized out>, inplace_supported=<optimized out>, ha_alter_info=<optimized out>, altered_table=<optimized out>, table=<optimized out>, table_list=<optimized out>, thd=<optimized out>) at /data/src/10.0/sql/sql_table.cc:7145
#10 mysql_alter_table (thd=0x7fef53675008, new_db=0x7fef60d654b0 "\003", new_db@entry=0x0, new_name=0x7fef60d68000 "\200\221\326`\357\177", create_info=0x7fef60d690f0, table_list=0x7fef4b1c70f0, alter_info=0x7fef4b1c70f0, order_num=0, order=0x0, ignore=false) at /data/src/10.0/sql/sql_table.cc:8949
#11 0x0000000000621110 in mysql_recreate_table (thd=thd@entry=0x7fef53675008, table_list=table_list@entry=0x7fef4b1c70f0, table_copy=table_copy@entry=false) at /data/src/10.0/sql/sql_table.cc:9714
#12 0x0000000000665415 in admin_recreate_table (thd=thd@entry=0x7fef53675008, table_list=table_list@entry=0x7fef4b1c70f0) at /data/src/10.0/sql/sql_admin.cc:58
#13 0x0000000000666c5e in mysql_admin_table (thd=thd@entry=0x7fef53675008, tables=tables@entry=0x7fef4b1c70f0, check_opt=check_opt@entry=0x7fef53679690, operator_name=operator_name@entry=0xc0ffd1 "optimize", lock_type=lock_type@entry=TL_WRITE, open_for_modify=false, open_for_modify@entry=true, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=<optimized out>, view_operator_func=0x0) at /data/src/10.0/sql/sql_admin.cc:913
#14 0x0000000000667b84 in Sql_cmd_optimize_table::execute (this=<optimized out>, thd=0x7fef53675008) at /data/src/10.0/sql/sql_admin.cc:1257
#15 0x00000000005a3a87 in mysql_execute_command (thd=0x7fef53675008) at /data/src/10.0/sql/sql_parse.cc:5123
#16 0x00000000005aa0b8 in mysql_parse (thd=0x7fef53675008, rawbuf=<optimized out>, length=17, parser_state=0x7fef60d6a850) at /data/src/10.0/sql/sql_parse.cc:6578
#17 0x00000000005abad9 in dispatch_command (command=<optimized out>, thd=0x7fef53675008, packet=<optimized out>, packet_length=<optimized out>) at /data/src/10.0/sql/sql_parse.cc:1305
#18 0x00000000005ac46f in do_command (thd=<optimized out>) at /data/src/10.0/sql/sql_parse.cc:999
#19 0x000000000065b9e4 in do_handle_one_connection (thd_arg=thd_arg@entry=0x7fef53675008) at /data/src/10.0/sql/sql_connect.cc:1377
#20 0x000000000065ba28 in handle_one_connection (arg=arg@entry=0x7fef53675008) at /data/src/10.0/sql/sql_connect.cc:1292
#21 0x000000000088f6d4 in pfs_spawn_thread (arg=0x7fef5e03f808) at /data/src/10.0/storage/perfschema/pfs.cc:1860
#22 0x00007fef609a8494 in start_thread (arg=0x7fef60d6b700) at pthread_create.c:333
#23 0x00007fef5eaf393f in clone () from /lib/x86_64-linux-gnu/libc.so.6

10.0 78b63425a3f17214b debug

mysqld: /data/src/10.0/storage/innobase/handler/handler0alter.cc:5118: bool commit_try_rebuild(Alter_inplace_info*, ha_innobase_inplace_ctx*, TABLE*, const TABLE*, trx_t*, const char*): Assertion `err_key < ha_alter_info->key_count' failed.
170924 16:12:09 [ERROR] mysqld got signal 6 ;
 
#7  0x00007f8939ab1ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8  0x00007f893236c76a in commit_try_rebuild (ha_alter_info=0x7f893bde2fe0, ctx=0x7f89258fb800, altered_table=0x7f89259a6070, old_table=0x7f892589e470, trx=0x7f8925952278, table_name=0x7f8925861175 "t1") at /data/src/10.0/storage/innobase/handler/handler0alter.cc:5117
#9  0x00007f893236a280 in ha_innodb::commit_inplace_alter_table (this=0x7f892587e088, altered_table=0x7f89259a6070, ha_alter_info=0x7f893bde2fe0, commit=true) at /data/src/10.0/storage/innobase/handler/handler0alter.cc:5817
#10 0x0000000000841067 in handler::ha_commit_inplace_alter_table (this=0x7f892587e088, altered_table=0x7f89259a6070, ha_alter_info=0x7f893bde2fe0, commit=true) at /data/src/10.0/sql/handler.cc:4226
#11 0x00000000006ffa69 in mysql_inplace_alter_table (thd=0x7f892df69070, table_list=0x7f89258fa158, table=0x7f892589e470, altered_table=0x7f89259a6070, ha_alter_info=0x7f893bde2fe0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f893bde2a30, alter_ctx=0x7f893bde35c0) at /data/src/10.0/sql/sql_table.cc:7145
#12 0x000000000070406b in mysql_alter_table (thd=0x7f892df69070, new_db=0x0, new_name=0x0, create_info=0x7f893bde4270, table_list=0x7f89258fa158, alter_info=0x7f893bde41e0, order_num=0, order=0x0, ignore=false) at /data/src/10.0/sql/sql_table.cc:8949
#13 0x0000000000706452 in mysql_recreate_table (thd=0x7f892df69070, table_list=0x7f89258fa158, table_copy=false) at /data/src/10.0/sql/sql_table.cc:9714
#14 0x00000000007768d1 in admin_recreate_table (thd=0x7f892df69070, table_list=0x7f89258fa158) at /data/src/10.0/sql/sql_admin.cc:58
#15 0x0000000000779135 in mysql_admin_table(THD *, TABLE_LIST *, HA_CHECK_OPT *, const char *, thr_lock_type, bool, bool, uint, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *), struct {...}, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *)) (thd=0x7f892df69070, tables=0x7f89258fa158, check_opt=0x7f892df6d830, operator_name=0xec8928 "optimize", lock_type=TL_WRITE, open_for_modify=false, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x840c2e <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0) at /data/src/10.0/sql/sql_admin.cc:913
#16 0x000000000077a18b in Sql_cmd_optimize_table::execute (this=0x7f89258fa740, thd=0x7f892df69070) at /data/src/10.0/sql/sql_admin.cc:1257
#17 0x0000000000652fba in mysql_execute_command (thd=0x7f892df69070) at /data/src/10.0/sql/sql_parse.cc:5123
#18 0x00000000006563f0 in mysql_parse (thd=0x7f892df69070, rawbuf=0x7f89258fa088 "OPTIMIZE TABLE t1", length=17, parser_state=0x7f893bde5640) at /data/src/10.0/sql/sql_parse.cc:6578
#19 0x0000000000648f1d in dispatch_command (command=COM_QUERY, thd=0x7f892df69070, packet=0x7f89339ef071 "", packet_length=17) at /data/src/10.0/sql/sql_parse.cc:1305
#20 0x0000000000648237 in do_command (thd=0x7f892df69070) at /data/src/10.0/sql/sql_parse.cc:999
#21 0x0000000000768052 in do_handle_one_connection (thd_arg=0x7f892df69070) at /data/src/10.0/sql/sql_connect.cc:1377
#22 0x0000000000767dc4 in handle_one_connection (arg=0x7f892df69070) at /data/src/10.0/sql/sql_connect.cc:1292
#23 0x0000000000ac8076 in pfs_spawn_thread (arg=0x7f892df19670) at /data/src/10.0/storage/perfschema/pfs.cc:1860
#24 0x00007f893ba23494 in start_thread (arg=0x7f893bde6700) at pthread_create.c:333
#25 0x00007f8939b6e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Comment by Elena Stepanova [ 2017-11-22 ]

Here is another variation, previously filed as MDEV-10706, but finally with a test case. It causes an identical crash on a non-debug build, but a different assertion failure on a debug build. Please make sure that both variations are fixed before closing the bug.

Note: Run with --repeat=N if it doesn't fail right away. Probably lock timeout recommendations from the previous test case also apply here, although I haven't seen this one lock up.

--source include/have_innodb.inc
 
--connect (con1,localhost,root,,test)
CREATE TABLE t1 (c CHAR DEFAULT '' UNIQUE) ENGINE=InnoDB;
INSERT INTO t1 () VALUES ();
 
--connection default
--send
	ALTER TABLE t1 FORCE;
 
--connection con1
--error ER_NO_SUCH_TABLE
ALTER TABLE non_existing FORCE;
--error ER_DUP_ENTRY
INSERT INTO t1 () VALUES (),(),(),();
 
# Cleanup
--disconnect con1
--connection default
--error 0,ER_DUP_ENTRY
--reap
DROP TABLE t1;

10.0 debug d8ccc61f76d56b761

mysqld: /data/src/10.0/storage/innobase/handler/handler0alter.cc:4177: virtual bool ha_innodb::inplace_alter_table(TABLE*, Alter_inplace_info*): Assertion `prebuilt->trx->error_key_num < ha_alter_info->key_count' failed.
171122 15:16:54 [ERROR] mysqld got signal 6 ;
 
#7  0x00007f04d1458ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8  0x00007f04c9f6768b in ha_innodb::inplace_alter_table (this=0x7f04bd845088, altered_table=0x7f04bd5a6070, ha_alter_info=0x7f04d351c260) at /data/src/10.0/storage/innobase/handler/handler0alter.cc:4176
#9  0x0000000000707b7f in handler::ha_inplace_alter_table (this=0x7f04bd845088, altered_table=0x7f04bd5a6070, ha_alter_info=0x7f04d351c260) at /data/src/10.0/sql/handler.h:3580
#10 0x00000000007003b1 in mysql_inplace_alter_table (thd=0x7f04c5b69070, table_list=0x7f04bd4fa160, table=0x7f04bd913c70, altered_table=0x7f04bd5a6070, ha_alter_info=0x7f04d351c260, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f04d351bcb0, alter_ctx=0x7f04d351c840) at /data/src/10.0/sql/sql_table.cc:7117
#11 0x0000000000704ac7 in mysql_alter_table (thd=0x7f04c5b69070, new_db=0x7f04bd4fa740 "test", new_name=0x0, create_info=0x7f04d351d4e0, table_list=0x7f04bd4fa160, alter_info=0x7f04d351d450, order_num=0, order=0x0, ignore=false) at /data/src/10.0/sql/sql_table.cc:8948
#12 0x000000000076d365 in Sql_cmd_alter_table::execute (this=0x7f04bd4fa748, thd=0x7f04c5b69070) at /data/src/10.0/sql/sql_alter.cc:312
#13 0x000000000065398b in mysql_execute_command (thd=0x7f04c5b69070) at /data/src/10.0/sql/sql_parse.cc:5114
#14 0x0000000000656dc2 in mysql_parse (thd=0x7f04c5b69070, rawbuf=0x7f04bd4fa088 "ALTER TABLE t1 FORCE", length=20, parser_state=0x7f04d351e640) at /data/src/10.0/sql/sql_parse.cc:6569
#15 0x0000000000649901 in dispatch_command (command=COM_QUERY, thd=0x7f04c5b69070, packet=0x7f04cb5ef071 "ALTER TABLE t1 FORCE", packet_length=20) at /data/src/10.0/sql/sql_parse.cc:1296
#16 0x0000000000648c01 in do_command (thd=0x7f04c5b69070) at /data/src/10.0/sql/sql_parse.cc:999
#17 0x0000000000768ab8 in do_handle_one_connection (thd_arg=0x7f04c5b69070) at /data/src/10.0/sql/sql_connect.cc:1377
#18 0x000000000076882a in handle_one_connection (arg=0x7f04c5b69070) at /data/src/10.0/sql/sql_connect.cc:1292
#19 0x0000000000ac9564 in pfs_spawn_thread (arg=0x7f04c5b19670) at /data/src/10.0/storage/perfschema/pfs.cc:1861
#20 0x00007f04d315c494 in start_thread (arg=0x7f04d351f700) at pthread_create.c:333
#21 0x00007f04d151593f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Reproducible on 10.0-10.3, and also on MySQL 5.6.
Not reproducible on 5.5 and on MySQL 5.7, 8.0.3.

Comment by Elena Stepanova [ 2017-11-29 ]

Another variation that is possibly related to the same problem:

10.3 0c6ff122fa080f80c461f77585176c25c284e33d

mysqld: /home/travis/src/sql/sql_admin.cc:1069: bool mysql_admin_table(THD*, TABLE_LIST*, HA_CHECK_OPT*, const char*, thr_lock_type, bool, bool, uint, int (*)(THD*, TABLE_LIST*, HA_CHECK_OPT*), int (handler::*)(THD*, HA_CHECK_OPT*), int (*)(THD*, TABLE_LIST*, HA_CHECK_OPT*)): Assertion `thd->is_error()' failed.
 
#5  0x00007f6269267028 in __GI_abort () at abort.c:89
#6  0x00007f626925cbf6 in __assert_fail_base (fmt=0x7f62693b1018 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x9e996b6d73 "thd->is_error()", file=file@entry=0x9e996b6780 "/home/travis/src/sql/sql_admin.cc", line=line@entry=1069, function=function@entry=0x9e996b70a0 <mysql_admin_table(THD*, TABLE_LIST*, st_ha_check_opt*, char const*, thr_lock_type, bool, bool, unsigned int, int (*)(THD*, TABLE_LIST*, st_ha_check_opt*), int (handler::*)(THD*, st_ha_check_opt*), int (*)(THD*, TABLE_LIST*, st_ha_check_opt*))::__PRETTY_FUNCTION__> "bool mysql_admin_table(THD*, TABLE_LIST*, HA_CHECK_OPT*, const char*, thr_lock_type, bool, bool, uint, int (*)(THD*, TABLE_LIST*, HA_CHECK_OPT*), int (handler::*)(THD*, HA_CHECK_OPT*), int (*)(THD*, T"...) at assert.c:92
#7  0x00007f626925cca2 in __GI___assert_fail (assertion=0x9e996b6d73 "thd->is_error()", file=0x9e996b6780 "/home/travis/src/sql/sql_admin.cc", line=1069, function=0x9e996b70a0 <mysql_admin_table(THD*, TABLE_LIST*, st_ha_check_opt*, char const*, thr_lock_type, bool, bool, unsigned int, int (*)(THD*, TABLE_LIST*, st_ha_check_opt*), int (handler::*)(THD*, st_ha_check_opt*), int (*)(THD*, TABLE_LIST*, st_ha_check_opt*))::__PRETTY_FUNCTION__> "bool mysql_admin_table(THD*, TABLE_LIST*, HA_CHECK_OPT*, const char*, thr_lock_type, bool, bool, uint, int (*)(THD*, TABLE_LIST*, HA_CHECK_OPT*), int (handler::*)(THD*, HA_CHECK_OPT*), int (*)(THD*, T"...) at assert.c:101
#8  0x0000009e98c8e571 in mysql_admin_table(THD *, TABLE_LIST *, HA_CHECK_OPT *, const char *, thr_lock_type, bool, bool, uint, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *), struct {...}, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *)) (thd=0x7f622400b1c0, tables=0x7f622401f720, check_opt=0x7f622400fdf0, operator_name=0x9e996b6ed0 "optimize", lock_type=TL_WRITE, open_for_modify=true, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x9e98dff734 <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0) at /home/travis/src/sql/sql_admin.cc:1069
#9  0x0000009e98c8f61d in Sql_cmd_optimize_table::execute (this=0x7f622401fd38, thd=0x7f622400b1c0) at /home/travis/src/sql/sql_admin.cc:1366
#10 0x0000009e98b31902 in mysql_execute_command (thd=0x7f622400b1c0) at /home/travis/src/sql/sql_parse.cc:6237
#11 0x0000009e98b36261 in mysql_parse (thd=0x7f622400b1c0, rawbuf=0x7f622401f608 "OPTIMIZE TABLE `PP_D` /* QNO 1381 CON_ID 18 */", length=46, parser_state=0x7f625017c620, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:7933
#12 0x0000009e98b23c78 in dispatch_command (command=COM_QUERY, thd=0x7f622400b1c0, packet=0x7f62240174d1 "", packet_length=47, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1828
#13 0x0000009e98b226a5 in do_command (thd=0x7f622400b1c0) at /home/travis/src/sql/sql_parse.cc:1370
#14 0x0000009e98c7afee in do_handle_one_connection (connect=0x9e9c573880) at /home/travis/src/sql/sql_connect.cc:1420
#15 0x0000009e98c7ad7b in handle_one_connection (arg=0x9e9c573880) at /home/travis/src/sql/sql_connect.cc:1326
#16 0x00007f6269e1e184 in start_thread (arg=0x7f625017d700) at pthread_create.c:312
#17 0x00007f626932affd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Comment by Alexander Barkov [ 2017-12-18 ]

Reassigning to Marko, as discussed on slack.

Comment by Marko Mäkelä [ 2017-12-21 ]

Deterministic test case:

--source include/have_innodb.inc
--source include/have_debug.inc
--source include/have_debug_sync.inc
 
CREATE TABLE t1 (i INT UNSIGNED NULL UNIQUE) ENGINE=InnoDB;
--connect (con1,localhost,root,,test)
SET DEBUG_SYNC='row_log_table_apply1_before SIGNAL built WAIT_FOR log';
--send
ALTER TABLE t1 FORCE;
 
--connection default
SET DEBUG_SYNC='now WAIT_FOR built';
--error ER_DUP_ENTRY
INSERT INTO t1 VALUES (0),(0);
SET DEBUG_SYNC='now SIGNAL log';
 
--connection con1
--error ER_DUP_ENTRY
reap;
--disconnect con1
--connection default
SET DEBUG_SYNC='RESET';
DROP TABLE t1;

It does not crash in MySQL 5.7.9 or MySQL 5.7.20. But the assertion failure is triggered in MySQL 5.6.38, and in MariaDB 10.x (tested the most recent 10.0 and 10.2 today).
I do not see anything obvious in the MySQL 5.7 revision history that could have affected this.

Comment by Marko Mäkelä [ 2017-12-21 ]

When comparing MySQL 5.7.9 to recent MariaDB, it occured to me that there was a fix in MySQL 5.6.28 and 5.7.10 for a very similar scenario (the difference being that a PRIMARY KEY was specified).
It turns out that this fix was merged incorrectly into MySQL 5.7.10. For some reason, the n_index+ statements were omitted, causing MySQL 5.7.10 to always incorrectly report the first key as the source of duplicates. Because the test case used a PRIMARY KEY, the error would incorrectly be reported to it, instead of the UNIQUE KEY.

git diff 449b27fc3205383c62f8c8005b9019be44c8c8b8{~,}| diff -I^@@ -u - <(git diff 449b27fc3205383c62f8c8005b9019be44c8c8b8^2{~,})
--- -	2017-12-21 15:44:32.788667258 +0200
+++ /dev/fd/63	2017-12-21 15:44:32.779964718 +0200
@@ -1,17 +1,16 @@
 diff --git a/mysql-test/suite/innodb/r/innodb-alter-debug.result b/mysql-test/suite/innodb/r/innodb-alter-debug.result
-index 2c9cfe850a9..c6fa1ed0072 100644
+index 2c9cfe850a9..229808df1b4 100644
 --- a/mysql-test/suite/innodb/r/innodb-alter-debug.result
 +++ b/mysql-test/suite/innodb/r/innodb-alter-debug.result
-@@ -24,3 +24,32 @@ t1ć	CREATE TABLE `t1ć` (
+@@ -24,3 +24,31 @@ t1ć	CREATE TABLE `t1ć` (
    CONSTRAINT `t1c2` FOREIGN KEY (`c2`) REFERENCES `①` (`c2`)
  ) ENGINE=InnoDB DEFAULT CHARSET=latin1
  DROP TABLE t1ć, ①;
 +#
-+# Bug #21364096	THE BOGUS DUPLICATE KEY ERROR IN ONLINE DDL
-+#		WITH INCORRECT KEY NAME
-+create table t1 (id int auto_increment primary key,
-+a int,
-+unique key uk(a))engine=innodb;
++# Bug #21364096  THE BOGUS DUPLICATE KEY ERROR IN ONLINE DDL
++#                WITH INCORRECT KEY NAME
++create table t1 (id int auto_increment primary key, a int, unique key uk(a))
++engine = innodb;
 +insert into t1 select 1, 1;
 +insert into t1 select 2, 2;
 +SET DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL s1 WAIT_FOR s2';
@@ -23,7 +22,7 @@
 +SET DEBUG_SYNC = 'now SIGNAL s2';
 +/* connection default */
 +/* reap */ alter table t1 add b int, ALGORITHM=inplace;
-+ERROR 23000: Duplicate entry '3' for key 'PRIMARY'
++ERROR 23000: Duplicate entry '1' for key 'uk'
 +SET DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL s1 WAIT_FOR s2';
 +alter table t1 add b int, ALGORITHM=inplace;;
 +/* connection con1 */
@@ -33,10 +32,10 @@
 +SET DEBUG_SYNC = 'now SIGNAL s2';
 +/* connection default */
 +/* reap */ alter table t1 add b int, ALGORITHM=inplace;
-+ERROR 23000: Duplicate entry '2' for key 'PRIMARY'
++ERROR 23000: Duplicate entry '1' for key 'uk'
 +drop table t1;
 diff --git a/mysql-test/suite/innodb/t/innodb-alter-debug.test b/mysql-test/suite/innodb/t/innodb-alter-debug.test
-index 48cef81df7e..59cc1307c84 100644
+index 48cef81df7e..5ab32ed14da 100644
 --- a/mysql-test/suite/innodb/t/innodb-alter-debug.test
 +++ b/mysql-test/suite/innodb/t/innodb-alter-debug.test
 @@ -1,5 +1,8 @@
@@ -48,18 +47,17 @@
  
  SET NAMES utf8;
  
-@@ -26,3 +29,50 @@ SET DEBUG = '-d,ib_rename_column_error';
+@@ -26,3 +29,49 @@ SET DEBUG = '-d,ib_rename_column_error';
  SHOW CREATE TABLE t1ć;
  
  DROP TABLE t1ć, ①;
 +
 +--echo #
-+--echo # Bug #21364096	THE BOGUS DUPLICATE KEY ERROR IN ONLINE DDL
-+--echo #		WITH INCORRECT KEY NAME
++--echo # Bug #21364096  THE BOGUS DUPLICATE KEY ERROR IN ONLINE DDL
++--echo #                WITH INCORRECT KEY NAME
 +
-+create table t1 (id int auto_increment primary key,
-+		 a int,
-+		 unique key uk(a))engine=innodb;
++create table t1 (id int auto_increment primary key, a int, unique key uk(a))
++engine = innodb;
 +insert into t1 select 1, 1;
 +insert into t1 select 2, 2;
 +SET DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL s1 WAIT_FOR s2';
@@ -100,10 +98,10 @@
 +# Wait till all disconnects are completed
 +--source include/wait_until_count_sessions.inc
 diff --git a/storage/innobase/row/row0log.cc b/storage/innobase/row/row0log.cc
-index b43207ac8fa..d6e2a139b75 100644
+index f88baa42d58..3989b669c28 100644
 --- a/storage/innobase/row/row0log.cc
 +++ b/storage/innobase/row/row0log.cc
-@@ -1613,6 +1613,7 @@ row_log_table_apply_insert_low(
+@@ -1454,6 +1454,7 @@ row_log_table_apply_insert_low(
  	dtuple_t*	entry;
  	const row_log_t*log	= dup->index->online_log;
  	dict_index_t*	index	= dict_table_get_first_index(log->table);
@@ -111,10 +109,19 @@
  
  	ut_ad(dtuple_validate(row));
  	ut_ad(trx_id);
-@@ -1658,6 +1659,12 @@ row_log_table_apply_insert_low(
+@@ -1489,6 +1490,8 @@ row_log_table_apply_insert_low(
+ 	}
+ 
+ 	do {
++		n_index++;
++
+ 		if (!(index = dict_table_get_next_index(index))) {
+ 			break;
+ 		}
+@@ -1501,6 +1504,12 @@ row_log_table_apply_insert_low(
+ 		error = row_ins_sec_index_entry_low(
  			flags, BTR_MODIFY_TREE,
- 			index, offsets_heap, heap, entry, trx_id, thr,
- 			false);
+ 			index, offsets_heap, heap, entry, trx_id, thr);
 +
 +		/* Report correct index name for duplicate key error. */
 +		if (error == DB_DUPLICATE_KEY) {
@@ -132,9 +139,18 @@
  
  	ut_ad(dtuple_get_n_fields_cmp(old_pk)
  	      == dict_index_get_n_unique(index));
-@@ -2308,6 +2316,11 @@ func_exit_committed:
+@@ -2083,6 +2093,8 @@ func_exit_committed:
+ 			break;
+ 		}
+ 
++		n_index++;
++
+ 		if (index->type & DICT_FTS) {
+ 			continue;
+ 		}
+@@ -2126,6 +2138,11 @@ func_exit_committed:
  			BTR_MODIFY_TREE, index, offsets_heap, heap,
- 			entry, trx_id, thr, false);
+ 			entry, trx_id, thr);
  
 +		/* Report correct index name for duplicate key error. */
 +		if (error == DB_DUPLICATE_KEY) {
@@ -142,5 +158,5 @@
 +		}
 +
  		mtr_start(&mtr);
- 		mtr.set_named_space(index->space);
  	}
+ 

Comment by Marko Mäkelä [ 2017-12-21 ]

It looks like this bug is a regression from the already mentioned upstream fix in MySQL 5.6.28, which was incorrectly merged to 5.7.10.

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