Assertion failure in file dict0dict.c line 2697

[Olaf van Zandwijk]

When running a relatively simple ALTER TABLE statement I get an assertion error and MySQL crashes. This happens in 5.5.39; downgrading to 5.5.38 resolves the issue.

ALTER TABLE database.table ADD version BIGINT NOT NULL DEFAULT '0'

results in

140902 10:56:02 InnoDB: Assertion failure in thread 139595063400192 in file dict0dict.c line 2697
InnoDB: Failing assertion: UT_LIST_GET_LEN(table->referenced_list) == rbt_size(table->referenced_rbt)

Thread pointer: 0x7ef5ff2925d0
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 = 7ef6022a8e68 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x29)[0x78ba99]
/usr/sbin/mysqld(handle_fatal_signal+0x372)[0x68c752]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf030)[0x7eff91e82030]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7eff900bc1a5]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x180)[0x7eff900bf420]
/usr/sbin/mysqld[0x83c023]
/usr/sbin/mysqld[0x846bad]
/usr/sbin/mysqld[0x84a9f7]
/usr/sbin/mysqld[0x7c6908]
/usr/sbin/mysqld[0x7a7fe8]
/usr/sbin/mysqld(_Z18mysql_rename_tableP10handlertonPKcS2_S2_S2_j+0x118)[0x602218]
/usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P24st_ha_create_informationP10TABLE_LISTP10Alter_infojP8st_orderb+0x26dc)[0x60696c]
/usr/sbin/mysqld(_ZN21Alter_table_statement7executeEP3THD+0x453)[0x76ff93]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1aeb)[0x5a5f3b]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x2eb)[0x5aa4cb]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1495)[0x5aba45]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x186)[0x63a526]
/usr/sbin/mysqld(handle_one_connection+0x4a)[0x63a5ba]
/usr/sbin/mysqld(pfs_spawn_thread+0x55)[0x9118f5]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7eff91e79b50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7eff90165e6d]

Then Percona Server crashes, and it restarts with the following error:

140902 10:56:15 InnoDB: Error: table 'database/#sql-bf32_92'
InnoDB: in InnoDB data dictionary has tablespace id 6715,
InnoDB: but the tablespace with that id has name ./database/table.ibd.

I found this upstream bug: http://bugs.mysql.com/bug.php?id=73761 that closely resembles my setup. We issue this alter table command from inside a JBoss container. However, the column I add has nothing to do with FK's.

[Valerii Kravchuk (valerii-kravchuk)]

Any simple test case to share? Maybe just a dump of that table (cleaned up from confidential information if needed)?

[Olaf van Zandwijk (olafz)]

The table was actually empty at the time of the altering. The structure was as follows (slightly changed some names):

CREATE TABLE `tablename` (
  `objectid` bigint(20) NOT NULL AUTO_INCREMENT,
  `employeeobjectid` bigint(20) NOT NULL,
  `clusterobjectid` bigint(20) NOT NULL,
  `date` date NOT NULL,
  `durationclienttime` int(11) NOT NULL DEFAULT '0',
  `durationworked` int(11) NOT NULL DEFAULT '0',
  `durationcontractfixed` int(11) NOT NULL DEFAULT '0',
  `durationcontractvar` int(11) NOT NULL DEFAULT '0',
  `durationtimesheet` int(11) NOT NULL DEFAULT '0',
  `durationworkedorig` int(11) NOT NULL DEFAULT '0',
  `durationmodifiediome` int(11) NOT NULL DEFAULT '0',
  `counterrors` int(11) NOT NULL DEFAULT '0',
  `countunverified` int(11) NOT NULL DEFAULT '0',
  `durationtravel` int(11) NOT NULL DEFAULT '0',
  `durationsickleave` int(11) NOT NULL DEFAULT '0',
  `durationvacation` int(11) NOT NULL DEFAULT '0',
  `expenseday` int(11) NOT NULL DEFAULT '0',
  `expensedistance` int(11) NOT NULL DEFAULT '0',
  `durationPLBLeave` int(11) NOT NULL DEFAULT '0',
  `countunverifiedexpenses` int(11) NOT NULL DEFAULT '0',
  PRIMARY KEY (`objectid`),
  UNIQUE KEY `unique_tablename` (`employeeobjectid`,`date`),
  KEY `IX_tablename_clusterobjectid_date` (`clusterobjectid`,`date`),
  KEY `IX_tablename_date` (`date`),
  CONSTRAINT `tablename_ibfk_1` FOREIGN KEY (`employeeobjectid`) REFERENCES `...` (`objectid`) ON DELETE CASCADE,
  CONSTRAINT `tablename_ibfk_2` FOREIGN KEY (`clusterobjectid`) REFERENCES `...` (`objectid`) ON DELETE CASCADE
) ENGINE=InnoDB DEFAULT CHARSET=latin1

