Bug #57762 errors in ibbackup restore logs
Submitted: 27 Oct 2010 8:47 Modified: 16 Nov 2010 11:18
Reporter: Chris Rattray Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Backup Severity:S3 (Non-critical)
Version:5.1.30 OS:Linux
Assigned to: CPU Architecture:Any

[27 Oct 2010 8:47] Chris Rattray
Description:
There is an ibbackup restore that is taking place that is producing the following in the log files

date
Wed Oct 27 05:32:01 BST 2010
/etc/init.d/mysql stop
Shutting down MySQL...[  OK  ]
date
Wed Oct 27 05:32:04 BST 2010
rm -f /var/lib/mysql/ib_logfile*
rm -f /var/lib/mysql/trace2/*
rm -f /var/lib/mysql/tnac1911/*
rm -f /var/lib/mysql/sp2www/*
rm -f /var/lib/mysql/sp2test/*
rm -f /var/lib/mysql/sp2content/*
cp -f /mysqldumpdir/data/sp2content/*  /var/lib/mysql/sp2content/
/usr/bin/myisamchk -rq /var/lib/mysql/sp2content/*.MYI
- check record delete-chain
- recovering (with sort) MyISAM-table '/var/lib/mysql/sp2content/content.MYI'
Data records: 917
- Fixing index 1
- Fixing index 2

---------

- check record delete-chain
- recovering (with sort) MyISAM-table '/var/lib/mysql/sp2content/content_files.MYI'
Data records: 52
- Fixing index 1

---------

- check record delete-chain
- recovering (with sort) MyISAM-table '/var/lib/mysql/sp2content/countries.MYI'
Data records: 243
- Fixing index 1

---------

- check record delete-chain
- recovering (with sort) MyISAM-table '/var/lib/mysql/sp2content/issues.MYI'
Data records: 20
- Fixing index 1

---------

- check record delete-chain
- recovering (with sort) MyISAM-table '/var/lib/mysql/sp2content/recommenders.MYI'
Data records: 47
- Fixing index 1
cp -f /mysqldumpdir/data/sp2test/*  /var/lib/mysql/sp2test/
cp -f /mysqldumpdir/data/sp2www/*  /var/lib/mysql/sp2www/
cp -f /mysqldumpdir/data/tnac1911/*  /var/lib/mysql/tnac1911/
cp -f /mysqldumpdir/data/trace2/* /var/lib/mysql/trace2/
cp -f /mysqldumpdir/data/ibdata* /var/lib/mysql/
cp -f /mysqldumpdir/data/ibbackup_* /var/lib/mysql/
/usr/local/bin/ibbackup --apply-log /etc/my.cnf
InnoDB Hot Backup version 3.0.0; Copyright 2002-2005 Innobase Oy
License A14421 is granted to brightsolid Ltd (scolligan@brightsolid.com)
(--apply-log works in any computer regardless of the hostname)
Licensed for use in a computer whose hostname is 'coa-dun-db1'
Expires 2009-2-1 (year-month-day) at 00:00
See http://www.innodb.com for further information
Type ibbackup --license for detailed license terms, --help for help

Contents of /etc/my.cnf:
101027  6:36:22  InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: File name /var/lib/mysql/mysql.sock
InnoDB: File operation call: 'stat'.
innodb_data_home_dir got value /var/lib/mysql
innodb_data_file_path got value ibdata1:64M:autoextend
datadir got value /var/lib/mysql
innodb_log_group_home_dir got value /var/lib/mysql
innodb_log_files_in_group got value 2
innodb_log_file_size got value 67108864

101027  6:36:22  InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: File name /var/lib/mysql/mysql.sock
InnoDB: File operation call: 'stat'.
InnoDB: Error: os_file_readdir_next_file() returned -1 in
InnoDB: directory /var/lib/mysql
InnoDB: Crash recovery may have failed for some .ibd files!
101027  6:36:22  ibbackup: ibbackup_logfile's creation parameters:
ibbackup: start lsn 213 3361248256, end lsn 213 3366478689,
ibbackup: start checkpoint 213 3361248679
InnoDB: Doing recovery: scanned up to log sequence number 213 3366478689
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 Setting log file size to 0 67108864
Setting log file size to 0 67108864
ibbackup: We were able to parse ibbackup_logfile up to
ibbackup: lsn 213 3366478689
ibbackup: Last MySQL binlog file position 0 47959306, file name ./mysql-bin.000001
ibbackup: The first data file is '/var/lib/mysql/ibdata1'
ibbackup: and the new created log files are at '/var/lib/mysql/'
101027  6:37:02  ibbackup: Full backup prepared for recovery successfully!
chown -R mysql /var/lib/mysql/
chgrp -R mysql /var/lib/mysql/
date
Wed Oct 27 06:37:02 BST 2010
/etc/init.d/mysql start
Starting MySQL...[  OK  ]
date
Wed Oct 27 06:37:05 BST 2010

######################

/var/lib/mysql/mysql.sock is a sym link to /tmp/mysql.sock  Is this anything to worry about and is the restore successful?  I guess the mysql.sock file is deleted when MySQL is shutdown

[root@coa-dun-db3 ~]# ls -l /var/lib/mysql/mysql.sock
lrwxrwxrwx 1 mysql mysql 15 Aug 26 16:26 /var/lib/mysql/mysql.sock -> /tmp/mysql.sock

Thanks

How to repeat:
script is

/etc/init.d/mysql stop
date
rm -f /var/lib/mysql/ib_logfile*
rm -f /var/lib/mysql/trace2/*
rm -f /var/lib/mysql/tnac1911/*
rm -f /var/lib/mysql/sp2www/*
rm -f /var/lib/mysql/sp2test/*
rm -f /var/lib/mysql/sp2content/*
cp -f /mysqldumpdir/data/sp2content/*  /var/lib/mysql/sp2content/
/usr/bin/myisamchk -rq /var/lib/mysql/sp2content/*.MYI
cp -f /mysqldumpdir/data/sp2test/*  /var/lib/mysql/sp2test/
cp -f /mysqldumpdir/data/sp2www/*  /var/lib/mysql/sp2www/
cp -f /mysqldumpdir/data/tnac1911/*  /var/lib/mysql/tnac1911/
cp -f /mysqldumpdir/data/trace2/* /var/lib/mysql/trace2/
cp -f /mysqldumpdir/data/ibdata* /var/lib/mysql/
cp -f /mysqldumpdir/data/ibbackup_* /var/lib/mysql/
/usr/local/bin/ibbackup --apply-log /etc/my.cnf
chown -R mysql /var/lib/mysql/
chgrp -R mysql /var/lib/mysql/
date
/etc/init.d/mysql start
date
[1 Nov 2010 11:51] Chris Rattray
any news on this?

thanks
[4 Nov 2010 10:54] Susanne Ebrecht
What do you think is the bug here?
[4 Nov 2010 16:19] Chris Rattray
sorry, please close, i meant to open a support ticket not a bug

Mat
[16 Nov 2010 11:18] Sveta Smirnova
Closing as not a bug because last comment.