MySQL 5.6 failed to start after xtrabackup 2.4 apply-log:sym_node->table != NULL

[Nickolay Ihalainen]

This is could be related to: http://bugs.mysql.com/bug.php?id=69274
The bug suggests to use innodb_fast_shutdown = 0 for upgrades (and downgrade in our case),
but xtrabackup calling shutdown with innodb_fast_shutdown = 1 twice.

2016-12-01 20:21:02 7f63dc4b07c0 InnoDB: Assertion failure in thread 140066874394560 in file pars0pars.cc line 865
InnoDB: Failing assertion: sym_node->table != NULL
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.
20:21:02 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 Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=16777216
read_buffer_size=1048576
max_used_connections=0
max_threads=100001
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 = 307674637 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8d828c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x65a791]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f63da9ae330]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f63d9defc37]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f63d9df3028]
/usr/sbin/mysqld[0x9a69c9]
/usr/sbin/mysqld(_Z7yyparsev+0xe1b)[0xae93bb]
/usr/sbin/mysqld[0x9a82d1]
/usr/sbin/mysqld[0x9ac2b6]
/usr/sbin/mysqld[0x9d3ba4]
/usr/sbin/mysqld[0x9d5804]
/usr/sbin/mysqld[0x9802ee]
/usr/sbin/mysqld[0x9fe10a]
/usr/sbin/mysqld[0x939cd1]
/usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x48)[0x59b958]
/usr/sbin/mysqld[0x6e8af1]
/usr/sbin/mysqld(_Z11plugin_initPiPPci+0x97a)[0x6ef03a]
/usr/sbin/mysqld[0x59418d]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x42c)[0x59521c]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f63d9ddaf45]
/usr/sbin/mysqld[0x58699d]

Apply log:

InnoDB: xtrabackup: Last MySQL binlog file position 137636015, file name mysql-bin.000046

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 30118062344
InnoDB: Number of pools: 1
InnoDB: The log block size is set to 4096.
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 8589934592
InnoDB: PUNCH HOLE support available
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Uses event mutexes
InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Number of pools: 1
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, total size = 128G, instances = 1, chunk size = 128M
InnoDB: Completed initialization of buffer pool
InnoDB: page_cleaner coordinator priority: -20
InnoDB: Setting log file ./ib_logfile101 size to 8192 MB
InnoDB: Progress in MB:
 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300 1400 1500 1600 1700 1800 1900 2000 2100 2200 2300 2400 2500 2600 2700 2800 2900 3000 3100 3200 3300 3400 3500 3600 3700 3800 3900 4000 4100 4200 4300 4400 4500 4600 4700 4800 4900 5000 5100 5200 5300 5400 5500 5600 5700 5800 5900 6000 6100 6200 6300 6400 6500 6600 6700 6800 6900 7000 7100 7200 7300 7400 7500 7600 7700 7800 7900 8000 8100
InnoDB: Setting log file ./ib_logfile1 size to 8192 MB
InnoDB: Progress in MB:
 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300 1400 1500 1600 1700 1800 1900 2000 2100 2200 2300 2400 2500 2600 2700 2800 2900 3000 3100 3200 3300 3400 3500 3600 3700 3800 3900 4000 4100 4200 4300 4400 4500 4600 4700 4800 4900 5000 5100 5200 5300 5400 5500 5600 5700 5800 5900 6000 6100 6200 6300 6400 6500 6600 6700 6800 6900 7000 7100 7200 7300 7400 7500 7600 7700 7800 7900 8000 8100
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=30118062344
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 30118064140
InnoDB: Doing recovery: scanned up to log sequence number 30118064149 (0%)
InnoDB: Doing recovery: scanned up to log sequence number 30118064149 (0%)
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: xtrabackup: Last MySQL binlog file position 137636015, file name mysql-bin.000046
InnoDB: Removed temporary tablespace data file: "ibtmp1"
InnoDB: Creating shared tablespace for temporary tables
InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
InnoDB: File './ibtmp1' size is now 12 MB.
InnoDB: 96 redo rollback segment(s) found. 1 redo rollback segment(s) are active.
InnoDB: 32 non-redo rollback segment(s) are active.
InnoDB: page_cleaner: 1000ms intended loop took 140132ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
InnoDB: 5.7.13 started; log sequence number 30118064149
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 30118065050

[Sergei Glushchenko (sergei.glushchenko)]

Hi Nickolay,

Can I see full server error log? Looks like InnoDB is trying to open some table on startup (maybe one of system tables) and fails to do so. In case of corrupted table we should see something in error log. I could also be that number of colimnts/indices do not match. Also, resolved server stack trace could help to see which statement InnoDB is trying to execute here.

[Shahriyar Rzayev (rzayev-sehriyar)]

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