[Valerii Kravchuk (valerii-kravchuk)]

It seems we still miss something here:

[openxs@chief p5.5]$ bin/mysql --no-defaults test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.39-36.0 MySQL Community Server (GPL)

Copyright (c) 2009-2014 Percona LLC and/or its affiliates
Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> create table tpk1(id bigint(20) primary key, c1 int) engine=InnoDB;
Query OK, 0 rows affected (0.14 sec)

mysql> create table tpk2(id bigint(20) primary key, c1 int) engine=InnoDB;
Query OK, 0 rows affected (0.08 sec)

mysql> CREATE TABLE `tablename` (
    -> `objectid` bigint(20) NOT NULL AUTO_INCREMENT,
    -> `employeeobjectid` bigint(20) NOT NULL,
    -> `clusterobjectid` bigint(20) NOT NULL,
    -> `date` date NOT NULL,
    -> `durationclienttime` int(11) NOT NULL DEFAULT '0',
    -> `durationworked` int(11) NOT NULL DEFAULT '0',
    -> `durationcontractfixed` int(11) NOT NULL DEFAULT '0',
    -> `durationcontractvar` int(11) NOT NULL DEFAULT '0',
    -> `durationtimesheet` int(11) NOT NULL DEFAULT '0',
    -> `durationworkedorig` int(11) NOT NULL DEFAULT '0',
    -> `durationmodifiediome` int(11) NOT NULL DEFAULT '0',
    -> `counterrors` int(11) NOT NULL DEFAULT '0',
    -> `countunverified` int(11) NOT NULL DEFAULT '0',
    -> `durationtravel` int(11) NOT NULL DEFAULT '0',
    -> `durationsickleave` int(11) NOT NULL DEFAULT '0',
    -> `durationvacation` int(11) NOT NULL DEFAULT '0',
    -> `expenseday` int(11) NOT NULL DEFAULT '0',
    -> `expensedistance` int(11) NOT NULL DEFAULT '0',
    -> `durationPLBLeave` int(11) NOT NULL DEFAULT '0',
    -> `countunverifiedexpenses` int(11) NOT NULL DEFAULT '0',
    -> PRIMARY KEY (`objectid`),
    -> UNIQUE KEY `unique_tablename` (`employeeobjectid`,`date`),
    -> KEY `IX_tablename_clusterobjectid_date` (`clusterobjectid`,`date`),
    -> KEY `IX_tablename_date` (`date`),
    -> CONSTRAINT `tablename_ibfk_1` FOREIGN KEY (`employeeobjectid`) REFERENCES `tpk1` (`id`) ON DELETE CASCADE,
    -> CONSTRAINT `tablename_ibfk_2` FOREIGN KEY (`clusterobjectid`) REFERENCES `tpk2` (`id`) ON DELETE CASCADE
    -> ) ENGINE=InnoDB DEFAULT CHARSET=latin1;
Query OK, 0 rows affected (0.10 sec)

mysql> alter table `tablename` add version bigint not null default '0';
Query OK, 0 rows affected (0.17 sec)
Records: 0 Duplicates: 0 Warnings: 0

No assertion failures. Please, send your my.cnf file content to double check.

[Olaf van Zandwijk (olafz)]

@valerii-kravchuk

Have you read the upstream bug-report? This happens from within a JBoss (Java application server) container. Outside the container, it cannot be reproduced. Downgrading version 5.5.38 solves this issue.

In our case, we run a liquibase changeset from inside JBoss with this content:

     <changeSet author="Author" id="changeset-ID">
         <addColumn tableName="tablename">
            <column name="version" type="bigint" defaultValue="0">
                <constraints nullable="false" />
            </column>
         </addColumn>
     </changeSet>

That translates to the query you see above.

[Valerii Kravchuk (valerii-kravchuk)]

We have to work on this part: "Outside the container, it cannot be reproduced". JBoss still sends some query to MySQL/Percona server eventually and may set some session (or global) variables. Connector/J version and connection string may help or provide some missing details in this case.

Repeatable test NOT involving JBoss is needed as hardly it can be installed and used by developer or QA engineers who will work on bug fix or test cases for further regression testing. Can you try, maybe, to enable general query log temporary to capture real sequence of queries sent for this change?

