mylvmbackup intermittantly fails to mount backup snapshot

[Scott Frazer]

mylvmbackup will occasionally fail to mount the snapshot it earlier created. Here's the log output:

root@db16a:~/mylvmbackup-0.13# mylvmbackup
20091118 12:56:45 Info: Connecting to database...
20091118 12:56:46 Info: Running hook 'preflush' as perl module.
20091118 12:56:46 Info: Flushing tables (initial)...
20091118 12:56:46 Info: Flushing tables with read lock...
20091118 12:56:46 Info: Taking position record into /tmp/mylvmbackup-backup-20091118_mysql-1BTx1n.pos...
20091118 12:56:46 Info: Running: /sbin/lvcreate -s --size=5G --name=MySQLLV_snapshot /dev/PrimaryVG/MySQLLV
File descriptor 5 left open
  Logical volume "MySQLLV_snapshot" created
20091118 12:56:46 Info: DONE: taking LVM snapshot
20091118 12:56:46 Info: Unlocking tables...
20091118 12:56:46 Info: Disconnecting from database...
20091118 12:56:46 Info: Mounting snapshot...
20091118 12:56:46 Info: Running: /bin/mount -o rw /dev/PrimaryVG/MySQLLV_snapshot /var/cache/mylvmbackup/mnt/backup
mount: you must specify the filesystem type
20091118 12:56:46 Error: FAILED: mount snapshot (exit status 32)
20091118 12:56:46 Info: Running hook 'logerr' as perl module.
20091118 12:56:46 Info: Copying /tmp/mylvmbackup-backup-20091118_mysql-1BTx1n.pos to /var/cache/mylvmbackup/mnt/backup-pos/backup-20091118_mysql.pos...
20091118 12:56:46 Info: Cleaning up...
20091118 12:56:46 Info: LVM Usage stats:
20091118 12:56:46 Info: LV VG Attr LSize Origin Snap% Move Log Copy%
20091118 12:56:46 Info: MySQLLV_snapshot PrimaryVG swi-a- 5.00G MySQLLV 0.00
20091118 12:56:46 Info: Running: /sbin/lvremove -f /dev/PrimaryVG/MySQLLV_snapshot
  Logical volume "MySQLLV_snapshot" successfully removed
20091118 12:56:46 Info: DONE: Removing snapshot
root@db16a:~/mylvmbackup-0.13# mylvmbackup
20091118 12:56:57 Info: Connecting to database...
20091118 12:56:57 Info: Running hook 'preflush' as perl module.
20091118 12:56:57 Info: Flushing tables (initial)...
20091118 12:56:57 Info: Flushing tables with read lock...
20091118 12:56:57 Info: Taking position record into /tmp/mylvmbackup-backup-20091118_mysql-akcyZC.pos...
20091118 12:56:57 Info: Running: /sbin/lvcreate -s --size=5G --name=MySQLLV_snapshot /dev/PrimaryVG/MySQLLV
File descriptor 5 left open
  Logical volume "MySQLLV_snapshot" created
20091118 12:56:57 Info: DONE: taking LVM snapshot
20091118 12:56:57 Info: Unlocking tables...
20091118 12:56:57 Info: Disconnecting from database...
20091118 12:56:57 Info: Mounting snapshot...
20091118 12:56:57 Info: Running: /bin/mount -o rw /dev/PrimaryVG/MySQLLV_snapshot /var/cache/mylvmbackup/mnt/backup
20091118 12:56:57 Info: DONE: mount snapshot
20091118 12:56:57 Info: Copying /tmp/mylvmbackup-backup-20091118_mysql-akcyZC.pos to /var/cache/mylvmbackup/mnt/backup-pos/backup-20091118_mysql.pos...
20091118 12:56:57 Info: Copying /etc/mysql/my.cnf to /var/cache/mylvmbackup/mnt/backup-pos/backup-20091118_mysql_my.cnf...
20091118 12:56:57 Info: Taking actual backup...
20091118 12:56:57 Info: Creating tar archive /var/cache/mylvmbackup/backup/backup-20091118_mysql.tar.gz
20091118 12:56:57 Info: Running: cd '/var/cache/mylvmbackup/mnt' ;'/bin/tar' cvzf - backup/ backup-pos/backup-20091118_mysql.pos backup-pos/backup-20091118_mysql_my.cnf| gzip --stdout --verbose --best -> /var/cache/mylvmbackup/backup/backup-20091118_mysql.tar.gz.INCOMPLETE-kPY5Wv6

