xtrabackup Assertion failure with Apply log process

[Arunjith]

While applying the log we are facing an assertion failure issue with xtrabackup version 2.1.9 so we decided to upgrade the tool to version 2.2.3. But still we are hitting the same error.

The issue is not occurring on every try, last time we found the issue when we initiated an incremental backup proceeding to a full backup. We have completed the full backup successfully but the incremental ended with the same error. Log details are given below.

Version :
[05:54:02 xxx@xxxx:~]# xtrabackup -v
xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )

[xxxx@xxxxxx~]$ innobackupex --version
InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy

mysql version: 5.6.17-66.0-log

Log:

InnoDB: Progress in percent: 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 329970412, file name data3-bin.001806
InnoDB: Last MySQL binlog file position 0 883545871, file name data1-bin.002972
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.17 started; log sequence number 13967966489023

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 883545871, file name data1-bin.002972

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
2014-09-12 05:13:40 4a7ee940 InnoDB: Assertion failure in thread 1249831232 in file buf0flu.cc line 2503
InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2610.

[Muhammad Irfan (muhammad-irfan)]

I tried it with full + incremental scheme but was not able to reproduce it. Can you please show exact commands you used.

[Arunjith (arunjith-aravindan)]

Here is the recent log:

140916 05:43:38 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/mnt/MOUNTED_DIR/db_back/server.name.com/full/2014-09-14_03-30-03/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/mnt/MOUNTED_DIR/db_back/server.name.com/full/2014-09-14_03-30-03 --incremental-dir=/mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03 --tmpdir=/tmp

Warning: World-writable config file '/mnt/MOUNTED_DIR/db_back/server.name.com/full/2014-09-14_03-30-03/backup-my.cnf' is ignored
xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
incremental backup from 14111243331989 is enabled.
xtrabackup: cd to /mnt/MOUNTED_DIR/db_back/server.name.com/full/2014-09-14_03-30-03
xtrabackup: This target seems to be already prepared.
xtrabackup: xtrabackup_logfile detected: size=1891237888, start_lsn=(14156284223024)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 1891237888
xtrabackup: page size for /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/ibdata1.delta is 16384 bytes
InnoDB: Failed to set O_DIRECT on file /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/ibdata1.delta: OPEN: Invalid argument, continuing anyway. O_DIRECT is known to result in 'Invalid argument' on Linux on tmpfs, see MySQL Bug#26662.
Applying /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/ibdata1.delta to ./ibdata1...
xtrabackup: page size for /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/currclick_mdl/mdl_assign.ibd.delta is 16384 bytes
Applying /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/currclick_mdl/mdl_assign.ibd.delta to ./currclick_mdl/mdl_assign.ibd...
xtrabackup: page size for /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/currclick_mdl/mdl_assignfeedback_comments.ibd.delta is 16384 bytes
Applying /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/currclick_mdl/mdl_assignfeedback_comments.ibd.delta to ./currclick_mdl/mdl_assignfeedback_comments.ibd...
xtrabackup: page size for /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/currclick_mdl/mdl_assignfeedback_editpdf_annot.ibd.delta is 16384 bytes
Applying /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/currclick_mdl/mdl_assignfeedback_editpdf_annot.ibd.delta to ./currclick_mdl/mdl_assignfeedback_editpdf_annot.ibd...
xtrabackup: page size for /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/currclick_mdl/mdl_assignfeedback_editpdf_cmnt.ibd.delta is 16384 bytes
Applying /mnt/MOUNTED_DIR/db_back/server.name.com/incremental/2014-09-16_03-30-03/currclick_mdl/mdl_assignfeedback_editpdf_cmnt.ibd.delta to ./currclick_mdl/mdl_assignfeedback_editpdf_cmnt.ibd...
xtrabackup: page size fo...

[Jeff Jordan (jdjordan)]

I am getting an assertion failure when running innobackupex --apply-log as well.

Package: xtrabackup
Source: percona-xtrabackup
Version: 2.2.4-5004-1.wheezy

innobackupex --apply-log 2014-10-01_16-58-10/

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

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

Get the latest version of Percona XtraBackup, documentation, and help resources:
http://www.percona.com/xb/p

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

141001 17:00:33 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="/app/backup/2014.10.01/2014-10-01_16-58-10/backup-my.cnf" --defaults-group="mysqld" --prepare --target-dir=/app/backup/2014.10.01/2014-10-01_16-58-10 --tmpdir=/tmp

xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
xtrabackup: cd to /app/backup/2014.10.01/2014-10-01_16-58-10
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(572982443902)
xtrabackup: using the following InnoDB configuration for recovery:
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: using the following InnoDB configuration for recovery:
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)
InnoDB: Using atomics to ref count buffer pool pages
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: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 572982443902
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 572984104313 (89%)
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 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: Last MySQL binlog file position...

[Nilnandan Joshi (nilnandan-joshi)]

Unable to reproduce the same with PS 5.6.17 and Xtrabackup 2.2.5

Can you please try to check the same with latest version of Xtrabackup? (2.2.5)

Also please provide the exact command of taking full backup, incremental backup and apply log. It might helpful to reproduce this bug.

[Arunjith (arunjith-aravindan)]

Joshi,

I have upgraded the xtrabackup to version 2.2.5 and initiated the
incremental backup.

Currently the incremental backup has been completed successfully and the
apply-log process is in progress.

I will update you the details.

# /usr/bin/xtrabackup -v
/usr/bin/xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux
(x86_64) (revision id: )

On Sun, Oct 12, 2014 at 3:26 PM, Nilnandan Joshi <
<email address hidden>> wrote:

> Unable to reproduce the same with PS 5.6.17 and Xtrabackup 2.2.5
>
> Can you please try to check the same with latest version of Xtrabackup?
> (2.2.5)
>
> Also please provide the exact command of taking full backup, incremental
> backup and apply log. It might helpful to reproduce this bug.
>
> ** Changed in: percona-xtrabackup
> Status: New => Incomplete
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1368846
>
> Title:
> xtrabackup Assertion failure with Apply log process
>
> Status in Percona XtraBackup:
> Incomplete
>
> Bug description:
> While applying the log we are facing an assertion failure issue with
> xtrabackup version 2.1.9 so we decided to upgrade the tool to version
> 2.2.3. But still we are hitting the same error.
>
> The issue is not occurring on every try, last time we found the issue
> when we initiated an incremental backup proceeding to a full backup.
> We have completed the full backup successfully but the incremental
> ended with the same error. Log details are given below.
>
> Version :
> [05:54:02 xxx@xxxx:~]# xtrabackup -v
> xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64)
> (revision id: )
>
> [xxxx@xxxxxx~]$ innobackupex --version
> InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
>
> mysql version: 5.6.17-66.0-log
>
> Log:
>
> InnoDB: Progress in percent: 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 329970412, file name data3-bin.001806
> InnoDB: Last MySQL binlog file position 0 883545871, file name
> data1-bin.002972
> InnoDB: 128 rollback segment(s) are active.
> InnoDB: Waiting for purge to start
> InnoDB: 5.6.17 started; log sequence number 13967966489023
>
> [notice (again)]
> If you use binary log and don't use any hack of group commit,
> the binary log position seems to be:
> InnoDB: Last MySQL binlog file position 0 883545871, file name
> data1-bin.002972
>
> xtrabackup: starting shutdown with innodb_fast_shutdown = 1
> InnoDB: FTS optimize thread exiting.
> InnoDB: Starting shutdown...
> 2014-09-12 05:13:40 4a7ee940 InnoDB: Assertion failure in thread
> 1249831232 in file buf0flu.cc line 2503
> InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 0
> InnoDB: We intentionally generate a ...

[Jeff Jordan (jdjordan)]

root@db075:/app/backup# dpkg -l percona-xtrabackup
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Architecture Description
+++-=============================================-===========================-===========================-===============================================================================================
ii percona-xtrabackup 2.2.5-5027-1.wheezy amd64 Open source backup tool for InnoDB and XtraDB

root@db075:/app/backup# /usr/bin/innobackupex /app/backup

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

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

Get the latest version of Percona XtraBackup, documentation, and help resources:
http://www.percona.com/xb/p

141013 15:34:02 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup' (using password: NO).
141013 15:34:02 innobackupex: Connected to MySQL server
141013 15:34:02 innobackupex: Executing a version check against the server...
141013 15:34:02 innobackupex: Done.
IMPORTANT: Please check that the backup run completes successfully.
           At the end of a successful backup run innobackupex
           prints "completed OK!".

innobackupex: Using mysql server version 5.5.37-0+wheezy1-log

innobackupex: Created backup directory /app/backup/2014-10-13_15-34-02

141013 15:34:02 innobackupex: Starting ibbackup with command: xtrabackup --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/app/backup/2014-10-13_15-34-02 --tmpdir=/app/mysql/tmp.mysql --extra-lsndir='/app/mysql/tmp.mysql'
innobackupex: Waiting for ibbackup (pid=9358) to suspend
innobackupex: Suspend file '/app/backup/2014-10-13_15-34-02/xtrabackup_suspended_2'

xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /app/mysql/data
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
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 = 471859200
>> log scanned up to (4073210617)
[01] Copying ./ibdata1 to /app/backup/2014-10-13_15-34-02/ibdata1
[01] ...done
>> log scanned up to (4073211469)
[01] Copying ./comp1/QuestionSharkDocumentCmp.ibd to /app/backup/2014-10-13_15-34-02/comp1/QuestionSharkDocumentCmp.ibd
[01] ...done
[01] Copying ./comp1/CalendarEventContent.ibd to /app/backup/2014-10-13_15-34-02/comp1/CalendarEventContent.ibd
[01] ...done
[01] Copying ./comp1/PollAnswer.ibd to /app/backup/2014-10-13_15-34-02/comp1/PollAnswer.ibd
[01] ...done
[01] Copying ./comp1/UserLikedReply.ibd to /app/backup/2014-1...

[Arunjith (arunjith-aravindan)]

xtrabackup -v
xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux (x86_64)
(revision id: )

Backup :

innobackupex: Created backup directory /mnt/RawPDFs-obsapp002/db_back/
data01.bookdownloader.com/incremental/2014-10-13_14-05-03

141013 14:05:03 innobackupex: Starting ibbackup with command: xtrabackup
--defaults-group="mysqld" --backup --suspend-at-end
--target-dir=/mnt/RawPDFs-obsapp002/db_back/
data01.bookdownloader.com/incremental/2014-10-13_14-05-03 --tmpdir=/dev/shm
--extra-lsndir='/dev/shm'
--incremental-basedir='/mnt/RawPDFs-obsapp002/db_back/
data01.bookdownloader.com/full/2014-10-12_03-30-02'
innobackupex: Waiting for ibbackup (pid=13943) to suspend
innobackupex: Suspend file '/mnt/RawPDFs-obsapp002/db_back/
data01.bookdownloader.com/incremental/2014-10-13_14-05-03/xtrabackup_suspended_2
'

xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux (x86_64)
(revision id: )
incremental backup from 15331124206933 is enabled.
....

Apply log:

141013 16:41:09 innobackupex: Starting ibbackup with command: xtrabackup
--defaults-file="/mnt/RawPDFs-obsapp002/db_back/
data01.bookdownloader.com/full/2014-10-12_03-30-02/backup-my.cnf"
--defaults-group="mysqld" --prepare
--target-dir=/mnt/RawPDFs-obsapp002/db_back/
data01.bookdownloader.com/full/2014-10-12_03-30-02
--incremental-dir=/mnt/RawPDFs-obsapp002/db_back/
data01.bookdownloader.com/incremental/2014-10-13_14-05-03 --tmpdir=/tmp

Error details:

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.
00:15:33 UTC - xtrabackup got signal 6 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x32) [0xa3bc9d]
xtrabackup(handle_fatal_signal+0x335) [0x910c05]
/lib64/libpthread.so.0 [0x36aac0eb10]
/lib64/libc.so.6(gsignal+0x35) [0x36aa030265]
/lib64/libc.so.6(abort+0x110) [0x36aa031d10]
xtrabackup(page_dir_find_owner_slot(unsigned char const*)+0x221) [0x774ebb]
xtrabackup(page_cur_delete_rec(page_cur_t*, dict_index_t const*, unsigned
long const*, mtr_t*)+0xc5) [0x738f49]
xtrabackup(page_cur_parse_delete_rec(unsigned char*, unsigned char*,
buf_block_t*, dict_index_t*, mtr_t*)+0x135) [0x7393eb]
xtrabackup [0x6d4439]
xtrabackup(recv_recover_page_func(unsigned long, buf_block_t*)+0x394)
[0x6d5c6c]
xtrabackup(buf_page_io_complete(buf_page_t*)+0x40c) [0x660e42]
xtrabackup(fil_aio_wait(unsigned long)+0x12e) [0x6e23b8]
xtrabackup(io_handler_thread+0x22) [0x796622]
...

