ib_logfiles are not copied on restore

val123 · December 30, 2020, 4:20pm

I’m trying to setup xtrabackup from Percona on CentOS 6.3 x86_64 with MySQL 5.1 and/or 5.5.
I have working environments with Percona backup setup on RHEL5.5 (Tikanga) with MySQL 5.5.20 that I’ve used many times to backup and restore innodb databases.

I need to setup CentOS 6.3 machine with some version of MySQL and I need to run periodic backup on it. The current size of db is only 25G, but we expect growth to over 100G in the next year or so, and I thought setting up percona backup using innobackupex would be a good idea.

I installed fresh CentOS 6.3 on 64-bit virtual machine on ESXi. I downloaded MySQL5.5.29 from mysql site, installed server, on top I tried installing percona-xtrabackup and I got my first surprise - it was missing some mysql libraries. I googled that there might be an issue with this version of MySQL, so I downloaded 5.1.68 from mysql web site, uninstalled 5.5.29, put MySQL 5.1.68 and on top percona-xtrabackup using yum install from percona repositories and it worked.

I copied my.cnf file from the production working environment, started mysql service, created database and one innodb table with one row in it.

Then I ran:
$ innobackupex --user=“root” --password=“XXX” /var/tmp/
$ innobackupex --user=“root” --password=“XXX” --apply-log /var/tmp/FOLDER_WITH_DATE

Both commands ran nicely, I got all OKs in the logs, I checked the files that were copied, everything looks neat.

Now, I stop mysql service, I rename /var/lib/mysql folder, I create empty /var/lib/mysql folder, give mysql user permission over it, and I run:
$ innobackupex --user=“root” --password=“XXX” --copy-back /var/tmp/FOLDER_WITH_DATE

I receive line “innobackupex: completed OK!”

If I go to the /var/lib/mysql folder I see taht ibdata1 file is there, my database folder is there, even the table frm and ibd files are there, but there are no files ib_logfile0 and ib_logfile1. If I change files ownership inside /var/lib/mysql to mysql and start service, I’m getting this in mysqld.log file:

130306 11:14:55 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
130306 11:14:55 [Note] Plugin ‘FEDERATED’ is disabled.
^G/usr/sbin/mysqld: Can’t find file: ‘./mysql/plugin.frm’ (errno: 13)
130306 11:14:55 [ERROR] Can’t open the mysql.plugin table. Please run mysql_upgrade to create it.
130306 11:14:55 InnoDB: Initializing buffer pool, size = 2.0G
130306 11:14:56 InnoDB: Completed initialization of buffer pool
130306 11:14:56 InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to
InnoDB: the directory.
InnoDB: File name /var/lib/mysql/ibdata1
InnoDB: File operation call: ‘open’.
InnoDB: Cannot continue operation.
130306 11:14:56 mysqld_safe mysqld from pid file /var/lib/mysql/.pid ended

Please help, what am I doing wrong? I can work with mysql, I can backup using mysqldump, but I’d love to have percona solution there and I don’t seem to find explanation to why this thing doesn’t work anywhere.

Thank you!

miguelangelnieto · December 30, 2020, 4:29pm

Error 13 means permission problems, check that the files are owned by mysql:mysql. mysqld usually runs with “mysql” user, but in your case it can’t open ibdata1 or frm files.

About the ib_logfiles they are not needed when restoring the backup. Anyway, those two files should be created by the --apply-log parameter. Can you attach the full --apply-log output?

val123 · December 30, 2020, 4:30pm

As I mentioned in the steps I adjust ownership of all files in /var/lib/mysql folder using command:
$ chown -Rh mysql: *

Here is the full log of the innobackupex:

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

130307 05:01:45 innobackupex: Starting mysql with options: --password=xxxxxxxx --user=‘root’ --unbuffered –
130307 05:01:45 innobackupex: Connected to database with mysql child process (pid=12367)
130307 05:01:51 innobackupex: Connection to database server closed
IMPORTANT: Please check that the backup run completes successfully.
At the end of a successful backup run innobackupex
prints “completed OK!”.

innobackupex: Using mysql Ver 14.14 Distrib 5.5.13, for Linux (x86_64) using readline 5.1
innobackupex: Using mysql server version Copyright © 2000, 2010, Oracle and/or its affiliates. All rights reserved.

innobackupex: Created backup directory /var/backups/2013-03-07_05-01-51
130307 05:01:51 innobackupex: Starting mysql with options: --password=xxxxxxxx --user=‘root’ --unbuffered –
130307 05:01:51 innobackupex: Connected to database with mysql child process (pid=12393)
130307 05:01:53 innobackupex: Connection to database server closed

130307 05:01:53 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-group=“mysqld” --backup --suspend-at-end --target-dir=/var/backups/2013-03-07_05-01-51
innobackupex: Waiting for ibbackup (pid=12401) to suspend
innobackupex: Suspend file ‘/var/backups/2013-03-07_05-01-51/xtrabackup_suspended’

xtrabackup_55 version 2.0.5 for Percona Server 5.5.16 Linux (x86_64) (revision id: 499)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /var/lib/mysql
xtrabackup: Target instance is assumed as followings.
xtrabackup: innodb_data_home_dir = /var/lib/mysql
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 536870912
xtrabackup: using O_DIRECT

log scanned up to (1594299)
[01] Copying /var/lib/mysql/ibdata1 to /var/backups/2013-03-07_05-01-51/ibdata1
[01] …done
[01] Copying ./gaming/config_set.ibd to /var/backups/2013-03-07_05-01-51/./gaming/config_set.ibd
[01] …done

