Bug #59126 ibbackup crash during incremental backup apply-log phase due to buffer overflow
Submitted: 23 Dec 2010 12:01 Modified: 27 Apr 2011 17:31
Reporter: Victor Kirkebo Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Enterprise Backup Severity:S3 (Non-critical)
Version:3.5.2 OS:Any
Assigned to: Pekka Lampio CPU Architecture:Any

[23 Dec 2010 12:01] Victor Kirkebo
Description:
The apply-log phase of an incremental backup of a database using per-table tablespaces may fail. This may leave the full backup in an inconsistent state.

E.g. mysqlbackup may report:
.
.
.
InnoDB: Renaming tablespace /export/home/tmp/meb/test_results/5.5.8/extra/20101222_204733_MBR_5.5.8/2010-12-22_20-52-43/systest2/tbstr0_eng1.ibd of id 1913,
InnoDB: to /export/home/tmp/meb/test_results/5.5.8/extra/20101222_204733_MBR_5.5.8/2010-12-22_20-52-43/systest2/tbstr0_eng1.ibd_ibbackup_old_vers_<timestamp>
InnoDB: because space /export/home/tmp/meb/test_results/5.5.8/extra/20101222_204733_MBR_5.5.8/2010-12-22_20-52-43/systest2/#sql-5886_a82.ibd with the same id
InnoDB: was scanned earlier. This can happen if you have renamed tables
InnoDB: during an ibbackup run.
mysqlbackup: Error: mysqlbackup "apply-log" failed

The error happened because ibbackup crashed due to a buffer overflow when handling the renaming of the tablespace mentioned above.

How to repeat:
Run apply-log on an incremental backup of a database using per-table tablespaces. The incremental backup must run while there are concurrent ALTER TABLE statements running against the database.
However, I have only seen this crash once out of hundreds of backups taken. (Hence reading the source code is a better way of verifying that a buffer overflow is happening). An clear indication that something is wrong can also be seen when looking at the actual names of the renamed files in the full backup directory. E.g:
#sql-5886_b70.ibd_ibbackup_old_vers__101222_21_21_30
#sql-5886_b7b.ibd_ibbackup_old_vers_0101222_21_21_30
#sql-5886_b8a.ibd_ibbackup_old_vers_

The three file names above all should have ended with "_ibbackup_old_vers_101222_21_21_30". i.e. only one underscore after "_ibbackup_old_vers". Apparently the date and time portion of the filename ("101222_21_21_30") has erroneously been offset by one character position.
[27 Dec 2010 8:48] Victor Kirkebo
If the uninitialized character between _ibbackup_old_vers_ and <timestamp> happens to be a path separator (/) then the apply-log phase of an incremental backup of a database using per-table tablespaces can also fail with this error message when trying to rename a file:
InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.

It is not possible from the error message to see that it is the new filename that is the cause of the failure. Rather, the error message from the 'rename' operation suggests that the error is caused by the non-existence of the file to be renamed. However, 'rename' is actually failing because the new filename now contains an unexpected path separator and hence contains a path component that does not exist. This will cause error number 2 (ENOENT) in the 'rename' operation.

E.g.:
------
.
.
InnoDB: Renaming tablespace /export/home/tmp/meb/test_results/5.5.8/extra/20101221_113148_MBR_5.5.8/2010-12-21_11-36-56/systest2/tbstr1_eng2.ibd of id 1368,
InnoDB: to /export/home/tmp/meb/test_results/5.5.8/extra/20101221_113148_MBR_5.5.8/2010-12-21_11-36-56/systest2/tbstr1_eng2.ibd_ibbackup_old_vers_<timestamp>
InnoDB: because space /export/home/tmp/meb/test_results/5.5.8/extra/20101221_113148_MBR_5.5.8/2010-12-21_11-36-56/systest2/#sql-510c_773.ibd with the same id
InnoDB: was scanned earlier. This can happen if you have renamed tables
InnoDB: during an ibbackup run.
101221 11:55:37  InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: File name /export/home/tmp/meb/test_results/5.5.8/extra/20101221_113148_MBR_5.5.8/2010-12-21_11-36-56/systest2/tbstr1_eng2.ibd
InnoDB: File operation call: 'rename'.
101221 11:55:37  InnoDB: Assertion failure in file innodb/fil/fil0fil.c line 3337
InnoDB: Failing assertion: os_file_rename(filepath, new_path)
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.
mysqlbackup: Error: mysqlbackup "apply-log" failed
[27 Apr 2011 17:31] John Russell
Added to 3.5.3 changelog:

When an incremental backup was taken of a database using per-table tablespaces, while ALTER TABLE statements were running, the apply-log phase could fail, leaving the full backup in an inconsistent state.