[Alexey Kopytov (akopytov)]

The error log in comment #7 is truncated, so it is not clear whether it is the same assertion as in the original report, or a different one. From the stacktrace in comment #7 it looks like it was a different assertion. Can you confirm this?

[Arunjith (arunjith-aravindan)]

Please consider the delay in response as I was waiting for the backup to
complete. We are still hitting with the similar (Incremental Backup)
assertion failure and here is the recent error message from apply log
process.

Backup :

$INNOBACKUPEX_BIN --no-version-check --user=$USER --password=$PASSWORD
--slave-info --incremental --incremental-basedir=$FULLDIR
$BACKUP_DIR/incremental >> $xb_backup_log 2>&1

Apply log:

$INNOBACKUPEX_BIN --no-version-check --apply-log
--incremental-dir=$LAST_BACKUP $($FIND $BACKUP_DIR/full -maxdepth 1
-mindepth 1 -type d -name 20\* | sort | tail -n 1) >> $xb_prepare_log 2>&1

Log:

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
2014-10-15 07:01:56 4b013940 InnoDB: Assertion failure in thread
1258371392 in file buf0flu.cc line 2507
InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
12:01:56 UTC - xtrabackup got signal 6 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x32) [0xa3bc9d]
xtrabackup(handle_fatal_signal+0x335) [0x910c05]
/lib64/libpthread.so.0 [0x36aac0eb10]
/lib64/libc.so.6(gsignal+0x35) [0x36aa030265]
/lib64/libc.so.6(abort+0x110) [0x36aa031d10]
xtrabackup(buf_flush_page_cleaner_thread+0x54e) [0x7680ec]
/lib64/libpthread.so.0 [0x36aac0673d]
/lib64/libc.so.6(clone+0x6d) [0x36aa0d44bd]

On Tue, Oct 14, 2014 at 11:36 AM, Alexey Kopytov <<email address hidden>
> wrote:

> The error log in comment #7 is truncated, so it is not clear whether it
> is the same assertion as in the original report, or a different one.
> >From the stacktrace in comment #7 it looks like it was a different
> assertion. Can you confirm this?
>
> ** Changed in: percona-xtrabackup
> Status: New => Incomplete
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1368846
>
> Title:
> xtrabackup Assertion failure with Apply log process
>
> Status in Percona XtraBackup:
> Incomplete
>
> Bug description:
> While applying the log we are facing an assertion failure issue with
> xtrabackup version 2.1.9 so we decided to upgrade the tool to version
> 2.2.3. But still we are hitting the same error.
>
> The issue is not occurring on every try, last time we found the issu...

[Alexey Kopytov (akopytov)]

OK, the assertion failure in comment #9 is identical to the one in the original report, but is different from the one in comment #7.

If you ever hit the assertion from comment #7 again, please file it as a separate bug.

[Alexey Kopytov (akopytov)]

Bug #1399873 was marked as a duplicate of this one.

[Alok Pathak (alok-pathak)]

Hi,

We are hitting same bug with Percona Xtrabackup 2.2.7 version as well while preparing incremental backup. We are taking backup from slave server with binary logs enabled and backups are on stored on a cifs (windows) share.

# xtrabackup --version
xtrabackup version 2.2.7 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )

# innobackupex --version
InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy

mysql> show global variables like '%version%';
+-------------------------+--------------------------------------------------+
| Variable_name | Value |
+-------------------------+--------------------------------------------------+
| innodb_version | 5.6.21-70.1 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.21-70.1-log |
| version_comment | Percona Server (GPL), Release 70.1, Revision 698 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+--------------------------------------------------+
7 rows in set (0.01 sec)

mysql> show global variables like 'log_bin';
+---------------------------------+--------------------------------+
| Variable_name | Value |
+---------------------------------+--------------------------------+
| log_bin | ON |
+---------------------------------+--------------------------------+

mysql> show global variables like '%log_slave%';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| log_slave_updates | ON |
+-------------------+-------+
1 row in set (0.00 sec)

# mount | grep -i cifs
//IP/Path on /mnt/Path type cifs (rw,mand)

Following are the commands used to take backup.

Taking full backup
# innobackupex --no-version-check --user=$USER --password=$PASSWORD --tmpdir=/home/mysqltmp --slave-info /mnt/Path/db_back/Server_Name/full
-- Completed OK