File system type on this server is ext3.

Here's the conf file:

#
# mylvmbackup configuration file
#
# Every line beginning with a pound sign (#) will be treated as a comment.
#
# Please refer to the mylvmbackup(1) manual page for more information

#
# These values define how mylvmbackup should connect to the local MySQL server
#
[mysql]
user=root
password=secret
host=localhost
port=3306
socket=
mycnf=/etc/mysql/my.cnf

#
# LVM-specific options
#
[lvm]
vgname=PrimaryVG
lvname=MySQLLV
backuplv=
lvsize=5G

#
# File system specific options
#
[fs]
xfs=0
mountdir=/var/cache/mylvmbackup/mnt/
backupdir=/var/cache/mylvmbackup/backup/
relpath=

#
# Full path names of required external utilities
#
[tools]
lvcreate=/sbin/lvcreate
lvremove=/sbin/lvremove
mount=/bin/mount
tar=/bin/tar
rsync=/usr/bin/rsync
umount=/bin/umount

#
# Other configuration options
#
[misc]
backuptype=tar
prefix=backup
tararg=cvzf
tarsuffixarg=
rsyncarg=-avWP
datefmt=%Y%m%d
innodb_recover=0
pidfile=/var/tmp/mylvmbackup_recoverserver.pid
skip_flush_tables=0
extra_flush_tables=1

#
# Logging options. The Sys::Syslog module is required for syslog option
#
[logging]
# 'console' (STDOUT, STDERR) or 'syslog' or 'both'.
log_method=both
# 'native', 'tcp', 'udp'. Default is 'native'
syslog_socktype=native
syslog_facility=
# If using remote syslog, don't forget to specify the socket type to tcp or udp.
syslog_remotehost=

[Lenz Grimmer (lenzgr)]

Sorry for the late reply. This happened to me during my testing once so far - it's pretty hard to reproduce it. What operating system is this? Which Kernel version? I wonder if there's a bug in the LVM code that triggers this...

[Scott Frazer (sfrazer-duoconsulting)]

It happens for me on various versions of Ubuntu ranging from 8.04 to 9.10

I haven't done much more research on this recently, though.