[Valerii Kravchuk (valerii-kravchuk)]

In any case foreign keys referencing table ALTERed play important role here, as assertion happens in the following code:

   2666 /**********************************************************************//**
   2667 Looks for the foreign constraint from the foreign and referenced lists
   2668 of a table.
   2669 @return foreign constraint */
   2670 static
   2671 dict_foreign_t*
   2672 dict_foreign_find(
   2673 /*==============*/
   2674 dict_table_t* table, /*!< in: table object */
   2675 const char* id) /*!< in: foreign constraint id */
   2676 {
...
   2695 if (table->referenced_rbt != NULL) {
   2696 ut_a(UT_LIST_GET_LEN(table->referenced_list)
   2697 == rbt_size(table->referenced_rbt));
   2698 node = rbt_lookup(table->referenced_rbt, id);
...

So, can you, please, check if the table is referenced by foreign keys from some other tables, and if it is (as I assume), share SHOW CREATE TABLE output (edited if needed) for them?

[Olaf van Zandwijk (olafz)]

I haven't verified myself, but the upstream bug report now has a comment with a testcase. I will add my testcase later tonight.

[Valerii Kravchuk (valerii-kravchuk)]

Upstream test case on non-debug build of Percona Server does not produce any assertion failure, just error:

mysql> create table t1(a int,key(a))engine=innodb;
Query OK, 0 rows affected (0.09 sec)

mysql> create table t2(a int,key(a))engine=innodb;
Query OK, 0 rows affected (0.10 sec)

mysql> create table t3(a int,key(a))engine=innodb;
Query OK, 0 rows affected (0.09 sec)

mysql> set foreign_key_checks=1;
Query OK, 0 rows affected (0.00 sec)

mysql> alter table `t3` add constraint `s` foreign key (`a`) references `t1`(`a`) on delete no action ;
Query OK, 0 rows affected (0.22 sec)
Records: 0 Duplicates: 0 Warnings: 0

mysql> alter table `t1` add constraint `p` foreign key (`a`) references `t2`(`a`) on update set null ;
Query OK, 0 rows affected (0.22 sec)
Records: 0 Duplicates: 0 Warnings: 0

mysql> alter table `t3` add constraint `s` foreign key (`a`) references `t1`(`a`) on update set null ;
ERROR 1005 (HY000): Can't create table 'test.#sql-2c22_3' (errno: 121)
mysql> alter table `t2` add constraint ` ip` foreign key (`a`) references `t1`(`a`) on update restrict;
Query OK, 0 rows affected (0.29 sec)
Records: 0 Duplicates: 0 Warnings: 0

mysql> show global status like 'Uptime';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Uptime | 80185 |
+---------------+-------+
1 row in set (0.00 sec)

mysql> select version();
+-------------+
| version() |
+-------------+
| 5.5.39-36.0 |
+-------------+
1 row in set (0.00 sec)

[Olaf van Zandwijk (olafz)]

@valerii-kravchuk, #6

Unfortunately, there are no references *to* the table that has a failing alter:
mysql> SELECT * FROM KEY_COLUMN_USAGE WHERE TABLE_SCHEMA = '...' AND REFERENCED_TABLE_NAME = 'table';
Empty set (0.01 sec)

The references *from* the table are the ones that show up in #3:

mysql> SELECT constraint_name FROM KEY_COLUMN_USAGE WHERE TABLE_SCHEMA = '...' AND TABLE_NAME = 'table' AND REFERENCED_TABLE_NAME IS NOT NULL;
+-------------------------------+
| constraint_name |
+-------------------------------+
| tablename_ibfk_1 |
| tablename_ibfk_2 |
+-------------------------------+
2 rows in set (0.00 sec)

[Olaf van Zandwijk (olafz)]

I have checked the upstream comment as well. With me there is also just an error, no crash (Server version: 5.5.39-36.0-log Percona Server (GPL), Release 36.0, Revision 697)

[Valerii Kravchuk (valerii-kravchuk)]

Quick status update: I am still not able to reproduce this assertion.

[Valerii Kravchuk (valerii-kravchuk)]

See https://bugs.launchpad.net/percona-server/+bug/1366073 for related crashes on both 5.6.20 and 5.5.39 (no assertion failure as reported here though). Use case is similar and bug is confirmed.

[Laurynas Biveinis (laurynas-biveinis)]

Marking as a duplicate of bug 1366073 for now.