[MDEV-11995] ALTER TABLE proceeds despite reporting ER_TOO_LONG_KEY error Created: 2017-02-05  Updated: 2017-04-17  Resolved: 2017-04-07

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.2.3
Fix Version/s: 10.2.6

Type: Bug Priority: Major
Reporter: Nirbhay Choubey (Inactive) Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: 10.2-ga

Issue Links:
Relates
relates to MDEV-7635 update defaults and simplify mysqld c... Closed

 Description   

How to repeat:
1. Start server with --sql_mode='STRICT_TRANS_TABLES'
2. Execute the following commands:

MariaDB [test]> create table t1(a TEXT not null) ROW_FORMAT=DYNAMIC;
Query OK, 0 rows affected (0.02 sec)
 
MariaDB [test]> create index idx1 on t1(a(3073));
ERROR 2013 (HY000): Lost connection to MySQL server during query

Stacktrace:

2017-02-04 21:32:18 140557726610176 [Note] InnoDB: Online DDL : Start applying row log
2017-02-04 21:32:18 140557726610176 [Note] InnoDB: Online DDL : End of applying row log
2017-02-04 21:32:18 140557726610176 [Note] InnoDB: Online DDL : Completed
mysqld: /home/nirbhay/project/git-repo/mariadb/10.2/sql/sql_error.cc:380: void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*): Assertion `!is_set() || (m_status == DA_OK_BULK && is_bulk_op())' failed.
170204 21:32:18 [ERROR] mysqld got signal 6 ;
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.2.4-MariaDB-debug
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=7
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467287 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x7fd604417070
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 = 0x7fd6255d6a80 thread_stack 0x48c00
./bin/mysqld(my_print_stacktrace+0x38)[0x558e471ce1cb]
addr2line: './bin/mysqld': No such file
./bin/mysqld(handle_fatal_signal+0x3a3)[0x558e46a3b896]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fd62390b390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7fd622cc5428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fd622cc702a]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dbd7)[0x7fd622cbdbd7]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7fd622cbdc82]
./bin/mysqld(_ZN16Diagnostics_area13set_ok_statusEyyPKc+0x89)[0x558e467a7961]
./bin/mysqld(_Z5my_okP3THDyyPKc+0x4e)[0x558e4675cd0d]
./bin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x2931)[0x558e468a5893]
./bin/mysqld(_Z21mysql_execute_commandP3THD+0x2f9a)[0x558e467d5366]
./bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x29d)[0x558e467e184b]
./bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0xf2f)[0x558e467cf6a1]
./bin/mysqld(_Z10do_commandP3THD+0x712)[0x558e467ce092]
./bin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x1ca)[0x558e469165b1]
./bin/mysqld(handle_one_connection+0x30)[0x558e46916331]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fd6239016ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fd622d9682d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fd604461088): create index idx1 on t1(a(3073))
Connection ID (thread ID): 7
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
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Aborted (core dumped)



 Comments   
Comment by Elena Stepanova [ 2017-02-06 ]

10.2 d123ed852a2

mysqld: /data/src/10.2/sql/sql_error.cc:380: void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*): Assertion `!is_set() || (m_status == DA_OK_BULK && is_bulk_op())' failed.
170206 16:22:08 [ERROR] mysqld got signal 6 ;
 
