Xtrabackup 2.3.x Creating Log Files With Incorrect Size

Bug #1528271 reported by Pat Suwalski on 2015-12-21
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
New
Undecided
Unassigned

Bug Description

This was initially noticed with 2.3.2, but it still happens with 2.3.3.

I've been using innobackupex weekly for years now without any issue on a fairly large database (1.6T).

With recent versions, my backup fails to create a launchable database after the --apply-log step. Yes, the command definitely reaches the "completed OK!" stage. I do not see anything unusual in the output.

The backup-my.cnf file has the correct parameters:

--------
# This MySQL options file was generated by innobackupex.

# The MySQL server
[mysqld]
innodb_checksum_algorithm=innodb
innodb_log_checksum_algorithm=innodb
innodb_data_file_path=ibdata1:1024M:autoextend
innodb_log_files_in_group=2
innodb_log_file_size=268435456
innodb_fast_checksum=false
innodb_page_size=16384
innodb_log_block_size=512
innodb_undo_directory=.
innodb_undo_tablespaces=0
--------

However, after the process completes, I'm left with:

--------
-rw-r--r-- 1 mysql mysql 50331648 Nov 15 16:24 ib_logfile0
-rw-r--r-- 1 mysql mysql 50331648 Nov 15 16:24 ib_logfile1
--------

At this point, mysql fails to start:

--------
InnoDB: Error: log file ./ib_logfile0 is of different size 0 50331648 bytes
InnoDB: than specified in the .cnf file 0 268435456 bytes!
151115 16:24:54 [ERROR] Plugin 'InnoDB' init function returned error.
151115 16:24:54 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
151115 16:24:54 [ERROR] Unknown/unsupported storage engine: InnoDB
151115 16:24:54 [ERROR] Aborting
--------

Deleting the files allows the database to start, albeit with some potentially serious warnings:

--------
151116 11:13:05 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 256 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
151116 11:13:06 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 256 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
151116 11:13:08 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!
151116 11:13:08 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
--------

My analysis:

It occurs to me that 50331648÷1024÷1024=48, so the log file size is getting a bad value somewhere along the way. This value does not show up anywhere in my.cnf. But it is worth noting that the 256M logfile size is specified under a mysqld_multi configuration, in the [mysqld1] section. Perhaps it is not getting parsed somewhere.

Looks like duplicate of 1527081

Pat Suwalski (pat-suwalski) wrote :

Looks like it may very well be a duplicate. That other issue goes into a tangent about cluster setups and whatnot. I may attempt explicitly specifying the defaults file.

In either case, the other issue suggests it's a bug, and it should not be too difficult to track down since the exact nature of the issue and workaround are known, and it's clear what version it broke on.

Pat Suwalski (pat-suwalski) wrote :

Looking at the old innobackupex.pl from the 2.2 branch, I see the following lines:

sub read_config_file {
(...)
   if ($option_apply_log) {
        $options = $options .
            " --defaults-file=\"${backup_dir}/backup-my.cnf\" ";

The C++ implementation needs something like this.

Pat Suwalski (pat-suwalski) wrote :

Looks like innobackupex.cc has something similar:

bool
ibx_handle_options(int *argc, char ***argv)
{
(...)
        if (ibx_mode == IBX_MODE_APPLY_LOG
            || ibx_mode == IBX_MODE_COPY_BACK
            || ibx_mode == IBX_MODE_MOVE_BACK) {
                ut_snprintf(backup_config_path, sizeof(backup_config_path),
                        "%s/backup_my.cnf", ibx_position_arg);
                load_defaults(backup_config_path, groups, argc, argv);
        }

Maybe I'm misinterpreting the code around it, but the "%s" may not getting populated with the correct path, based on the argument processing logic in the lines preceding.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers