Mysql – Issues with thesql enterprise backup, assertion failure on restore

backupMySQLmysql-5.6restore

I'm trying to restore a backup to a new server, but having some issues with corruption. The source server has a 2.5T table which is very active. I copied the latest backup over to a new server and restored it, but I'm getting an assertion error at the end of the restore.

The db will start up but I'll continually get those innodb errors about the logs being in the future.
I know the answer for a corrupt db, or forcing recovery, is usually dump and restore. That's really not possible on on 2.5T table and I'm wondering why I'm getting these errors on a supposedly "successful" backup.

MySQL Enterprise Backup version 3.12.0 Linux-3.8.13-16.2.1.el6uek.x86_64-x86_64 [2015/03/10]
Copyright (c) 2003, 2015, Oracle and/or its affiliates. All Rights Reserved.

mysqlbackup: INFO: Starting with following command line ...
mysqlbackup --defaults-file=/etc/my.cnf
    --backup-dir=/transfer/radius_backup_08132015.01.30.01.375562935
    copy-back-and-apply-log

mysqlbackup: INFO:
IMPORTANT: Please check that mysqlbackup run completes successfully.
       At the end of a successful 'copy-back-and-apply-log' run mysqlbackup
       prints "mysqlbackup completed OK!".

150819 16:00:53 mysqlbackup: INFO: MEB logfile created at /transfer/radius_backup_08132015.01.30.01.375562935/meta/MEB_2015-08-19.16-00-53_copy_back_dir_to_datadir.log

 mysqlbackup: WARNING: If you restore to a server of a different version, the innodb_data_file_path parameter might have a different default. In that case you need to add 'innodb_data_file_path=ibdata1:12M:autoextend' to the target server configuration.
mysqlbackup: WARNING: If you restore to a server of a different version, the innodb_log_files_in_group parameter might have a different default. In that case you need to add 'innodb_log_files_in_group=2' to the target server configuration.
--------------------------------------------------------------------
                   Server Repository Options:
--------------------------------------------------------------------
datadir = /mysqldata/mysql
innodb_data_home_dir = /mysqldata/mysql
innodb_data_file_path = ibdata1:12M:autoextend
innodb_log_group_home_dir = /mysqldata/mysql
innodb_log_files_in_group = 2
innodb_log_file_size = 128MB
innodb_page_size = Null
innodb_checksum_algorithm = innodb

--------------------------------------------------------------------
                        Backup Config Options:
--------------------------------------------------------------------
datadir = /transfer/radius_backup_08132015.01.30.01.375562935/datadir
innodb_data_home_dir = /transfer/radius_backup_08132015.01.30.01.375562935/datadir
innodb_data_file_path = ibdata1:12M:autoextend
innodb_log_group_home_dir = /transfer/radius_backup_08132015.01.30.01.375562935/datadir
innodb_log_files_in_group = 2
innodb_log_file_size = 134217728
innodb_page_size = 16384
innodb_checksum_algorithm = innodb

mysqlbackup: INFO: Creating 14 buffers each of size 16777216.
150819 16:00:53 mysqlbackup: INFO: Copy-back-and-apply-log operation starts with following threads
            1 read-threads    1 write-threads
mysqlbackup: INFO: Could not find binlog index file. binlogs will not be copied for this backup.
Point-In-Time-Recovery will not be possible.
If this is online backup then server may not have started with --log-bin.
You may specify its location with --log-bin-index option.
150819 16:00:53 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/ibdata1.
150819 16:00:53 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/mysql/innodb_index_stats.ibd.
150819 16:00:54 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/mysql/innodb_table_stats.ibd.
150819 16:00:54 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/mysql/slave_master_info.ibd.
150819 16:00:54 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/mysql/slave_relay_log_info.ibd.
150819 16:00:54 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/mysql/slave_worker_info.ibd.
150819 16:00:54 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/percona/checksums.ibd.
150819 16:00:54 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/radius/cui.ibd.
150819 16:00:54 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/radius/nas.ibd.
150819 16:00:54 mysqlbackup: INFO: Copying /transfer/radius_backup_08132015.01.30.01.375562935/datadir/radius/radacct.ibd.
mysqlbackup: Progress in MB: 200 400 600 800 1000 1200 1400 1600 1800 2000 2200 2400 2600 2800 3000 3200 3400

 <snip>