#7  0x00007fcb4ac42312 in __GI___assert_fail (assertion=0x7fcb4e1a06f0 "!is_set() || (m_status == DA_OK_BULK && is_bulk_op())", file=0x7fcb4e1a0628 "/data/src/10.2/sql/sql_error.cc", line=380, function=0x7fcb4e1a0b40 <Diagnostics_area::set_ok_status(unsigned long long, unsigned long long, char const*)::__PRETTY_FUNCTION__> "void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*)") at assert.c:101
#8  0x00007fcb4d6f9149 in Diagnostics_area::set_ok_status (this=0x7fcb31c1b060, affected_rows=0, last_insert_id=0, message=0x7fcb4e833710 "Records: 0  Duplicates: 0  Warnings: 1") at /data/src/10.2/sql/sql_error.cc:380
#9  0x00007fcb4d6ae5b3 in my_ok (thd=0x7fcb31c16070, affected_rows=0, id=0, message=0x7fcb4e833710 "Records: 0  Duplicates: 0  Warnings: 1") at /data/src/10.2/sql/sql_class.h:4336
#10 0x00007fcb4d7f75e5 in mysql_alter_table (thd=0x7fcb31c16070, new_db=0x7fcb31c64788 "test", new_name=0x7fcb31c64148 "t1", create_info=0x7fcb4e834500, table_list=0x7fcb31c64180, alter_info=0x7fcb4e834450, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9550
#11 0x00007fcb4d726d2a in mysql_execute_command (thd=0x7fcb31c16070) at /data/src/10.2/sql/sql_parse.cc:3981
#12 0x00007fcb4d732f8c in mysql_parse (thd=0x7fcb31c16070, rawbuf=0x7fcb31c64088 "create index idx1 on t1(a(3073))", length=32, parser_state=0x7fcb4e834dd0, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7842
#13 0x00007fcb4d721097 in dispatch_command (command=COM_QUERY, thd=0x7fcb31c16070, packet=0x7fcb31c58071 "create index idx1 on t1(a(3073))", packet_length=32, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1800
#14 0x00007fcb4d71fa8f in do_command (thd=0x7fcb31c16070) at /data/src/10.2/sql/sql_parse.cc:1360
#15 0x00007fcb4d868390 in do_handle_one_connection (connect=0x7fcb4a471f70) at /data/src/10.2/sql/sql_connect.cc:1354
#16 0x00007fcb4d86811d in handle_one_connection (arg=0x7fcb4a471f70) at /data/src/10.2/sql/sql_connect.cc:1260
#17 0x00007fcb4dbabaa2 in pfs_spawn_thread (arg=0x7fcb41bbf870) at /data/src/10.2/storage/perfschema/pfs.cc:1862
#18 0x00007fcb4cd4f0a4 in start_thread (arg=0x7fcb4e836300) at pthread_create.c:309
#19 0x00007fcb4acfc87d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Comment by Elena Stepanova [ 2017-02-06 ]

Assigning to marko as it seems to only happen with InnoDB. Please re-assign if needed.

Comment by Marko Mäkelä [ 2017-02-08 ]

I think that in order to properly fix this, we must fix handler::max_supported_key_part_length() and possibly handler::max_supported_key_length() so that they will take ROW_FORMAT into account. Long time ago, I filed MySQL Bug#76096 for suggesting this fix.

The assertion apparently fails because mysql_alter_table() fails to notice that an error has been reported.

Comment by Marko Mäkelä [ 2017-02-08 ]

Isn’t this repeatable on 10.0 or 10.1 when setting --innodb_large_prefix=1 --innodb-file-per-table=1 --innodb-file-format=barracuda?

Comment by Marko Mäkelä [ 2017-02-08 ]

On 10.0 without setting SQL_MODE, I get a proper warning or error reported (depending on whether SQL_MODE is assigned):

--source include/have_innodb.inc
 
SET GLOBAL innodb_file_per_table=1;
SET GLOBAL innodb_large_prefix=1;
SET GLOBAL innodb_file_format=barracuda;
SET SQL_MODE='STRICT_TRANS_TABLES';
 
CREATE TABLE t1(a TEXT NOT NULL) ROW_FORMAT=DYNAMIC DEFAULT CHARSET latin1;
CREATE INDEX idx1 ON t1(a(3072));
 
DROP TABLE t1;

mysqltest: At line 9: query 'CREATE INDEX idx1 ON t1(a(3073))' failed: 1071: Specified key was too long; max key length is 1000 bytes

This appears to mean that 10.0 is not compatible with MySQL 5.5, which allows key prefixes up to 3072 bytes when the above settings are in effect.

Note: the above test uses 3072 instead of 3073, to test the expected-valid scenario first.

Comment by Marko Mäkelä [ 2017-02-08 ]

I got the same result with 10.1.22 and 10.0.30: the maximum length is only 1000.

Comment by Elena Stepanova [ 2017-02-08 ]

marko,

You are creating MyISAM table in your test, which is probably not what you were trying to achieve. Try this:

--source include/have_innodb.inc
 
SET GLOBAL innodb_file_per_table=1;
SET GLOBAL innodb_large_prefix=1;
SET GLOBAL innodb_file_format=barracuda;
SET SQL_MODE='STRICT_TRANS_TABLES';
 
