Crash safe replication crashes mysqld (wsrep disabled)

[Przemek]

Under some circumstances, Percona XtraDB Cluster server crashes, even with wsrep not yet enabled.

Test scenario:
* Install fresh PXC 5.6 packages
* create my.cnf with:
[mysqld]
master_info_repository = TABLE
relay_log_info_repository = TABLE
relay_log_recovery = 1
server_id = 100
log-bin = /var/lib/mysql/mysql-bin
binlog-format = MIXED

* restart mysqld
* start dummy slave (no real master needed):
mysql> CHANGE MASTER TO MASTER_HOST='10.1.1.1',MASTER_USER='replica',MASTER_PASSWORD='replica', MASTER_LOG_FILE='bin.00001', MASTER_LOG_POS=1;
Query OK, 0 rows affected, 2 warnings (0.10 sec)

mysql> start slave;
Query OK, 0 rows affected (0.04 sec)

* restart mysql again
* mysql crashes with:

131118 18:20:12 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
131118 18:20:12 mysqld_safe Skipping wsrep-recover for empty datadir: /var/lib/mysql
131118 18:20:12 mysqld_safe Assigning 00000000-0000-0000-0000-000000000000:-1 to wsrep_start_position
2013-11-18 18:20:13 0 [Note] WSREP: wsrep_start_position var submitted: '00000000-0000-0000-0000-000000000000:-1'
2013-11-18 18:20:13 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-11-18 18:20:13 1121 [Note] Plugin 'FEDERATED' is disabled.
2013-11-18 18:20:13 1121 [Note] InnoDB: The InnoDB memory heap is disabled
2013-11-18 18:20:13 1121 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-11-18 18:20:13 1121 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-11-18 18:20:13 1121 [Note] InnoDB: Using Linux native AIO
2013-11-18 18:20:13 1121 [Note] InnoDB: Not using CPU crc32 instructions
2013-11-18 18:20:13 1121 [Note] InnoDB: Initializing buffer pool, size = 100.0M
2013-11-18 18:20:13 1121 [Note] InnoDB: Completed initialization of buffer pool
2013-11-18 18:20:13 1121 [Note] InnoDB: Highest supported file format is Barracuda.
2013-11-18 18:20:13 1121 [Note] InnoDB: 128 rollback segment(s) are active.
2013-11-18 18:20:13 1121 [Note] InnoDB: Waiting for purge to start
2013-11-18 18:20:13 1121 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.15-rel63.0 started; log sequence number 1662407
2013-11-18 18:20:13 1121 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2013-11-18 18:20:13 1121 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2013-11-18 18:20:13 1121 [Note] Server hostname (bind-address): '*'; port: 3306
2013-11-18 18:20:13 1121 [Note] IPv6 is available.
2013-11-18 18:20:13 1121 [Note] - '::' resolves to '::';
2013-11-18 18:20:13 1121 [Note] Server socket created on IP: '::'.
2013-11-18 18:20:13 1121 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=centos6-2-relay-bin' to avoid
this problem.
2013-11-18 18:20:13 1121 [Warning] Recovery from master pos 4 and file bin.00001.
17:20:13 UTC - 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.
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=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 69222 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x32bd8c0
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 = 7fff6ebb0fb8 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x902645]
/usr/sbin/mysqld(handle_fatal_signal+0x4c4)[0x6801e4]
/lib64/libpthread.so.0(+0xf500)[0x7f2206e34500]
/usr/sbin/mysqld[0x95cd5f]
/usr/sbin/mysqld(_ZN11ha_innobase17wsrep_append_keysEP3THDbPKhS3_+0x4c3)[0x960f23]
/usr/sbin/mysqld[0x96e3f8]
/usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhPh+0x112)[0x5c9492]
/usr/sbin/mysqld(_ZN14Rpl_info_table13do_flush_infoEb+0x1cb)[0x8e8d5b]
/usr/sbin/mysqld(_ZN14Relay_log_info10flush_infoEb+0x91)[0x8dd481]
/usr/sbin/mysqld(_ZN14Relay_log_info13rli_init_infoEv+0x4d1)[0x8e05c1]
/usr/sbin/mysqld(_Z16global_init_infoP11Master_infobi+0x1ab)[0x8d4cdb]
/usr/sbin/mysqld(_Z10init_slavev+0x14b)[0x8d6a7b]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x1195)[0x5ac065]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f220526acdd]
/usr/sbin/mysqld[0x59c381]

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

I could not trigger the same crash when I started with binlog-format = ROW, but once I start with MIXED only once, then I am getting crashes in a loop even after changing back to ROW, until I remove the master_info_repository = TABLE.
Then, once mysql starts properly with master_info_repository = FILE and binlog-format = ROW, I am able to get back to master_info_repository = TABLE later.

Galera was disabled all the time during the tests:
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.01 sec)

mysql> select @@version,@@version_comment;
+---------------+----------------------------------------------------------------------------+
| @@version | @@version_comment |
+---------------+----------------------------------------------------------------------------+
| 5.6.15-56-log | Percona XtraDB Cluster (GPL), Release 25.5, Revision 759, wsrep_25.5.r4061 |
+---------------+----------------------------------------------------------------------------+
1 row in set (0.01 sec)