150820 00:54:37 mysqlbackup: INFO: Copying the database directory 'mysql'
150820 00:54:37 mysqlbackup: INFO: Copying the database directory 'percona'
150820 00:54:37 mysqlbackup: INFO: Copying the database directory 'radius'
150820 00:54:37 mysqlbackup: INFO: Completing the copy of all non-innodb files.
150820 00:54:38 mysqlbackup: INFO: Creating server config files server-my.cnf and server-all.cnf in /mysqldata/mysql
150820 00:54:38 mysqlbackup: INFO: Copy-back operation completed successfully.
mysqlbackup: INFO: Creating 14 buffers each of size 65536.
150820 00:54:38      mysqlbackup: INFO: Apply-log operation starts with following threads
1 read-threads    1 process-threads
mysqlbackup: INFO: Using up to 100 MB of memory.
    150820 00:54:38 mysqlbackup: INFO: ibbackup_logfile's creation parameters:
      start lsn 10489797849600, end lsn 10500114427565,
      start checkpoint 10489797849969.
InnoDB: Doing recovery: scanned up to log sequence number 10489803092480
 InnoDB: Doing recovery: scanned up to log sequence number 10489808335360
      InnoDB: Doing recovery: scanned up to log sequence number 10489813578240
InnoDB: Doing recovery: scanned up to log sequence number 10489818821120
InnoDB: Doing recovery: scanned up to log sequence number 10489824064000
InnoDB: Doing recovery: scanned up to log sequence number 10489829306880
InnoDB: Doing recovery: scanned up to log sequence number 10489834549760
mysqlbackup: INFO: InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 2015-08-20     00:54:53 7f9356014700  InnoDB: Assertion failure in file /export/home/pb2/build_bi/sb_7-14661950-1425966633.09/mysql/storage/innobase/page/page0zip.cc line 4236
InnoDB: Failing assertion: slot
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.

After mysql starts up, the error log will fill up with the error below, but I can get into mysql and query all tables.

2015-08-20 16:53:10 7f297ffff700 InnoDB: Error: page 409 log sequence number 10487836334381
InnoDB: is in the future! Current system log sequence number 1630346.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. 

Here is the mysqlbackup command we use, it's in a script which is why there are variables everywhere.

mysqlbackup --defaults-file=/etc/my.cnf --user=$user -p${password} --databases=radius --backup-dir=${dir}/${database_name}/${database_name}_backup_$date --socket=/var/lib/mysql/mysql.sock --port=3306 backup --compress --compress-level=5 2>  $dir/${BACKUP_LOG}/Error_${database_name}_DB_Backup${dstr1}.log

And here is the command I used to restore it.

mysqlbackup --defaults-file=<my.cnf> -uroot --backup-dir=<backupDir> --uncompress copy-back-and-apply-log

On a side note, should I increase the innodb_log_file_size? It's currently at 128M and I figured out it's writing almost 50M a minute to the log file. We had an issue last weekend where the backup failed with the error below.
I was thinking about increasing it to 1024M??

mysqlbackup: ERROR: Log scan was only able to reach 10572453925888,
      but a checkpoint was at 10572582184834.
      This means that the database server has overwritten
      a part of the circular InnoDB log files before ibbackup
      was able to read it.
      To solve this problem either:
      1) re-run the backup when the database has less load, or
      2) re-configure the database with bigger InnoDB log files.

mysqlbackup failed with errors!

Thanks for any help and sorry for the long post!

Best Answer

I have this issue as well. I have found it related to the global variable old_alter_table being turned on by mysqlbackup. This happens only with our created backup account. If I have the problem and run the backup as root, I have found I don't have to bounce the database.