CREATE TABLE t1(a TEXT NOT NULL) ENGINE=InnoDB ROW_FORMAT=DYNAMIC DEFAULT CHARSET latin1;
CREATE INDEX idx1 ON t1(a(3072));
 
DROP TABLE t1;

Comment by Marko Mäkelä [ 2017-02-09 ]

elenst, thanks for the suggestion. Indeed, after adding ENGINE=InnoDB it works in 10.0, 10.1, and 10.2 when using the maximum size 3072 bytes.
In 10.0 and 10.1, changing the 3072 to 3073 causes a proper failure, no crash. It only crashes in 10.2.

mysqltest: At line 9: query 'CREATE INDEX idx1 ON t1(a(3073))' failed: 1071: Specified key was too long; max key length is 3072 bytes

Comment by Marko Mäkelä [ 2017-02-09 ]

In 10.2, ha_innobase::prepare_inplace_alter_table() is invoked with a truncated key_length (3072 instead of the requested 3073):

(gdb) p ha_alter_info->key_info_buffer[0]
$4 = {key_length = 3072, flags = 65576, user_defined_key_parts = 1, 
  usable_key_parts = 0, ext_key_parts = 0, ext_key_flags = 0, 
  ext_key_part_map = 0, block_size = 0, name_length = 0, 
  algorithm = HA_KEY_ALG_UNDEF, is_statistics_from_stat_tables = false, {
    parser = 0x0, parser_name = 0x0}, key_part = 0x62b0000015b0, 
  name = 0x62b000000340 "idx1", cache_name = 0x0, rec_per_key = 0x0, 
  read_stats = 0x0, collected_stats = 0x0, handler = {bdb_return_if_eq = 0}, 
  table = 0x0, comment = {str = 0x0, length = 0}, option_list = 0x0, 
  option_struct = 0x0}

Had it been invoked with the correct key_length, InnoDB would have returned an error in one of these places, by invoking my_error() and returning true:

		if (innobase_check_column_length(max_col_len, key)) {
			my_error(ER_INDEX_COLUMN_TOO_LONG, MYF(0),
				 max_col_len);
			goto err_exit_no_heap;
		}
			if (field->prefix_len > max_col_len) {
				my_error(ER_INDEX_COLUMN_TOO_LONG, MYF(0),
					 max_col_len);
				goto err_exit_no_heap;
			}

Instead, ha_innobase::prepare_inplace_alter_table() and ha_innobase::inplace_alter_table() returned false, indicating success. Inside InnoDB, the index stub was created according to the supplied wrong information:

p *m_prebuilt->table->indexes.end->fields@2
$11 = {{col = 0x61c00004f908, name = {m_name = 0x61c00004f990 "a"}, 
    prefix_len = 3072, fixed_len = 0}, {col = 0x61c00004f914, name = {
      m_name = 0x61c00004f992 "DB_ROW_ID"}, prefix_len = 0, fixed_len = 6}}

The problem appears to be that we have

(gdb) p thd->m_stmt_da->m_status
$17 = Diagnostics_area::DA_ERROR

already when ha_innobase::prepare_inplace_alter_table() is invoked. That is a clear error. The SQL layer should have aborted the ALTER TABLE shortly after setting the flag:

#2  0x000055555620a402 in push_warning (thd=0x62a000078270, 
    level=Sql_condition::WARN_LEVEL_WARN, code=1071, 
    msg=0x7fffdf272ca0 "Specified key was too long; max key length is 3072 bytes") at /mariadb/server/sql/sql_error.cc:765
#3  0x000055555620a6d6 in push_warning_printf (thd=0x62a000078270, 
    level=Sql_condition::WARN_LEVEL_WARN, code=1071, 
    format=0x63100002b5d0 "Specified key was too long; max key length is %d bytes") at /mariadb/server/sql/sql_error.cc:800
#4  0x0000555556458dd7 in mysql_prepare_create_table (thd=0x62a000078270, 
    create_info=0x7fffdf277de0, alter_info=0x7fffdf277d00, 
    db_options=0x7fffdf273b30, file=0x62b000000db8, 
    key_info_buffer=0x7fffdf275b10, key_count=0x7fffdf275a10, 
    create_table_mode=-2) at /mariadb/server/sql/sql_table.cc:3959