On Tue, Jan 26, 2010 at 5:29 AM, LenZ <email address hidden> wrote:
> Sorry for the late reply. This happened to me during my testing once so
> far - it's pretty hard to reproduce it. What operating system is this?
> Which Kernel version? I wonder if there's a bug in the LVM code that
> triggers this...
>
> ** Changed in: mylvmbackup
>     Assignee: (unassigned) => LenZ (lenzgr)
>
> ** Changed in: mylvmbackup
>   Importance: Undecided => Medium
>
> ** Changed in: mylvmbackup
>       Status: New => Incomplete
>
> --
> mylvmbackup intermittantly fails to mount backup snapshot
> https://bugs.launchpad.net/bugs/484961
> You received this bug notification because you are a direct subscriber
> of the bug.
>
> Status in mylvmbackup - A tool for quickly creating backups of a MySQL server's data files: Incomplete
>
> Bug description:
> mylvmbackup will occasionally fail to mount the snapshot it earlier created. Here's the log output:
>
> root@db16a:~/mylvmbackup-0.13# mylvmbackup
> 20091118 12:56:45 Info: Connecting to database...
> 20091118 12:56:46 Info: Running hook 'preflush' as perl module.
> 20091118 12:56:46 Info: Flushing tables (initial)...
> 20091118 12:56:46 Info: Flushing tables with read lock...
> 20091118 12:56:46 Info: Taking position record into /tmp/mylvmbackup-backup-20091118_mysql-1BTx1n.pos...
> 20091118 12:56:46 Info: Running: /sbin/lvcreate -s --size=5G --name=MySQLLV_snapshot /dev/PrimaryVG/MySQLLV
> File descriptor 5 left open
>  Logical volume "MySQLLV_snapshot" created
> 20091118 12:56:46 Info: DONE: taking LVM snapshot
> 20091118 12:56:46 Info: Unlocking tables...
> 20091118 12:56:46 Info: Disconnecting from database...
> 20091118 12:56:46 Info: Mounting snapshot...
> 20091118 12:56:46 Info: Running: /bin/mount -o rw /dev/PrimaryVG/MySQLLV_snapshot /var/cache/mylvmbackup/mnt/backup
> mount: you must specify the filesystem type
> 20091118 12:56:46 Error: FAILED: mount snapshot (exit status 32)
> 20091118 12:56:46 Info: Running hook 'logerr' as perl module.
> 20091118 12:56:46 Info: Copying /tmp/mylvmbackup-backup-20091118_mysql-1BTx1n.pos to /var/cache/mylvmbackup/mnt/backup-pos/backup-20091118_mysql.pos...
> 20091118 12:56:46 Info: Cleaning up...
> 20091118 12:56:46 Info: LVM Usage stats:
> 20091118 12:56:46 Info:   LV               VG        Attr   LSize Origin  Snap%  Move Log Copy%
> 20091118 12:56:46 Info:   MySQLLV_snapshot PrimaryVG swi-a- 5.00G MySQLLV   0.00
> 20091118 12:56:46 Info: Running: /sbin/lvremove -f /dev/PrimaryVG/MySQLLV_snapshot
>  Logical volume "MySQLLV_snapshot" successfully removed
> 20091118 12:56:46 Info: DONE: Removing snapshot
> root@db16a:~/mylvmbackup-0.13# mylvmbackup
> 20091118 12:56:57 Info: Connecting to database...
> 20091118 12:56:57 Info: Running hook 'preflush' as perl module.
> 20091118 12:56:57 Info: Flushing tables (initial)...
> 20091118 12:56:57 Info: Flushing tables with read lock...
> 20091118 12:56:57 Info: Taking position record into /tmp/mylvmbackup-backup-20091118_mysql-akcyZC.pos...
> 20091118 12:56:57 Info: Running: /sbin/lvcreate -s --size=5G ...

[Kjetil Torgrim Homme (kjetilho)]

I see the same problem intermittently on Debian 5.0 (Lenny). The kernel is 2.6.18-4-amd64.

[Kjetil Torgrim Homme (kjetilho)]

See also bug #105936, it seems sort of relevant, although in theory it should be obsolete. It suggests a workaround of doing sync after lvcreate.

I used the test script from there, and it triggers the bug, although not consistently.

# bash /tmp/snapshot-collision.sh myvg 1 10 12M 4M
Dropping disk caches ...
Creating test LVs ...
  Logical volume "poc1" created
Creating snapshots ...
  Logical volume "poc1-1" created
mount: you must specify the filesystem type
  Logical volume "poc1-7" created
  Logical volume "poc1-2" created
  Logical volume "poc1-5" created
[...]

This only happened once, and most other times I only got it to fail with

   device-mapper: reload ioctl failed: Cannot allocate memory
   Failed to suspend origin poc1
 mount: you must specify the filesystem type

This is running on a VM with 4 GiB RAM, 3.5 GiB free. Should be enough to avoid memory allocation errors.

[Kjetil Torgrim Homme (kjetilho)]

Same issue crops up on Hardy, kernel 2.6.24-23-xen

It seems like putting a sync command in
/usr/share/mylvmbackup/premount solves the problem, but since it is intermittent, who knows?

[Pieter Ennes (skion)]

The sync in the premount file seems tpo help here too, thanks...

Debian lenny: Linux jul 2.6.26-2-amd64 #1 SMP Thu Nov 5 02:23:12 UTC 2009 x86_64 GNU/Linux
mylvmbackup: 0.13

[myriapod (s-myriapod)]

Same issue on Ubuntu Hardy 8.04.4 LTS.
It's quite frequent and the sync on premount does *not* solve the problem.
I'm trying to do an lvmdump on premount to collect some more debug info.

[Puneet (puneet-v)]

I am seeing same issue on Ubuntu 10.04. Has anyone figured out the solution to it yet?

Thanks.

[Lenz Grimmer (lenzgr)]

This does not seem to be a bug in mylvmbackup per se, but rather some kind of race condition in the LVM kernel code. What file systems is this happening on? The original reported mentioned he's seeing it with ext3, can anyone confirm? Also, does the problem disappear if the file system type is explicitly mentioned in the mount options?