Xtrabackup 2.3.x Creating Log Files With Incorrect Size

[Pat Suwalski]

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.

[Sergei Glushchenko (sergei.glushchenko)]

Looks like duplicate of 1527081

[Pat Suwalski (pat-suwalski)]

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)]

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)]

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.