Bug #70802 MySQL Crashes when Trying to Start Slave
Submitted: 2 Nov 2013 15:04 Modified: 14 Dec 2013 19:07
Reporter: John Smith Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.5.34-log MySQL Community Server (GPL) OS:Linux (RHEL 6.4)
Assigned to: CPU Architecture:Any

[2 Nov 2013 15:04] John Smith
Description:
Attempts to start the slave process using the "START SLAVE"  statement results in the server crashing. Other commands, i.e. show databases, select * from..., insert... etc, seem to work fine. I have not yet encountered an issue outside of trying to start the slave process. 

The following is the log output: 

131102 09:38:01 mysqld_safe Starting mysqld daemon with databases from /data/mysql
131102  9:38:01 [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.
131102  9:38:01 [Note] Plugin 'FEDERATED' is disabled.
131102  9:38:01 [Warning] Using unique option prefix innodb_log_buffer instead of innodb-log-buffer-size is deprecated and will be removed in a future release. Please use the full name instead.
131102  9:38:01 InnoDB: The InnoDB memory heap is disabled
131102  9:38:01 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131102  9:38:01 InnoDB: Compressed tables use zlib 1.2.3
131102  9:38:01 InnoDB: Using Linux native AIO
131102  9:38:02 InnoDB: Initializing buffer pool, size = 24.0G
131102  9:38:03 InnoDB: Completed initialization of buffer pool
131102  9:38:03 InnoDB: highest supported file format is Barracuda.
131102  9:38:05  InnoDB: Waiting for the background threads to start
131102  9:38:06 InnoDB: 5.5.34 started; log sequence number 1300038142994
131102  9:38:06 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131102  9:38:06 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131102  9:38:06 [Note] Server socket created on IP: '0.0.0.0'.
131102  9:38:06 [Note] Event Scheduler: Loaded 0 events
131102  9:38:06 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.34-log'  socket: '/data/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
131102  9:38:40 [Note] Slave SQL thread initialized, starting replication in log 'mysql-binary.000348' at position 581113896, relay log '/archives/mysql/relaylogs/db5-relay-log.000002' position: 1864402
131102  9:38:40 [Note] Slave I/O thread: connected to master 'replication@111.111.111.111:3306',replication started in log 'mysql-binary.000348' at position 604386377
InnoDB: Error: trying to access page number 170335 in space 104,
InnoDB: space name ./DATA/TABLE.ibd,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
131102  9:38:41  InnoDB: Assertion failure in thread 140142929028864 in file fil0fil.c line 4578
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.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
14:38:41 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.

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

Thread pointer: 0x7f6f20000990
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 = 7f7591809838 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x7ac645]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x6844f4]
/lib64/libpthread.so.0(+0xf500)[0x7f759142d500]
/lib64/libc.so.6(gsignal+0x35)[0x7f75905f58e5]
/lib64/libc.so.6(abort+0x175)[0x7f75905f70c5]
/usr/sbin/mysqld[0x870bee]
/usr/sbin/mysqld[0x84a478]
/usr/sbin/mysqld[0x84ad27]
/usr/sbin/mysqld[0x83e461]
/usr/sbin/mysqld[0x827c27]
/usr/sbin/mysqld[0x8cb127]
/usr/sbin/mysqld[0x8cd69f]
/usr/sbin/mysqld[0x7d8be6]
/usr/sbin/mysqld[0x7c44ca]
/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0x5d)[0x6899bd]
/usr/sbin/mysqld(_ZN14Rows_log_event9write_rowEPK14Relay_log_infob+0x11a)[0x72753a]
/usr/sbin/mysqld(_ZN20Write_rows_log_event11do_exec_rowEPK14Relay_log_info+0x22)[0x727822]
/usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEPK14Relay_log_info+0x204)[0x7294b4]
/usr/sbin/mysqld(_Z26apply_event_and_update_posP9Log_eventP3THDP14Relay_log_info+0x12d)[0x52874d]
/usr/sbin/mysqld[0x52d552]
/usr/sbin/mysqld(handle_slave_sql+0x9a1)[0x52ea11]
/lib64/libpthread.so.0(+0x7851)[0x7f7591425851]
/lib64/libc.so.6(clone+0x6d)[0x7f75906ab94d]

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

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.
131102 09:38:41 mysqld_safe Number of processes running now: 0
131102 09:38:41 mysqld_safe mysqld restarted
131102  9:38:41 [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.
131102  9:38:41 [Note] Plugin 'FEDERATED' is disabled.
131102  9:38:41 [Warning] Using unique option prefix innodb_log_buffer instead of innodb-log-buffer-size is deprecated and will be removed in a future release. Please use the full name instead.
131102  9:38:41 InnoDB: The InnoDB memory heap is disabled
131102  9:38:41 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131102  9:38:41 InnoDB: Compressed tables use zlib 1.2.3
131102  9:38:41 InnoDB: Using Linux native AIO
131102  9:38:41 InnoDB: Initializing buffer pool, size = 24.0G
131102  9:38:42 InnoDB: Completed initialization of buffer pool
131102  9:38:42 InnoDB: highest supported file format is Barracuda.
131102  9:38:44  InnoDB: Waiting for the background threads to start
131102  9:38:45 InnoDB: 5.5.34 started; log sequence number 1300038142994
131102  9:38:45 [Note] Recovering after a crash using /archives/mysql/binlogs/db5-bin-log
131102  9:38:45 [Note] Starting crash recovery...
131102  9:38:45 [Note] Crash recovery finished.
131102  9:38:45 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131102  9:38:45 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131102  9:38:45 [Note] Server socket created on IP: '0.0.0.0'.
131102  9:38:45 [Note] Event Scheduler: Loaded 0 events
131102  9:38:45 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.34-log'  socket: '/data/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)