130307 05:01:54 innobackupex: Continuing after ibbackup has suspended
130307 05:01:54 innobackupex: Starting mysql with options: --password=xxxxxxxx --user=‘root’ --unbuffered –
130307 05:01:54 innobackupex: Connected to database with mysql child process (pid=12415)
130307 05:01:56 innobackupex: Starting to lock all tables…

log scanned up to (1594299)
log scanned up to (1594299)
130307 05:02:06 innobackupex: All tables locked and flushed to disk

130307 05:02:06 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of ‘/var/lib/mysql’
innobackupex: Backing up files ‘/var/lib/mysql/mysql/*.{frm,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM ,ARZ,CSM,CSV,opt,par}’ (69 files)
innobackupex: Backing up file ‘/var/lib/mysql/gaming/config_set.frm’
innobackupex: Backing up file ‘/var/lib/mysql/gaming/db.opt’
130307 05:02:07 innobackupex: Finished backing up non-InnoDB tables and files

130307 05:02:07 innobackupex: Waiting for log copying to finish

xtrabackup: The latest check point (for incremental): ‘1594299’
xtrabackup: Stopping log copying thread.
.>> log scanned up to (1594299)

xtrabackup: Transaction log of lsn (1594299) to (1594299) was copied.
130307 05:02:10 innobackupex: All tables unlocked
130307 05:02:10 innobackupex: Connection to database server closed

innobackupex: Backup created in directory ‘/var/backups/2013-03-07_05-01-51’
innobackupex: MySQL binlog position: filename ‘’, position
130307 05:02:10 innobackupex: completed OK!

And here is the full log of --apply-log command:

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

IMPORTANT: Please check that the apply-log run completes successfully.
At the end of a successful apply-log run innobackupex
prints “completed OK!”.

130307 05:03:36 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/var/backups/2013-03-07_05-01-51/backup-my.cnf " --defaults-group=“mysqld” --prepare --target-dir=/var/backups/2013-03-07_05-01-51

xtrabackup_55 version 2.0.5 for Percona Server 5.5.16 Linux (x86_64) (revision id: 499)
xtrabackup: cd to /var/backups/2013-03-07_05-01-51
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(1594299)
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
130307 5:03:36 InnoDB: The InnoDB memory heap is disabled
130307 5:03:36 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130307 5:03:36 InnoDB: Compressed tables use zlib 1.2.3
130307 5:03:36 InnoDB: Initializing buffer pool, size = 100.0M
130307 5:03:36 InnoDB: Completed initialization of buffer pool
130307 5:03:36 InnoDB: highest supported file format is Barracuda.
130307 5:03:36 Percona XtraDB () 1.1.8-20.1 started; log sequence number 1594299

[notice (again)]
If you use binary log and don’t use any hack of group commit,
the binary log position seems to be:

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
130307 5:03:36 InnoDB: Starting shutdown…
130307 5:03:41 InnoDB: Shutdown completed; log sequence number 1595529

130307 05:03:41 innobackupex: Restarting xtrabackup with command: xtrabackup_55 --defaults-file="/var/backups/2013-03-07_05-01-51/backup-my.cnf " --defaults-group=“mysqld” --prepare --target-dir=/var/backups/2013-03-07_05-01-51
for creating ib_logfile*

xtrabackup_55 version 2.0.5 for Percona Server 5.5.16 Linux (x86_64) (revision id: 499)
xtrabackup: cd to /var/backups/2013-03-07_05-01-51
xtrabackup: This target seems to be already prepared.
xtrabackup: notice: xtrabackup_logfile was already used to ‘–prepare’.
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 536870912
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 536870912
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
130307 5:03:41 InnoDB: The InnoDB memory heap is disabled
130307 5:03:41 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130307 5:03:41 InnoDB: Compressed tables use zlib 1.2.3
130307 5:03:41 InnoDB: Initializing buffer pool, size = 100.0M
130307 5:03:41 InnoDB: Completed initialization of buffer pool
130307 5:03:41 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 512 MB
InnoDB: Database physically writes the file full: wait…
InnoDB: Progress in MB: 100 200 300 400 500
130307 5:03:46 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 512 MB
InnoDB: Database physically writes the file full: wait…
InnoDB: Progress in MB: 100 200 300 400 500
130307 5:03:50 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
130307 5:03:50 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files…
130307 5:03:50 InnoDB: Waiting for the background threads to start
130307 5:03:51 Percona XtraDB () 1.1.8-20.1 started; log sequence number 1595916

[notice (again)]
If you use binary log and don’t use any hack of group commit,
the binary log position seems to be:

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
130307 5:03:51 InnoDB: Starting shutdown…
130307 5:03:55 InnoDB: Shutdown completed; log sequence number 1595916
130307 05:03:55 innobackupex: completed OK!

And here are the files that were created:

total 1069084
-rw-r–r--. 1 root root 262 Mar 7 05:01 backup-my.cnf
drwx------. 2 root root 4096 Mar 7 05:02 gaming
-rw-r-----. 1 root root 18874368 Mar 7 05:03 ibdata1
-rw-r–r--. 1 root root 536870912 Mar 7 05:03 ib_logfile0
-rw-r–r--. 1 root root 536870912 Mar 7 05:03 ib_logfile1
drwxr-xr-x. 2 root root 4096 Mar 7 05:02 mysql
-rw-r–r--. 1 root root 13 Mar 7 05:02 xtrabackup_binary
-rw-r–r--. 1 root root 4 Mar 7 05:02 xtrabackup_binlog_info
-rw-r-----. 1 root root 77 Mar 7 05:03 xtrabackup_checkpoints
-rw-r-----. 1 root root 2097152 Mar 7 05:03 xtrabackup_logfile

And when I do restore, ib_logfiles are not created and after I change ownership, I can’t start mysql.

What would you advise? On RHEL5.5 it works exactly like this.

Thanks!