snapshot creation failure race "in use: not deactivating"

[Kees Cook]

Binary package hint: lvm2

This is the same as bug 84672, but happens much more rarely since the prior bug was fixed:

  LV systemvg/dapper-7607be5d-0b2f-4b41-8ec0-94fca9b4a47d in use: not deactivating
  Couldn't deactivate new snapshot.

I've tried to reproduce the issue, but it is proving difficult. It happens randomly, and doesn't seem to be related to IO load. I will attach a test script I have been using to spark the problem. While I have had it happen, it's not clear how to repeat it. Try with differing LV sizes...

[Kees Cook (kees)]

Here is an example of the attached test script hitting the bug:

# ./snapshot-collision.sh systemvg 4 1 4G 2G
Attempting to empty disk caches ...
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB) copied, 8.92084 seconds, 120 MB/s
Creating test LVs ...
  Logical volume "poc1" created
  Logical volume "poc2" created
  Logical volume "poc3" created
  Logical volume "poc4" created
Creating snapshots ...
  LV systemvg/poc2-1 in use: not deactivating
  Couldn't deactivate new snapshot.
  LV systemvg/poc3-1 in use: not deactivating
  Couldn't deactivate new snapshot.
  Logical volume "poc1-1" created
  LV systemvg/poc4-1 in use: not deactivating
  Couldn't deactivate new snapshot.
Done
Deleting snapshots ...
umount: /mnt/poc3-1: not mounted
umount: /mnt/poc2-1: not mounted
umount: /mnt/poc4-1: not mounted
  Logical volume "poc1-1" successfully removed
Deleteing test LVs ...
  Logical volume "poc1" successfully removed
  Logical volume "poc2" successfully removed
  Logical volume "poc3" successfully removed
  Logical volume "poc4" successfully removed

[Craig Box (craig.box)]

I had a couple of snaphots on a machine, which I rebooted, and I had to remove before I could mount the underlying LV.

Now, I can't create new ones, with the same error as in this bug.

[Craig Box (craig.box)]

Although after a few minutes wait, now I can!

(I am very sorry that my bug reports for LVM are so irrational. :-)

[Craig Box (craig.box)]

Same problem is reoccuring - when lvcreate has run, the volume is created, but not marked as a snapshot volume.

  LV VG Attr LSize Origin Snap% Move Log Copy%
  2007.04.30-19.00.00 mlc2 swi-ao 3.91G storage 10.32
  2007.05.01-00.00.00 mlc2 -wi-a- 3.42G
  2007.05.01-19.00.00 mlc2 -wi-a- 2.93G
  2007.05.02-00.00.00 mlc2 -wi-a- 2.44G
  2007.05.02-19.00.00 mlc2 swi-ao 1.95G storage 16.72
  2007.05.03-00.00.00 mlc2 -wi-a- 1.46G
  2007.05.03-19.00.00 mlc2 -wi-a- 1000.00M
  2007.05.04-00.00.00 mlc2 -wi-a- 500.00M

All of these should have status 's' and be marked as having 'storage' as their origin, but this isn't happening. All of them were created with the same command line:

lvcreate -L500M -s -n $SNAPNAME /dev/VG/LV

[Craig Box (craig.box)]

Debug output:
root@mlc2:/etc/udev# lvcreate -L500M -s -n test /dev/mlc2/storage -v
    Setting chunksize to 16 sectors.
    Finding volume group "mlc2"
    Archiving volume group "mlc2" metadata (seqno 261).
    Creating logical volume test
    Creating volume group backup "/etc/lvm/backup/mlc2" (seqno 262).
    Found volume group "mlc2"
    Creating mlc2-test
    Loading mlc2-test table
    Resuming mlc2-test (254:4)
    Clearing start of logical volume "test"
    Found volume group "mlc2"
  LV mlc2/test in use: not deactivating
  Couldn't deactivate new snapshot.

[Alex Muntada (alex.muntada)]

I'm confirming this issue in Feisty's xen kernel 2.6.19-4-server:

# ./snapshot-collision.sh xen 4 1 4G 512M
Attempting to empty disk caches ...
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB) copied, 6.87661 seconds, 156 MB/s
Creating test LVs ...
  Logical volume "poc1" created
  Logical volume "poc2" created
  Logical volume "poc3" created
  Logical volume "poc4" created
Creating snapshots ...
  LV xen/poc1-1 in use: not deactivating
  Couldn't deactivate new snapshot.
  Logical volume "poc3-1" created
  LV xen/poc2-1 in use: not deactivating
  Couldn't deactivate new snapshot.
  Logical volume "poc4-1" created
