Assertion failure in thread 140598511429376 in file ha_innodb.cc line 6759

[Aleksey Sokolov]

We have a latest version of Percona Cluster (with percona repository):

Server version: 5.6.19-67.0-56-log Percona XtraDB Cluster (GPL), Release rel67.0, Revision 824, WSREP version 25.6, wsrep_25.6.r4111

Table structure (CMS Joomla 2.5):

mysql> show create table r8kmb_redirect_links;
............................
CREATE TABLE `r8kmb_redirect_links` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `old_url` varchar(255) DEFAULT NULL,
  `new_url` varchar(255) NOT NULL,
  `referer` varchar(150) NOT NULL,
  `comment` varchar(255) NOT NULL,
  `published` tinyint(4) NOT NULL,
  `created_date` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
  `modified_date` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
  PRIMARY KEY (`id`),
  UNIQUE KEY `idx_link_old` (`old_url`),
  KEY `idx_link_modifed` (`modified_date`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

Wsrep debug mode is enabled:

1) my.cnf -> wsrep_debug = on
2) my.cnf -> wsrep_provider_options contain "debug = yes"

Trying to execute SQL query:

INSERT INTO r8kmb_redirect_links VALUES (550,'http://mysite.com/images/download/ßуñûічýøù_ôþóþòір_þфõÑ.doc','','','',0,'2013-07-15 14:29:42','0000-00-00 00:00:00');

Column "old_url", is a string containing UTF 8 characters.

Result:

mysql> truncate table r8kmb_redirect_links;
Query OK, 0 rows affected (0.06 sec)

mysql> INSERT INTO r8kmb_redirect_links VALUES (550,'http://mysite.com/images/download/ßуñûічýøù_ôþóþòір_þфõÑ.doc','','','',0,'2013-07-15 14:29:42','0000-00-00 00:00:00');
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>

Now, the node is crashed. Full information from MySQL log (17:29:29 - node is running):

2014-07-23 17:29:29 18374 [Note] WSREP: Synchronized with group, ready for connections
2014-07-23 17:29:29 18374 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2014-07-23 17:29:29 18374 [Note] WSREP: Nobody is waiting for SST.

2014-07-23 17:29:35 18374 [Note] WSREP: TO BEGIN: -1, 0 : truncate table r8kmb_redirect_links
2014-07-23 17:29:35 18374 [Note] [Debug] WSREP: galera/src/replicator_smm.cpp:to_isolation_begin():1018: Executing TO isolated action: source: c13ea636-1275-11e4-8261-e764b10b34ba version: 3 local: 1 state: APPLYING flags: 65 conn_id: 52 trx_id: -1 seqnos (l: 3, g: 406, s: 405, d: 405, ts: 1314639831686956)
2014-07-23 17:29:35 18374 [Note] WSREP: TO BEGIN: 406, 2
2014-07-23 17:29:35 18374 [Note] WSREP: TO END: 406, 2 : truncate table r8kmb_redirect_links
2014-07-23 17:29:35 18374 [Note] WSREP: Set WSREPXid for InnoDB: a6b54819-1263-11e4-b5fd-c648b3b01fae:406
2014-07-23 17:29:35 18374 [Note] WSREP: TO END: 406, update seqno
2014-07-23 17:29:35 18374 [Note] [Debug] WSREP: galera/src/replicator_smm.cpp:to_isolation_end():1043: Done executing TO isolated action: source: c13ea636-1275-11e4-8261-e764b10b34ba version: 3 local: 1 state: APPLYING flags: 65 conn_id: 52 trx_id: -1 seqnos (l: 3, g: 406, s: 405, d: 405, ts: 1314639831686956)
2014-07-23 17:29:35 18374 [Note] WSREP: TO END: 406
2014-07-23 17:32:35 7f650012e700 InnoDB: Assertion failure in thread 140071769663232 in file ha_innodb.cc line 6759
InnoDB: Failing assertion: buff <= buff_start + buff_len
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
14:32:35 UTC - 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.
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.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=52
connection_count=1
14:32:35 UTC - 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.
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.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=52
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 192136 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x1f8ce50
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 = 7f650012dd38 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x8f36b5]
/usr/sbin/mysqld(handle_fatal_signal+0x4c4)[0x6635c4]
/lib64/libpthread.so.0[0x331840f710]
/lib64/libpthread.so.0[0x331840f710]
/lib64/libc.so.6(gsignal+0x35)[0x3318032925]
/lib64/libc.so.6(abort+0x175)[0x3318034105]
/usr/sbin/mysqld[0x909d4e]
/usr/sbin/mysqld(_ZN11ha_innobase17wsrep_append_keysEP3THDbPKhS3_+0x1d4)[0x90a654]
/usr/sbin/mysqld[0x9152b9]
/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0xa9)[0x5a7c99]
/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP9COPY_INFOS4_+0x8a)[0x6cbdca]
/usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0xb70)[0x6d3940]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0xf70)[0x6e8050]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x658)[0x6ed768]
/usr/sbin/mysqld[0x6ed8c1]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1362)[0x6ef412]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1e3)[0x6f0f73]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17f)[0x6b9bdf]
/usr/sbin/mysqld(handle_one_connection+0x47)[0x6b9db7]
/usr/sbin/mysqld(pfs_spawn_thread+0x12a)[0xae9b4a]
/lib64/libpthread.so.0[0x33184079d1]
/lib64/libc.so.6(clone+0x6d)[0x33180e8b6d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f6554024600): is an invalid pointer
Connection ID (thread ID): 52
Status: NOT_KILLED

