slave continually crashes on start

[paullush]

After updating a slave tonight, mysql will no longer start and bombs with the following log

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
141015 13:08:25 mysqld_safe Number of processes running now: 0
141015 13:08:25 mysqld_safe mysqld restarted
2014-10-15 13:08:25 0 [Warning] Using unique option prefix key_buffer instead of key_buffer_size is deprecated and will be removed in a future release. Please use the full name instead.
2014-10-15 13:08:25 0 [Warning] 'THREAD_CONCURRENCY' is deprecated and will be removed in a future release.
2014-10-15 13:08:25 0 [Warning] Using unique option prefix key_buffer instead of key_buffer_size is deprecated and will be removed in a future release. Please use the full name instead.
2014-10-15 13:08:25 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-10-15 13:08:25 12116 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
2014-10-15 13:08:25 12116 [Warning] /usr/sbin/mysqld: ignoring option '--innodb-use-sys-malloc' due to invalid value '48M'
2014-10-15 13:08:25 12116 [Note] Plugin 'FEDERATED' is disabled.
2014-10-15 13:08:25 12116 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-10-15 13:08:25 12116 [Note] InnoDB: The InnoDB memory heap is disabled
2014-10-15 13:08:25 12116 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-10-15 13:08:25 12116 [Note] InnoDB: Memory barrier is not used
2014-10-15 13:08:25 12116 [Note] InnoDB: Compressed tables use zlib 1.2.8
2014-10-15 13:08:25 12116 [Note] InnoDB: Using Linux native AIO
2014-10-15 13:08:25 12116 [Note] InnoDB: Using CPU crc32 instructions
2014-10-15 13:08:25 12116 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2014-10-15 13:08:25 12116 [Note] InnoDB: Completed initialization of buffer pool
2014-10-15 13:08:26 12116 [Note] InnoDB: Highest supported file format is Barracuda.
2014-10-15 13:08:26 12116 [Note] InnoDB: Log scan progressed past the checkpoint lsn 906918457893
2014-10-15 13:08:26 12116 [Note] InnoDB: Database was not shutdown normally!
2014-10-15 13:08:26 12116 [Note] InnoDB: Starting crash recovery.
2014-10-15 13:08:26 12116 [Note] InnoDB: Reading tablespace information from the .ibd files...
2014-10-15 13:08:26 12116 [Note] InnoDB: Restoring possible half-written data pages
2014-10-15 13:08:26 12116 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 906918457903
InnoDB: Last MySQL binlog file position 0 34144609, file name mysql-bin.001195
2014-10-15 13:08:26 12116 [Note] InnoDB: 128 rollback segment(s) are active.
2014-10-15 13:08:26 12116 [Note] InnoDB: Waiting for purge to start
2014-10-15 13:08:26 12116 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-69.0 started; log sequence number 906918457903
Wed Oct 15 13:08:26 2014 TokuFT recovery starting in env /var/lib/mysql/
Wed Oct 15 13:08:26 2014 TokuFT recovery scanning backward from 87200036
Wed Oct 15 13:08:26 2014 TokuFT recovery bw_end_checkpoint at 87200036 timestamp 1413378504419056 xid 87200032 (bw_newer)
Wed Oct 15 13:08:26 2014 TokuFT recovery bw_begin_checkpoint at 87200032 timestamp 1413378504419051 (bw_between)
Wed Oct 15 13:08:26 2014 TokuFT recovery turning around at begin checkpoint 87200032 time 5
Wed Oct 15 13:08:26 2014 TokuFT recovery starts scanning forward to 87200036 from 87200032 left 4 (fw_between)
Wed Oct 15 13:08:26 2014 TokuFT recovery closing 2 dictionaries
Wed Oct 15 13:08:26 2014 TokuFT recovery making a checkpoint
Wed Oct 15 13:08:26 2014 TokuFT recovery done
2014-10-15 13:08:26 12116 [Note] Recovering after a crash using tc.log
2014-10-15 13:08:26 12116 [Note] Starting crash recovery...
2014-10-15 13:08:26 12116 [Note] Crash recovery finished.
2014-10-15 13:08:26 12116 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2014-10-15 13:08:26 12116 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2014-10-15 13:08:26 12116 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2014-10-15 13:08:26 12116 [Note] - '0.0.0.0' resolves to '0.0.0.0';
2014-10-15 13:08:26 12116 [Note] Server socket created on IP: '0.0.0.0'.
2014-10-15 13:08:26 12116 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2014-10-15 13:08:26 12116 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2014-10-15 13:08:26 12116 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001203' at position 263186660, relay log './www-relay-bin.000031' position: 1054
2014-10-15 13:08:26 12116 [Note] Event Scheduler: Loaded 0 events
2014-10-15 13:08:26 12116 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.21-69.0-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Percona Server (GPL), Release 69.0, Revision 675
2014-10-15 13:08:27 12116 [Note] Slave I/O thread: connected to master 'xxxxx@10.0.0.10:13306',replication started in log 'mysql-bin.001203' at position 271026515
13:08:28 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 Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=16777216
read_buffer_size=8388608
max_used_connections=0
max_threads=1002
thread_count=2
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 16447877 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f78e8c11000
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 = 7f796ba46940 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x90314c]
/usr/sbin/mysqld(handle_fatal_signal+0x352)[0x65ffa2]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f796a269340]
/usr/sbin/mysqld(_Z10free_blobsP5TABLE+0x13)[0x771d33]
/usr/sbin/mysqld(_ZN14Relay_log_info25slave_close_thread_tablesEP3THD+0x89)[0x8d7ea9]
/usr/sbin/mysqld(_ZN14Relay_log_info15cleanup_contextEP3THDb+0x7d)[0x8d7fdd]
/usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEPK14Relay_log_info+0x4f3)[0x8986d3]
/usr/sbin/mysqld(_ZN9Log_event11apply_eventEP14Relay_log_info+0x6a)[0x890dca]
/usr/sbin/mysqld(_Z26apply_event_and_update_posPP9Log_eventP3THDP14Relay_log_info+0x256)[0x8cb756]
/usr/sbin/mysqld(handle_slave_sql+0xe68)[0x8ce858]
/usr/sbin/mysqld(pfs_spawn_thread+0x140)[0xb1a200]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182)[0x7f796a261182]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f7969983fbd]

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): 1
Status: NOT_KILLED

[Valerii Kravchuk (valerii-kravchuk)]

Please, try to find out what exact statement may cause a crash by starting MySQL with --skip-slave-start option and executing:

show slave status\G

and then checking content of the slave's relay log at current SQL_thread position.

Please, send also your my.cnf file content from this slave.

[paullush (paullush-8)]

Sorry, this was on a production system and I had to get the DB running again which required a complete backup and copy. I didnt have time to leave the system down

[paullush (paullush-8)]

there is a mechanism to log a crash, could it not be reworked so that the processing thread logs the query/log positions that cause the failure?

[Peiran Song (peiran-song)]

If you still have mysql-bin.001203 on the master, please double check if continuous restart always has the line of :

2014-10-15 13:08:26 12116 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001203' at position 263186660, relay log './www-relay-bin.000031' position: 1054

Then run this command on the master, upload the output as well as my.cnf from the slave:

$ mysqlbinlog -vvv --start-position=263186660 mysql-bin.001203 | head -n 1000 > master.bin.out

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.6 because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

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