Assertion failure on apply-logs

Bug #723097 reported by Marcus Bointon on 2011-02-22
This bug report is a duplicate of:  Bug #690661: build with --with-extra-charsets=all. Edit Remove
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

We're running xtrabackup 1.4-193.lucid.25 and percona server 5.1.54-12.5-188.lucid on Ubuntu lucid. xtrabackup does a complete backup every day, resultiing in a compressed size of about 50Gb.

We're getting an intermittent assertion failure on apply-logs. Most days this works perfectly, but 1-2 times per week, the resulting backup fails to restore as described below.

Backups are created like this:

# /usr/bin/innobackupex-1.5.1 --user=root --password=password --ibbackup=/usr/bin/xtrabackup --slave-info --stream=tar --throttle=350 --tmpdir=/var/backups/xtrabackuptmp /var/backups/xtrabackup 2> /tmp/xtrabackup.out | /usr/bin/pigz -p 5 --stdout --best -q > /var/backups/mysql/daily.1.tar.gz

The backup script that does this checks that the output said "completed OK!" at the end, and we're not getting any failures there.

To restore we first extract the tar archive into a new empty directory:

# cd /data/db
# tar xzvfi /var/backups/mysql/daily.1.tar.gz

Then apply-logs like this:

# innobackupex-1.5.1 --apply-log --use-memory=5G --ibbackup=/usr/bin/xtrabackup /data/db
Version string '' contains invalid data; ignoring: '' at /usr/bin/innobackupex-1.5.1 line 1708.

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy.
All Rights Reserved.

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-1.5.1
           prints "completed OK!".

110222 11:52:01 innobackupex-1.5.1: Starting ibbackup with command: /usr/bin/xtrabackup --prepare --target-dir=/data/db --use-memory=5G

/usr/bin/xtrabackup Ver 1.4 Rev 193 for 5.1.47 unknown-linux-gnu (x86_64)
xtrabackup: cd to /data/db
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=13926400, start_lsn=(679026977997)
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 = 13926400
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 5368709120 bytes for buffer pool (set by --use-memory parameter)
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Warning: innodb_file_io_threads is deprecated. Please use innodb_read_io_threads and innodb_write_io_threads instead
110222 11:52:02 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 679026977997
110222 11:52:02 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Doing recovery: scanned up to log sequence number 679032220672 (42 %)
InnoDB: Doing recovery: scanned up to log sequence number 679037463552 (84 %)
InnoDB: Doing recovery: scanned up to log sequence number 679039346585 (99 %)
110222 11:52:05 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 0 31396311, file name mysql-bin.000163
InnoDB: and relay log file
InnoDB: position 0 31396456, file name ./mysqld-relay-bin.001224
InnoDB: Last MySQL binlog file position 0 16782487, file name /var/log/mysql/mysql-bin.000837
110222 11:52:30 Percona XtraDB (http://www.percona.com) 1.0.8-11.2 started; log sequence number 679039346585
110222 11:52:32 InnoDB: Assertion failure in thread 140009625151232 in file xtrabackup.c line 1141
InnoDB: Failing assertion: cset == 0
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.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
innobackupex-1.5.1: Error:
innobackupex-1.5.1: ibbackup failed at /usr/bin/innobackupex-1.5.1 line 534.

So, we currently don't have confidence in our backups. Any idea of the cause of this and how we might fix it?

Related branches

I found a clue. Trying to start mysql after the failed restore flagged a problem with the ib_logfile* sizes. After the (failed) restore, there are no ib_logfile* files in the data dir. Logfile size on both backup and restore machines is set to 64M. Starting mysql at this point results in a single 14M log file being created, leading to this error in the logs:

110222 14:17:12 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
110222 14:17:12 InnoDB: Initializing buffer pool, size = 5.4G
110222 14:17:12 InnoDB: Completed initialization of buffer pool
InnoDB: Error: log file ./ib_logfile0 is of different size 0 13926400 bytes
InnoDB: than specified in the .cnf file 0 67108864 bytes!
110222 14:17:12 [ERROR] Plugin 'InnoDB' init function returned error.
110222 14:17:12 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
110222 14:17:13 [Note] Event Scheduler: Loaded 0 events
110222 14:17:13 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.54-rel12.5-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Percona Server (GPL), 12.5 , Revision 188)

Is it correct that xtrabackup does not include the ib_logfile* files?

Another possible source of this problem: The server the backup is created on is running 5.1.52, the restore server is running 5.1.54. If this was the other way around it would not seem unreasonable, but I don't see that this should cause a problem.
Any ideas?

Something else occurred to me. On the restore server, there may be binlogs lying around (not in the datadir, so not replaced by the restore mechanism) from whatever the server was previously running. Their filenames are unlikely to correspond with anything in the backup, but are that likely to be a source of this error?

I have eliminated the server version mismatch as a cause. I get the same problem when restoring to the same version (5.1.52r11.6).

Still seeing this with 5.1.55-rel12.6-log and xtrabackup 1.5-203.lucid.3

Percona did a custom build of xtrabackup 1.6.1 for us which includes the charset fix mentioned in #690661, and it does indeed appear to fix our restore problems, successfully restoring backups that always failed before. It's worth noting that this does appear to be a restore-only issue, so any backups already created are fine. This bug can probably be closed now.

Stewart Smith (stewart) wrote :

Excellent! Thanks for keeping the bug up to date, it's much appreciated!

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

Other bug subscribers