Preparing full backup
# innobackupex --no-version-check --apply-log --redo-only --tmpdir=/home/mysqltmp /mnt/Path/db_back/Server_Name/full/2014-12-29_22-10-40
-- Completed OK

Taking incremental backup
# innobackupex --no-version-check --user=$USER --password=$PASSWORD --tmpdir=/home/mysqltmp --slave-info --incremental --incremental-basedir=/mnt/Path/db_back/Server_Name/full/2014-12-29_22-10-40 /mnt/Path/db_back/Server_Name/incremental
-- Completed OK

Preparing incremental backup

# innobackupex --no-version-check --apply-log --tmpdir=/home/mysqltmp --incremental-dir=/mnt/Path/db_back/Server_Name/incremental/2014-12-31_05-30-02 /mnt/Path/db_back/Server_Name/full/2014-12-29_22-10-40

InnoDB: Doing recovery: scanned up to log sequence number 19059978766316 (100%)
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 36794...

[Sergei Glushchenko (sergei.glushchenko)]

Interesting part from stack trace at the moment of crash:

Thread 8 (Thread 0x41e02940 (LWP 3699)):
#0 0x00000036aac0e438 in pread64 () from /lib64/libpthread.so.0
#1 0x0000000000636f15 in os_file_io(int, void*, unsigned long, long, unsigned long) ()
#2 0x00000000006373cc in os_file_pread(int, void*, unsigned long, unsigned long) ()
#3 0x0000000000637570 in os_file_read_func(int, void*, unsigned long, unsigned long) ()
#4 0x0000000000638000 in os_aio_func(unsigned long, unsigned long, char const*, int, void*, unsigned long, unsigned long, fil_node_t*, void*) ()
#5 0x00000000006e4ae9 in fil_io(unsigned long, bool, unsigned long, unsigned long, unsigned long, unsigned long, unsigned long, void*, void*) ()
#6 0x00000000007699bd in buf_read_page_low(dberr_t*, bool, unsigned long, unsigned long, unsigned long, unsigned long, long, unsigned long) ()
#7 0x0000000000769d08 in buf_read_page(unsigned long, unsigned long, unsigned long) ()
#8 0x000000000065f722 in buf_page_get_gen(unsigned long, unsigned long, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*) ()
#9 0x00000000007791e5 in btr_block_get_func ()
#10 0x00000000007794b4 in btr_cur_latch_leaves(unsigned char*, unsigned long, unsigned long, unsigned long, unsigned long, btr_cur_t*, mtr_t*) ()
#11 0x0000000000781186 in btr_cur_search_to_nth_level(dict_index_t*, unsigned long, dtuple_t const*, unsigned long, unsigned long, btr_cur_t*, unsigned long, char const*, unsigned long, mtr_t*) ()
#12 0x0000000000714858 in btr_pcur_open_with_no_init_func(dict_index_t*, dtuple_t const*, unsigned long, unsigned long, btr_pcur_t*, unsigned long, char const*, unsigned long, mtr_t*) ()
#13 0x0000000000715960 in btr_pcur_restore_position_func(unsigned long, btr_pcur_t*, char const*, unsigned long, mtr_t*) ()
#14 0x000000000072ff5a in ibuf_restore_pos(unsigned long, unsigned long, dtuple_t const*, unsigned long, btr_pcur_t*, mtr_t*) ()
#15 0x0000000000730558 in ibuf_delete_rec(unsigned long, unsigned long, btr_pcur_t*, dtuple_t const*, mtr_t*) ()
#16 0x00000000007358f4 in ibuf_merge_or_delete_for_page(buf_block_t*, unsigned long, unsigned long, unsigned long, unsigned long) ()
#17 0x00000000006618ed in buf_page_io_complete(buf_page_t*) ()
#18 0x00000000006e2e14 in fil_aio_wait(unsigned long) ()
#19 0x000000000079703a in io_handler_thread ()
#20 0x00000036aac0673d in start_thread () from /lib64/libpthread.so.0
#21 0x00000036aa0d44bd in clone () from /lib64/libc.so.6

Here we see that there is an ibuf merge is in progress caused by pending IO operation. I believe that page_cleaner thread should not exit until number of pending IOs comes down to zero.

[Sergei Glushchenko (sergei.glushchenko)]

Fix for originally reported assertion pushed to 2.2 branch https://github.com/percona/percona-xtrabackup/pull/19

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-700