How to repeat:
Sign into server remotely or locally via TCP or socket and issue "START SLAVE".
[14 Nov 2013 19:07] Sveta Smirnova
Thank you for the report.

Error log explains what happens:

InnoDB: Error: trying to access page number 170335 in space 104,
InnoDB: space name ./DATA/TABLE.ibd,
InnoDB: which is outside the tablespace bounds.

Please check if such a table exists on your slave and not corrupted. For example, run following statements: SHOW CREATE TABLE DATA.TABLE; CHECK TABLE DATA.TABLE; and send us result. Note, that CHECK TABLE can shutdown your server in case if DATA.TABLE is corrupted.
[15 Dec 2013 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[19 Aug 2015 8:07] MySQL Verification Team
This is an innodb problem not a replication problem.  To troubleshoot innodb corruption you should examine entire mysql error log,  system messages,  check storage functions okay.

Here is the resolved stack trace:

0x00000000007ac645: my_print_stacktrace at stacktrace.c:225
0x00000000006844f4: handle_fatal_signal at signal_handler.cc:164
0x0000000000870bee: fil_io at fil0fil.c:4602
0x000000000084a478: buf_read_page_low at buf0rea.c:191
0x000000000084ad27: buf_read_page at buf0rea.c:407
0x000000000083e461: buf_page_get_gen at buf0buf.c:2319
0x0000000000827c27: btr_cur_search_to_nth_level at btr0cur.c:602
0x00000000008cb127: row_ins_index_entry_low at row0ins.c:2026
0x00000000008cd69f: row_ins at row0ins.c:2266
 (inlined by) row_ins_step at row0ins.c:2601
0x00000000007d8be6: row_insert_for_mysql at row0mysql.c:1242
0x00000000007c44ca: ha_innobase::write_row(unsigned char*) at ha_innodb.cc:5240
0x00000000006899bd: handler::ha_write_row(unsigned char*) at handler.cc:5196
0x000000000072753a: Rows_log_event::write_row(Relay_log_info const*, bool) at log_event.cc:9231
0x0000000000727822: Write_rows_log_event::do_exec_row(Relay_log_info const*) at log_event.cc:9392
0x00000000007294b4: Rows_log_event::do_apply_event(Relay_log_info const*) at log_event.cc:8049
0x000000000052874d: apply_event_and_update_pos(Log_event*, THD*, Relay_log_info*) at slave.cc:2443
0x000000000052d552: exec_relay_log_event at slave.cc:2579
0x000000000052ea11: handle_slave_sql at slave.cc:3397