You may download the Percona XtraDB Cluster operations manual by visiting
http://www.percona.com/software/percona-xtradb-cluster/. You may find information
in the manual which will help you identify the cause of the crash.
140723 17:32:35 mysqld_safe Number of processes running now: 0
140723 17:32:35 mysqld_safe WSREP: not restarting wsrep node automatically
140723 17:32:35 mysqld_safe mysqld from pid file /var/lib/mysql/myhost.pid ended

I managed to work around the problem in 2 ways:

1) Drop unique index: UNIQUE KEY `idx_link_old` (`old_url`)
2) Change coding column 'old_url'. I've tried latin1: alter table r8kmb_redirect_links modify `old_url` varchar(255) character set latin1;

How to reproduce:

1) Create table `r8kmb_redirect_links`. The table structure is written above.
2) Executing SQL query (INSERT INTO).

Initially, the error was discovered in a cluster of 3 nodes. For a detailed analysis of the problem, we used a virtual machine (one node: wsrep_cluster_size = 1).

On the virtual machine, we used the following configuration (my.cnf):

[mysqld]

# ///// General

user=mysql

datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
tmpdir=/tmp

symbolic-links=0

table_open_cache = 4096
table_definition_cache = 4096

thread_cache_size=4

default_storage_engine=InnoDB

# ///// innodb

innodb_buffer_pool_size = 100M

innodb_log_file_size = 32M
innodb_log_buffer_size = 2M

innodb_open_files = 4096
innodb_file_per_table = 1
innodb_rollback_on_timeout=On
innodb_flush_log_at_trx_commit = 1
innodb_flush_method = O_DIRECT
innodb_lock_wait_timeout = 300
innodb_flush_neighbors = 0

innodb_write_io_threads = 4
innodb_read_io_threads = 4

innodb_support_xa = 0

innodb_autoinc_lock_mode = 2
innodb_locks_unsafe_for_binlog = 1

# ///// binlog \ relaylog

log-bin = /var/lib/mysql_logs/binary/binlog
max_binlog_size = 1024M
binlog_format = ROW
binlog_cache_size = 5M
expire_logs_days = 1
sync_binlog = 0

relay_log = /var/lib/mysql_logs/relay/relaylog
slave_load_tmpdir = /var/lib/mysql_logs/slave
log_slave_updates = On