#5  0x000055555645d7c8 in mysql_create_frm_image (thd=0x62a000078270, 
    db=0x62b000000988 "test", table_name=0x62b000000348 "t1", 
    create_info=0x7fffdf277de0, alter_info=0x7fffdf277d00, 
    , key_info=0x7fffdf275b10, key_count=0x7fffdf275a10, 
    frm=0x7fffdf275b90) at /mariadb/server/sql/sql_table.cc:4634
#6  0x000055555645eb44 in create_table_impl (thd=0x62a000078270, 
    orig_db=0x62b000000988 "test", orig_table_name=0x62b000000348 "t1", 
    db=0x62b000000988 "test", table_name=0x7fffdf276bd0 "#sql-7265_7", 
    path=0x7fffdf27743c "./test/#sql-7265_7", options=..., 
    create_info=0x7fffdf277de0, alter_info=0x7fffdf277d00, 
    create_table_mode=-2, is_trans=0x0, key_info=0x7fffdf275b10, 
    key_count=0x7fffdf275a10, frm=0x7fffdf275b90)
    at /mariadb/server/sql/sql_table.cc:4878
#7  0x0000555556477c93 in mysql_alter_table (thd=0x62a000078270, 
    new_db=0x62b000000988 "test", new_name=0x62b000000348 "t1", 
    create_info=0x7fffdf277de0, table_list=0x62b000000380, 
    alter_info=0x7fffdf277d00, order_num=0, order=0x0, ignore=false)
    at /mariadb/server/sql/sql_table.cc:9076

Comment by Sergei Golubchik [ 2017-04-03 ]

I cannot repeat it with the latest 10.2.5, must've been fixed meanwhile.

Comment by Marko Mäkelä [ 2017-04-03 ]

It still crashes for me:

--source include/have_innodb.inc
SET SQL_MODE='STRICT_TRANS_TABLES';
 
CREATE TABLE t1(a TEXT NOT NULL) ENGINE=InnoDB ROW_FORMAT=DYNAMIC DEFAULT CHARSET latin1;
CREATE INDEX idx1 ON t1(a(3073));
DROP TABLE t1;

with the following assertion failure in CREATE INDEX:

sql/sql_error.cc:381: void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*): Assertion `!is_set() || (m_status == DA_OK_BULK && is_bulk_op())' failed.

Comment by Marko Mäkelä [ 2017-04-17 ]

The fix (issuing a note for a truncated column prefix instead of a warning or error) caused a result difference for the test innodb.innodb_mysql:

CURRENT_TEST: innodb.innodb_mysql
--- /mariadb/10.2/mysql-test/suite/innodb/r/innodb_mysql.result	2017-03-30 14:33:52.956081571 +0300
+++ /mariadb/10.2/mysql-test/suite/innodb/r/innodb_mysql.reject	2017-04-17 03:14:01.995075307 +0300
@@ -1547,7 +1547,7 @@
 set statement sql_mode = 'NO_ENGINE_SUBSTITUTION' for
 alter table t1 add index(a(1024));
 Warnings:
-Warning	1071	Specified key was too long; max key length is 767 bytes
+Note	1071	Specified key was too long; max key length is 767 bytes
 show create table t1;
 Table	Create Table
 t1	CREATE TABLE `t1` (

I fixed that by re-recording the result.
I do not fully agree with this change in behaviour. Not issuing a warning during DDL may cause surprises or break replication to older versions:

  • For UNIQUE INDEX, INSERT or UPDATE may unexpectedly fail due to duplicate key error (when the originally specified key prefix is unique, but the truncated one is not)
  • For all indexes, LIKE 'prefix%' may unexpectedly skip the index when the prefix is longer than what the index was truncated to, but not longer than what was specified.
  • When older-version replication slaves are running in strict mode, they would refuse the DDL operation, instead of silently changing the table schema.
Comment by Sergei Golubchik [ 2017-04-17 ]

marko, the index is never truncated for UNIQUE indexes, that would change the semantics of the constraint. But a non-UNIQUE index is merely a non-standard optimization technique, it does not affect correctness of results. The message should've always been a note, it's never an error to truncate a non-unique index.

The case with LIKE 'prefix%' with a 3072-byte long prefix is technically possible, but practically unlikely. Anyway, I think that LIKE should be able to use the index in cases when the index length is smaller than the prefix length.

Generated at Thu Feb 08 07:54:16 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.