Done
Deleting snapshots ...
umount: /mnt/poc1-1: not found
umount: /mnt/poc2-1: not found
  Logical volume "poc1-1" successfully removed
  Logical volume "poc2-1" successfully removed
  Logical volume "poc4-1" successfully removed
  Logical volume "poc3-1" successfully removed
Deleteing test LVs ...
  Logical volume "poc1" successfully removed
  Logical volume "poc2" successfully removed
  Logical volume "poc3" successfully removed
  Logical volume "poc4" successfully removed

[Alex Muntada (alex.muntada)]

Usually after performing a lvremove and retrying lvcreate again works.

BTW, Kees, were you using a xen kernel too?

[Kees Cook (kees)]

Yeah, there is a race condition with the udev helper tools and the lvm tools while the support devices are being created/removed. I was using a stock Feisty kernel, non-Xen. (And this is still present in Gutsy too).

[Joe Kislo (joe-k12s)]

I can confirm this happens on feisty AMD64.

Linux db-1-snapshot 2.6.20-16-server #2 SMP Wed May 23 00:36:09 UTC 2007 x86_64 GNU/Linux

db-1-snapshot - error creating snapshot lvcreate: Setting chunksize to 16 sectors.
    Finding volume group "vg_san_mysql"
    Archiving volume group "vg_san_mysql" metadata (seqno 132).
    Creating logical volume 28517.1181234430.905286
    Creating volume group backup "/etc/lvm/backup/vg_san_mysql" (seqno 133).
    Found volume group "vg_san_mysql"
    Creating vg_san_mysql-28517.1181234430.905286
    Loading vg_san_mysql-28517.1181234430.905286 table
    Resuming vg_san_mysql-28517.1181234430.905286 (254:13)
    Clearing start of logical volume "28517.1181234430.905286"
    Found volume group "vg_san_mysql"
  LV vg_san_mysql/28517.1181234430.905286 in use: not deactivating
  Couldn't deactivate new snapshot.

This is a fairly serious issue for us, since it happens 4-5 times a day. These snapshots are created programmatically as part of a script... so when the snapshot creation fails... it's not like I can just re-run the snapshot create.

I can be on IRC to help anybody debug this issue. Just let me know when to be online. I am in the US/Eastern timezone.

[Alex Muntada (alex.muntada)]

@Joe Kislo:

lvcreate reports an error in $? when snapshot fails, but just retrying won't work since you'll need to remove the bad LV first because it is actually created.
However, you can check it out in your scripts by looking at lvdisplay flags for that LV (e.g. see the attachment included).

HTH

[Kees Cook (kees)]

Updated test harness to use a more reliable cache-clearing mechanism (thanks shawarma!)

[Kees Cook (kees)]

Since the udevmapper changes from Feisty were reverted, I have not seen this bug any more. Does anyone else still see it?

[Craig Box (craig.box)]

Is this fix going to be backportable to Feisty?

[Martin Pitt (pitti)]

moving to tribe-3 as agreed on yesterday's meeting

[Martin Pitt (pitti)]

Does not look like it is getting fixed in tijme for tribe-3, moving.

[Darik Horn (dajhorn)]

I've got a computer that always expresses this bug, perhaps because the filesystem is XFS. Let me know if I can help test a fix.

[Darik Horn (dajhorn)]

My comment about XFS was mistaken. The glitch can be reliably reproduced only because I am trying to create very large snapshots. I'm getting the same race condition with small snapshots.

[Joe Kislo (joe-k12s)]

So I've been struggling with LVM snapshot issues for atleast a year or so (in some form or another)

I'm not sure if the kernel engineers working on this issue have nailed down the precise cause, but I have made some observations over the past week that may help.

1) The issue is has a definite positive correlation with disk activity
 I am snapshotting a database partition. If I try to snapshot the partition while there is database activity, I can almost never get a snapshot off (I've gotten up to 10 snapshot failures in a row). If I suspend the database, which eliminates *most* of the disk activity, I can almost always get a snapshot off

2) Starting in Feisty, I get corrupted snapshots
 Snapshots were working so poorly for me, I started booting the Edgy kernel on my feisty system. This solved almost all of my problems (except for the very very occasional snapshot creation failure). Ubuntu dropped a few new updates to the feisty kernel, so I decided I would give it a try in the interests of helping people debug feisty issues. When I use the feisty kernel, some of my snapshots have corrupted data on them. This never (AFAIK) happened with the Edgy kernel. Here is what I am doing:
On the MySQL server I am snapshotting, I issue
flush tables with read lock
then I lvcreate a snapshot of the mysql partition
then I issue unlock tables.

The MySQL session is kept open during the snapshotting, which keeps the lock in place, and the tables closed.

With the edgy kernel, I get database tables that are completely closed and non-corrupt.

With the feisty kernel (2.6.20-16-server), I will sometimes get tables that are 'still open', and sometimes I get corrupted tables.

Now.. I can't find documentation anywhere that describes what creating a snapshot actually does. Does it ask the ext3 filesystem to sync it's buffers before snapshot? Is ext3 supposed to close it journal for the snapshot? Does it flush outstanding write pages sitting in the kernel before the snapshot? I do not know, and I don't know if it's supposed to. (but I sure would be curious)

Barring a bug in MySQL, when the 'flush tables with read lock' command is returned, it's supposed to have completed closing all of it's tables. I would expect when an lvcreate snapshot comes around, those pages (any anything else that's hit the kernel) would be part of that snapshot. They don't always appear to be in feisty. If I put a 'sync' infront of my lvcreate, I haven't been able to get corrupted tables (yet... I haven't tried all that much). If I don't put the sync infront of the lvcreate, I can sometimes get corrupted tables.

So if I *am* supposed to be getting those pages, perhaps there is a race condition when disk activity is present on a partition being snapshotted, and that is part of the core issue here with snapshot creation failures. Especially since I see a very high percentage of snapshot failures when I have activity on the partition.

[Henrik Nilsen Omma (henrik)]

Moving milestone.

[Scott James Remnant (Canonical) (canonical-scott)]

Removing milestone; this is merely a theoretical bug and should not be demonstrable in the field. The only way to replicate it is by gdb'ing the kernel (through vmware) and mucking around -- we keep it open because there is a race here, and that should be fixed

[Alex Muntada (alex.muntada)]

FWIW, I don't know if this bug isn't reproducible in Gutsy (I won't upgrade my servers until Gutsy is released) but it definitely is reproducible in Feisty with Kees' latest test script:

# bash snapshot-collision.sh xen 3 5 512M 256M
Dropping disk caches ...
Creating test LVs ...
  Logical volume "poc1" created
  Logical volume "poc2" created
  Logical volume "poc3" created
Creating snapshots ...
  Logical volume "poc1-1" created
  LV xen/poc1-3 in use: not deactivating
  Couldn't deactivate new snapshot.
mount: you must specify the filesystem type
  Logical volume "poc1-4" created
  Logical volume "poc1-2" created
  Logical volume "poc2-5" created
  Logical volume "poc2-1" created
  Logical volume "poc2-3" created
  Logical volume "poc3-3" created
  Logical volume "poc3-5" created
  Logical volume "poc3-2" created
  Logical volume "poc3-4" created
  LV xen/poc3-1 in use: not deactivating
  Couldn't deactivate new snapshot.
mount: you must specify the filesystem type
  LV xen/poc2-4 in use: not deactivating
  Couldn't deactivate new snapshot.
mount: you must specify the filesystem type
  Logical volume "poc1-5" created
  Logical volume "poc2-2" created
Done
Deleting snapshots ...
umount: /mnt/poc3-1: not mounted
umount: /mnt/poc2-4: not mounted
umount: /mnt/poc1-3: not mounted
  Logical volume "poc1-4" successfully removed
  Logical volume "poc3-1" successfully removed
  Logical volume "poc2-4" successfully removed
  Logical volume "poc1-2" successfully removed
  Logical volume "poc3-4" successfully removed
  Logical volume "poc3-3" successfully removed
  Logical volume "poc2-5" successfully removed
  Logical volume "poc1-3" successfully removed
  Logical volume "poc3-2" successfully removed
  Logical volume "poc3-5" successfully removed
  Logical volume "poc2-3" successfully removed
  Logical volume "poc2-1" successfully removed
  Logical volume "poc1-1" successfully removed
  Logical volume "poc1-5" successfully removed
  Logical volume "poc2-2" successfully removed
Deleteing test LVs ...
  Logical volume "poc1" successfully removed
  Logical volume "poc2" successfully removed
  Logical volume "poc3" successfully removed

[Kees Cook (kees)]

I have not been able to reproduce it on gutsy. As Scott says, it is technically still possible, but it is much much harder to run into on accident now. Feisty's situation is not easily fixed.

[Scott James Remnant (Canonical) (canonical-scott)]

The fix is likely to be invasive, so not eligible for packporting - especially past an LTS release