# ///// log

log_error = "/var/log/mysql/error.log"

# ///// Galera

wsrep_provider=/usr/lib64/libgalera_smm.so
wsrep_provider_options="gcache.size=100M; gcache.name = /var/lib/mysql_logs/galera/galera.cache; debug = yes"

wsrep_cluster_address=gcomm://

wsrep_cluster_name="Test"
wsrep_node_address="192.168.0.1"
wsrep_node_name="qwerty"
wsrep_sst_method=rsync
wsrep_replicate_myisam=On
wsrep_forced_binlog_format = ROW
wsrep_log_conflicts = On
wsrep_auto_increment_control = On
wsrep_retry_autocommit = 5
wsrep_slave_threads=2
wsrep_convert_LOCK_to_trx = 1
wsrep_debug = on

[Aleksey Sokolov (absokolov2010)]

Reproduce (First run after "mysql_install_db"):

[root@vm-percona /]# mysql
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 52
Server version: 5.6.19-67.0-56-log Percona XtraDB Cluster (GPL), Release rel67.0, Revision 824, WSREP version 25.6, wsrep_25.6.r4111

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 database `tested`;
Query OK, 1 row affected (0.03 sec)

mysql> use tested;
Database changed
mysql> CREATE TABLE `r8kmb_redirect_links` (
    -> `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
    -> `old_url` varchar(255) DEFAULT NULL,
    -> `new_url` varchar(255) NOT NULL,
    -> `referer` varchar(150) NOT NULL,
    -> `comment` varchar(255) NOT NULL,
    -> `published` tinyint(4) NOT NULL,
    -> `created_date` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
    -> `modified_date` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
    -> PRIMARY KEY (`id`),
    -> UNIQUE KEY `idx_link_old` (`old_url`),
    -> KEY `idx_link_modifed` (`modified_date`)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
Query OK, 0 rows affected (0.09 sec)

mysql> INSERT INTO r8kmb_redirect_links VALUES (550,'http://mysite.com/images/download/ßуñûічýøù_ôþóþòір_þфõÑ.doc','','','',0,'2013-07-15 14:29:42','0000-00-00 00:00:00');
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>

[Valerii Kravchuk (valerii-kravchuk)]

I wonder what do you mean by "upstream" tag though, as I can not reproduce with Percona Server 5.6.19:

openxs@ao756:~$ mysql -uroot -proot test
Warning: Using a password on the command line interface can be insecure.
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 50
Server version: 5.6.19-67.0 Percona Server (GPL), Release 67.0, Revision 618

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 `r8kmb_redirect_links` (
    -> `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
    -> `old_url` varchar(255) DEFAULT NULL,
    -> `new_url` varchar(255) NOT NULL,
    -> `referer` varchar(150) NOT NULL,
    -> `comment` varchar(255) NOT NULL,
    -> `published` tinyint(4) NOT NULL,
    -> `created_date` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
    -> `modified_date` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
    -> PRIMARY KEY (`id`),
    -> UNIQUE KEY `idx_link_old` (`old_url`),
    -> KEY `idx_link_modifed` (`modified_date`)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
Query OK, 0 rows affected (0,56 sec)

mysql> INSERT INTO r8kmb_redirect_links VALUES (550,'http://mysite.com/images/download/ßуñûічýøù_ôþóþòір_þфõÑ.doc','','','',0,'2013-07-15 14:29:42','0000-00-00 00:00:00');
Query OK, 1 row affected (0,05 sec)

[Przemek (pmalkowski)]

I can confirm the problem on the same version:
mysql> select @@version,@@version_comment;
+----------------+---------------------------------------------------------------------------------------------------+
| @@version | @@version_comment |
+----------------+---------------------------------------------------------------------------------------------------+
| 5.6.19-67.0-56 | Percona XtraDB Cluster (GPL), Release rel67.0, Revision 824, WSREP version 25.6, wsrep_25.6.r4111 |
+----------------+---------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

However, the crash does not happen when wsrep_provider is not set:
mysql> show status like 'ws%';
+--------------------------+----------------------+
| Variable_name | Value |
+--------------------------+----------------------+
| wsrep_cluster_conf_id | 18446744073709551615 |
| wsrep_cluster_size | 0 |
| wsrep_cluster_state_uuid | |
| wsrep_cluster_status | Disconnected |
| wsrep_connected | OFF |
| wsrep_local_bf_aborts | 0 |
| wsrep_local_index | 18446744073709551615 |
| wsrep_provider_name | |
| wsrep_provider_vendor | |
| wsrep_provider_version | |
| wsrep_ready | ON |
+--------------------------+----------------------+
11 rows in set (0.00 sec)

mysql> INSERT INTO r8kmb_redirect_links VALUES (550,'http://mysite.com/images/download/ßуñûічýøù_ôþóþòір_þфõÑ.doc','','','',0,'2013-07-15 14:29:42','0000-00-00 00:00:00');
Query OK, 1 row affected (0.09 sec)

When wsrep_provider is enabled, I get the same crash:

mysql> INSERT INTO r8kmb_redirect_links VALUES (550,'http://mysite.com/images/download/ßуñûічýøù_ôþóþòір_þфõÑ.doc','','','',0,'2013-07-15 14:29:42','0000-00-00 00:00:00');
ERROR 2013 (HY000): Lost connection to MySQL server during query

2014-07-24 23:55:33 7f73886e9700 InnoDB: Assertion failure in thread 140134186915584 in file ha_innodb.cc line 6759
InnoDB: Failing assertion: buff <= buff_start + buff_len
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
21:55:33 UTC - 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. Th...

[Przemek (pmalkowski)]

Latest PXC 5.5 version is not affected:

mysql> select @@version,@@version_comment;
+----------------+-----------------------------------------------------------------------------------------------------+
| @@version | @@version_comment |
+----------------+-----------------------------------------------------------------------------------------------------+
| 5.5.37-35.0-55 | Percona XtraDB Cluster (GPL), Release rel35.0, Revision 756, WSREP version 25.10, wsrep_25.10.r3985 |
+----------------+-----------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> CREATE TABLE `r8kmb_redirect_links` (
    -> `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
    -> `old_url` varchar(255) DEFAULT NULL,
    -> `new_url` varchar(255) NOT NULL,
    -> `referer` varchar(150) NOT NULL,
    -> `comment` varchar(255) NOT NULL,
    -> `published` tinyint(4) NOT NULL,
    -> `created_date` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
    -> `modified_date` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
    -> PRIMARY KEY (`id`),
    -> UNIQUE KEY `idx_link_old` (`old_url`),
    -> KEY `idx_link_modifed` (`modified_date`)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8;
Query OK, 0 rows affected (0.35 sec)

mysql> INSERT INTO r8kmb_redirect_links VALUES (550,'http://mysite.com/images/download/ßуñûічýøù_ôþóþòір_þфõÑ.doc','','','',0,'2013-07-15 14:29:42','0000-00-00 00:00:00');
Query OK, 1 row affected (0.15 sec)

[Yan Zhang (yan.zhang)]

fixed in http://bazaar.launchpad.net/~codership/codership-mysql/5.6/revision/4113

[Seppo Jaakola (seppo-jaakola)]

The fix in revision 4113 caused regression of bug: lp:1314854
New fix was pushed in revision:
http://bazaar.launchpad.net/~codership/codership-mysql/5.6/revision/4115
This fix will allow max 3500 bytes of key material to be populated, longer keys will be truncated

[Raghavendra D Prabhu (raghavendra-prabhu)]

@Aleksey

The fix is available in experimental repository.

http://jenkins.percona.com/experimental/CENTOS/percona-experimental.repo

[Raghavendra D Prabhu (raghavendra-prabhu)]

Fix for this is also available in percona-testing repo now for both debian and centos. Refer to documentation for details.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1704