mylvmbackup-discuss team mailing list archive

[Lenz Grimmer <lenz@xxxxxxxxxxx>]

Hi,

On 09/03/10 14:28, Yves Goergen wrote:

> today I've noticed that the InnoDB recovery doesn't work at all. MySQL
> is started and prints out some errors about invalid arguments, and the
> error log says that it has no permission to read the data files,
> whereever they may be.

Thanks for reporting this!

> Here's my call:
> 
> sudo PASSWORD=rootpass mylvmbackup --vgname=apollo3 --lvname=root
> --backuptype=none --extra_flush_tables --relpath=var/lib/mysql
> --innodb_recover --keep_mount --lvsize=1G --skip_hooks
> 
> I'm on Ubuntu 10.4 with the standard MySQL package.
> 
> Hostname and volume group name: apollo3
> Logical volume name: root, mounted at /
> MySQL data dir: /var/lib/mysql
> 
> Here's the output from the command:
> 
>> 20100901 17:20:27 Info: Connecting to database...
>> 20100901 17:20:27 Info: Flushing tables (initial)...
>> 20100901 17:20:27 Info: Flushing tables with read lock...
>> 20100901 17:20:27 Info: Taking position record into /tmp/mylvmbackup-backup-20100901_172027_mysql-Zjcn3z.pos...
>> 20100901 17:20:27 Info: Running: lvcreate -s --size=1G --name=root_snapshot /dev/apollo3/root
>> File descriptor 4 (socket:[72962]) leaked on lvcreate invocation. Parent PID 17228: /usr/bin/perl
>>   Logical volume "root_snapshot" created
>> 20100901 17:20:27 Info: DONE: taking LVM snapshot
>> 20100901 17:20:27 Info: Unlocking tables...
>> 20100901 17:20:27 Info: Disconnecting from database...
>> 20100901 17:20:27 Info: Mounting snapshot...
>> 20100901 17:20:27 Info: Running: mount -o rw /dev/apollo3/root_snapshot /var/cache/mylvmbackup/mnt/backup
>> 20100901 17:20:28 Info: DONE: mount snapshot
>> 20100901 17:20:28 Info: Copying /tmp/mylvmbackup-backup-20100901_172027_mysql-Zjcn3z.pos to /var/cache/mylvmbackup/mnt/backup-pos/backup-20100901_172027_mysql.pos...
>> 20100901 17:20:28 Info: Recovering InnoDB...
>> 20100901 17:20:28 Info: Running: echo 'select 1;' | mysqld_safe --socket=/tmp/mylvmbackup.sock --pid-file=/var/run/mylvmbackup_recoverserver.pid --log-error=/tmp/mylvmbackup_recoverserver.err --datadir=/var/cache/mylvmbackup/mnt/backup/var/lib/mysql --skip-networking --skip-grant --bootstrap --skip-ndbcluster --skip-slave-start
>> 100901 17:20:29 mysqld_safe Can't log to error log and syslog at the same time.  Remove all --log-error configuration options for --syslog to take effect.
>> 100901 17:20:29 mysqld_safe Logging to '/tmp/mylvmbackup_recoverserver.err'.
>> 100901 17:20:29 mysqld_safe Starting mysqld daemon with databases from /var/cache/mylvmbackup/mnt/backup/var/lib/mysql
>> 100901 17:20:29 mysqld_safe mysqld from pid file /var/run/mylvmbackup_recoverserver.pid ended
>> 20100901 17:20:29 Info: DONE: InnoDB recovery on snapshot

Here I would have expected an error, as InnoDB was not actually doing it's
job. I need to take a look at the error handling for this part.

>> 20100901 17:20:29 Info: Copying /etc/mysql/my.cnf to /var/cache/mylvmbackup/mnt/backup-pos/backup-20100901_172027_mysql_my.cnf...
>> 20100901 17:20:29 Info: Backuptype none selected, not doing backup... DONE
>> 20100901 17:20:29 Info: Cleaning up...
>> 20100901 17:20:29 Info: Not removing mount as requested by configuration
>> 20100901 17:20:29 Info: LVM Usage stats:
>> 20100901 17:20:29 Info:   LV            VG      Attr   LSize Origin Snap%  Move Log Copy%  Convert
>> 20100901 17:20:29 Info:   root_snapshot apollo3 swi-ao 1,00g root     0,04                        
>> 20100901 17:20:29 Info: Not removing snapshot as requested by configuration
> 
> (Don't mind the late system time, NTPd doesn't work anymore after the VM
> was suspended.)
> 
> Here's the contents of /tmp/mylvmbackup_recoverserver.err:
> 
>> 100901 17:20:29 mysqld_safe Starting mysqld daemon with databases from /var/cache/mylvmbackup/mnt/backup/var/lib/mysql
>> 100901 17:20:29 [Warning] Can't create test file /var/cache/mylvmbackup/mnt/backup/var/lib/mysql/apollo3.lower-test
>> 100901 17:20:29 [Warning] Can't create test file /var/cache/mylvmbackup/mnt/backup/var/lib/mysql/apollo3.lower-test
>> 100901 17:20:29 [Note] Plugin 'FEDERATED' is disabled.
>> 100901 17:20:29  InnoDB: Operating system error number 13 in a file operation.
>> InnoDB: The error means mysqld does not have the access rights to
>> InnoDB: the directory.
>> InnoDB: File name ./ibdata1
>> InnoDB: File operation call: 'open'.
>> InnoDB: Cannot continue operation.
>> 100901 17:20:29 mysqld_safe mysqld from pid file /var/run/mylvmbackup_recoverserver.pid ended
> 
> Any idea?

Error number 13 is the classic "permission denied". It seems as if the
permissions/ownerships of the files in the snapshot don't agree with the user
ID the recovery instance is using. Can you verify that the "real" MySQL Server
and the recovery instance are using the same user ID? I assume that the
recovery server changes to a different user ID that what is defined for the
main server.

Bye,
	LenZ
-- 
  Lenz Grimmer <lenz@xxxxxxxxxxx> - http://www.lenzg.net/

Attachment: signature.asc
Description: OpenPGP digital signature