[Raghavendra D Prabhu (raghavendra-prabhu)]

This seems to be due to wsrep_on being set.

#0 0x00000000009597a8 in wsrep_append_key (thd=thd@entry=0x193a300, trx=trx@entry=0x1938f58, key=key@entry=0x7fffffffaa00 "", key_len=<optimized out>, shared=shared@entry=false, table=<optimized out>,
    table_share=<optimized out>, table_share=<optimized out>) at /tmp/bld1/Percona-Server/storage/innobase/handler/ha_innodb.cc:9801
#1 0x0000000000962e3d in ha_innobase::wsrep_append_keys (this=this@entry=0x19422d0, thd=0x193a300, shared=shared@entry=false, record0=record0@entry=0x1929688 "\a", record1=record1@entry=0x1929650 "\a")
    at /tmp/bld1/Percona-Server/storage/innobase/handler/ha_innodb.cc:9901
#2 0x00000000009634ec in ha_innobase::update_row (this=0x19422d0, old_row=0x1929688 "\a", new_row=0x1929650 "\a") at /tmp/bld1/Percona-Server/storage/innobase/handler/ha_innodb.cc:8287
#3 0x00000000006406d2 in handler::ha_update_row (this=0x19422d0, old_data=0x1929688 "\a", new_data=0x1929650 "\a") at /tmp/bld1/Percona-Server/sql/handler.cc:7620
#4 0x00000000008bc7fa in Rpl_info_table::do_flush_info (this=0x19307c0, force=<optimized out>) at /tmp/bld1/Percona-Server/sql/rpl_info_table.cc:207
#5 0x00000000008b4aa8 in Relay_log_info::flush_info (this=this@entry=0x1925fa0, force=force@entry=true) at /tmp/bld1/Percona-Server/sql/rpl_rli.cc:2029
#6 0x00000000008b5093 in Relay_log_info::rli_init_info (this=0x1925fa0) at /tmp/bld1/Percona-Server/sql/rpl_rli.cc:1883
#7 0x00000000008a471d in global_init_info (mi=0x18eb270, ignore_if_no_info=ignore_if_no_info@entry=true, thread_mask=thread_mask@entry=3) at /tmp/bld1/Percona-Server/sql/rpl_slave.cc:558
#8 0x00000000008a8a36 in init_slave () at /tmp/bld1/Percona-Server/sql/rpl_slave.cc:379
#9 0x0000000000624a95 in mysqld_main (argc=15, argv=0x1351398) at /tmp/bld1/Percona-Server/sql/mysqld.cc:6397
#10 0x00007ffff5f37000 in __libc_start_main () from /usr/lib/libc.so.6
#11 0x0000000000616700 in _start ()

It tries to append_key and what not.

Starting with --wsrep-on=0 doesn't crash.

[Muhammad Irfan (muhammad-irfan)]

# dpkg -l | grep percona
ii percona-xtrabackup 2.2.3-4982-1.precise Open source backup tool for InnoDB and XtraDB
ii percona-xtradb-cluster-56 5.6.19-25.6-824.precise Percona XtraDB Cluster with Galera
ii percona-xtradb-cluster-client-5.6 5.6.19-25.6-824.precise Percona XtraDB Cluster database client binaries
ii percona-xtradb-cluster-common-5.6 5.6.19-25.6-824.precise Percona XtraDB Cluster database common files (e.g. /etc/mysql/my.cnf)
ii percona-xtradb-cluster-galera-3 3.6.3190.precise Metapackage for latest version of galera3.
ii percona-xtradb-cluster-galera-3.x 3.6.3190.precise Galera components of Percona XtraDB Cluster
ii percona-xtradb-cluster-server-5.6 5.6.19-25.6-824.precise Percona XtraDB Cluster database server binaries

# cat my.cnf
[mysqld]
master_info_repository = TABLE
relay_log_info_repository = TABLE
relay_log_recovery = 1
server_id = 100
log-bin = /var/lib/mysql/mysql-bin
binlog-format = MIXED
datadir=/var/lib/mysql

mysql> show global variables like '%wsrep%';
+---------------------------------+-----------------------------------------+
| Variable_name | Value |
+---------------------------------+-----------------------------------------+
| wsrep_on | ON |
| wsrep_preordered | OFF |
| wsrep_provider | none |
+---------------------------------+-----------------------------------------+

* restart mysqld
* start dummy slave (no real master needed):
mysql> CHANGE MASTER TO MASTER_HOST='10.1.1.1',MASTER_USER='replica',MASTER_PASSWORD='replica', MASTER_LOG_FILE='bin.00001', MASTER_LOG_POS=1;
Query OK, 0 rows affected, 2 warnings (0.10 sec)

mysql> start slave;
Query OK, 0 rows affected (0.04 sec)

* restarted mysql 2-3 times and no crashes.

[Shahriyar Rzayev (rzayev-sehriyar)]

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