Breaking^WExploring LVM Snapshots Part 2

Author:Jeff Propes
Date:Aug 18, 2016
Copyright:© 2016 Jeff Propes. All rights reserved.

In part 1, we walked through how to deploy and use a LVM snapshot. In part 2, we're going to explore what happens if you write more to the snapshot than it has room for.

Table of Contents

Getting Reacquainted

Here's what I'll be doing to the poor thing:

  1. Creating an undersized snapshot of an existing logical volume (hereafter LV).
  2. Writing data to the LV past what the snapshot can accomodate.
  3. Try to recover from any damage caused by the overwrite.

For this experiment, I'm using the same server from part 1 named spacewalk.universe. It is running CentOS 7 and LVM2 with some uncommitted disk space in its volume group. What will the system do? Complain? Reject further writes to the LV? Quietly fail without notice? LET'S FIND OUT!

Target Audience

Similar to part 1, this document is targetted at the intermediate-level Linux sysadmin. You should already be familiar with what LVM is and what it can do. Numerous and sundry docs already exist which can fill in potential knowledge gaps. Neither will I be covering how to operate any of the commands listed here. There are quality man pages for everything and --help usage responses built into all of the LVM binaries.

The Story So Far

I've got a 5GB logical volume called snaptest to play with. It is mounted to /snaptest and has some data already written to it.

[root@spacewalk ~]# lvdisplay /dev/mapper/centos-snaptest
  --- Logical volume ---
  LV Path                /dev/centos/snaptest
  LV Name                snaptest
  VG Name                centos
  LV UUID                mxl7fi-WjPb-dTcs-J3TS-orac-RoJD-tyWLKt
  LV Write Access        read/write
  LV Creation host, time spacewalk.universe, 2016-08-18 14:45:28 -0500
  LV Status              available
  # open                 1
  LV Size                5.00 GiB
  Current LE             1280
  Segments               1
  Allocation             inherit
  Read ahead sectors     auto
  - currently set to     8192
  Block device           253:3
[root@spacewalk ~]# df -h |awk '{if (NR == 1) {print $0}} /snaptest/ {print $0}'
Filesystem                    Size  Used Avail Use% Mounted on
/dev/mapper/centos-snaptest   4.8G  2.1G  2.5G  46% /snaptest

Creating the Snapshot

I'm going to create a small snapshot named snaptest_fill that will be easy to break. Since the parent LV is around 5GB in size, I'll make it about 5% or 250MB.

Hmm, maybe I'll round that down to 200MB so we're not here all day.

[root@spacewalk ~]# lvcreate -L200M -s -n snaptest_fill /dev/mapper/centos-snaptest
  Logical volume "snaptest_fill" created.
[root@spacewalk ~]# mkdir /snaptest_fill
[root@spacewalk ~]# mount /dev/mapper/centos-snaptest_fill /snaptest_fill
[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-aos--- 200.00m      snaptest 0.01
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g

Interesting that it's already showing some disk usage. Something to explore in another post, perhaps?

Snapshot on the Edge

Now it's time to fill the snapshot up by writing to its parent LV. If you don't know or don't remember the mechanics of snapshots, check back in to part 1 and read over section 5's explanation.

We're going to write 190MB of data to take it to the edge:

[root@spacewalk ~]# for i in {1..19}; do dd if=/dev/urandom of=/snaptest/fill${i} bs=1M count=10 >/dev/null 2>&1; echo -n "."; done
...................[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-aos--- 200.00m      snaptest 92.44
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g

Whups, forgot a trailing echo there. As you can see, the snapshot is now dangerously full. There's something funny going on here though, because the math isn't adding up. It should be reporting 95% or more full.

[root@spacewalk ~]# sync
[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-aos--- 200.00m      snaptest 95.47
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g
[root@spacewalk ~]#

... oh. System-level write-buffering to the rescue.

Over the Edge

All right, let's put the pedal to the metal and fill the snapshot.

[root@spacewalk ~]# dd if=/dev/urandom of=/snaptest/overfull1 bs=1M count=20M

Waiting ... waiting longer ... wonder what's taking so long.

[90 seconds go by]

Ok, it should definitely be done by now. Time to kill it and see what's happened.

^C
455+0 records in
454+0 records out
476053504 bytes (476 MB) copied, 39.3667 s, 12.1 MB/s

Huh. Did it block on the write to /snaptest and did not return an error at all? Well, no error was printed to my shell. Let's check the system logs ...

[root@spacewalk ~]# less /var/log/messages
...
Aug 18 16:24:50 spacewalk lvm[30082]: Monitoring snapshot centos-snaptest_fill
...
Aug 18 16:28:00 spacewalk lvm[30082]: Snapshot centos-snaptest_fill is now 92% full.
...
Aug 18 16:28:30 spacewalk lvm[30082]: Snapshot centos-snaptest_fill is now 95% full.
...
Aug 18 16:31:17 spacewalk kernel: device-mapper: snapshots: Invalidating snapshot: Unable to allocate exception.
Aug 18 16:31:17 spacewalk lvm[30082]: Unmounting invalid snapshot centos-snaptest_fill from /snaptest_fill.
Aug 18 16:31:17 spacewalk kernel: Buffer I/O error on device dm-6, logical block 557056
Aug 18 16:31:17 spacewalk kernel: lost page write due to I/O error on dm-6
Aug 18 16:31:17 spacewalk kernel: JBD2: Error -5 detected when updating journal superblock for dm-6-8.
Aug 18 16:31:17 spacewalk kernel: Buffer I/O error on device dm-6, logical block 557056
Aug 18 16:31:17 spacewalk kernel: lost page write due to I/O error on dm-6
Aug 18 16:31:17 spacewalk kernel: JBD2: Error -5 detected when updating journal superblock for dm-6-8.
Aug 18 16:31:17 spacewalk kernel: Buffer I/O error on device dm-6, logical block 0
Aug 18 16:31:17 spacewalk kernel: lost page write due to I/O error on dm-6
Aug 18 16:31:17 spacewalk kernel: ------------[ cut here ]------------
Aug 18 16:31:17 spacewalk kernel: WARNING: at fs/block_dev.c:67 bdev_inode_switch_bdi+0x7a/0x90()
Aug 18 16:31:17 spacewalk kernel: Modules linked in: dm_snapshot dm_bufio vmw_vsock_vmci_transport vsock ext4 mbcache jbd2 coretemp crc32_pclmul ghash_clmulni_intel aesni_intel lrw gf128mul glue_helper ablk_helper cryptd ppdev vmw_balloon pcspkr sg shpchp i2c_piix4 vmw_vmci parport_pc parport ip_tables xfs libcrc32c sr_mod cdrom sd_mod crc_t10dif crct10dif_generic ata_generic pata_acpi crct10dif_pclmul crct10dif_common crc32c_intel serio_raw vmwgfx drm_kms_helper mptspi ttm vmxnet3 scsi_transport_spi mptscsih mptbase drm ata_piix i2c_core libata dm_mirror dm_region_hash dm_log dm_mod
Aug 18 16:31:17 spacewalk kernel: CPU: 1 PID: 32235 Comm: umount Not tainted 3.10.0-327.28.2.el7.x86_64 #1
Aug 18 16:31:17 spacewalk kernel: Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/21/2015
Aug 18 16:31:17 spacewalk kernel: 0000000000000000 00000000162d1fa6 ffff88000f3c3da0 ffffffff81636553
Aug 18 16:31:17 spacewalk kernel: ffff88000f3c3dd8 ffffffff8107b200 ffff880036d01e30 ffff880036d01eb8
Aug 18 16:31:17 spacewalk kernel: ffffffff819c28c0 0000000000000083 0000000000000000 ffff88000f3c3de8
Aug 18 16:31:17 spacewalk kernel: Call Trace:
Aug 18 16:31:17 spacewalk kernel: [<ffffffff81636553>] dump_stack+0x19/0x1b
Aug 18 16:31:17 spacewalk kernel: [<ffffffff8107b200>] warn_slowpath_common+0x70/0xb0
Aug 18 16:31:17 spacewalk kernel: [<ffffffff8107b34a>] warn_slowpath_null+0x1a/0x20
Aug 18 16:31:17 spacewalk kernel: [<ffffffff81219d2a>] bdev_inode_switch_bdi+0x7a/0x90
Aug 18 16:31:17 spacewalk kernel: [<ffffffff8121a914>] __blkdev_put+0x74/0x1a0
Aug 18 16:31:17 spacewalk kernel: [<ffffffff8121b38e>] blkdev_put+0x4e/0x140
Aug 18 16:31:17 spacewalk kernel: [<ffffffff811e15b4>] kill_block_super+0x44/0x70
Aug 18 16:31:17 spacewalk kernel: [<ffffffff811e18d9>] deactivate_locked_super+0x49/0x60
Aug 18 16:31:17 spacewalk kernel: [<ffffffff811e1ed6>] deactivate_super+0x46/0x60
Aug 18 16:31:17 spacewalk kernel: [<ffffffff811fee35>] mntput_no_expire+0xc5/0x120
Aug 18 16:31:17 spacewalk kernel: [<ffffffff811fff6f>] SyS_umount+0x9f/0x3c0
Aug 18 16:31:17 spacewalk kernel: [<ffffffff81646c49>] system_call_fastpath+0x16/0x1b
Aug 18 16:31:17 spacewalk kernel: ---[ end trace 80a934f9a2fc1615 ]---

Wow, my kernel is very not happy with me. It unmounted the snapshot to avoid causing any more errors.

[root@spacewalk ~]# mount |grep snaptest_fill
[root@spacewalk ~]#

The snapshot still exists, according to LVM2:

[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-I-s--- 200.00m      snaptest 100.00
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g
[root@spacewalk ~]# ls -l /dev/mapper/centos-snaptest*
lrwxrwxrwx. 1 root root 7 Aug 18 16:24 /dev/mapper/centos-snaptest -> ../dm-3
lrwxrwxrwx. 1 root root 7 Aug 18 16:24 /dev/mapper/centos-snaptest_fill -> ../dm-6
lrwxrwxrwx. 1 root root 7 Aug 18 16:24 /dev/mapper/centos-snaptest_fill-cow -> ../dm-5
lrwxrwxrwx. 1 root root 7 Aug 18 16:24 /dev/mapper/centos-snaptest-real -> ../dm-4

I just can't interact with it any longer.

[root@spacewalk ~]# mount /dev/mapper/centos-snaptest_fill /snaptest_fill/
mount: /dev/mapper/centos-snaptest_fill: can't read superblock
[root@spacewalk ~]# tail /var/log/messages
...
Aug 18 16:41:07 spacewalk kernel: Buffer I/O error on device dm-6, logical block 1310704

I wonder though ... do you think we can enlarge it and keep going?

We Have the Technology

So I've no idea if this will work or maybe destroy the system drive on the server. I also forgot to take a VM snapshot before doing any of this. So we're pretty much flying by the seat of our pants here. See, you're judging me again. I can feel it. Stop that.

I'm going to do what I can to recover it by exending the logical volume. I don't expect this to work, since the snapshot isn't a real partition and isn't formatted as one.

[root@spacewalk ~]# lvextend -L+20M /dev/mapper/centos-snaptest_fill
  Size of logical volume centos/snaptest_fill changed from 200.00 MiB (50 extents) to 220.00 MiB (55 extents).
  Logical volume snaptest_fill successfully resized.

... huh. That worked without complaint. Let's try to mount it again!

[root@spacewalk ~]# mount /dev/mapper/centos-snaptest_fill /snaptest_fill
mount: /dev/mapper/centos-snaptest_fill: can't read superblock
[root@spacewalk ~]# tail /var/log/messages
...
Aug 18 16:41:07 spacewalk kernel: Buffer I/O error on device dm-6, logical block 1310704
Aug 18 16:43:07 spacewalk lvm[30082]: No longer monitoring snapshot centos-snaptest_fill
Aug 18 16:43:07 spacewalk kernel: Buffer I/O error on device dm-6, logical block 1310704
Aug 18 16:43:07 spacewalk lvm[30082]: Monitoring snapshot centos-snaptest_fill
Aug 18 16:43:07 spacewalk kernel: sdb: unknown partition table
Aug 18 16:43:22 spacewalk kernel: Buffer I/O error on device dm-6, logical block 1310704

This looks suspiciously like the error before. I wonder if ...

[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-I-s--- 220.00m      snaptest 100.00
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g

So maybe it filled up again, perhaps with more of the data we were trying to write from before. The over-filling dd was 20 minutes ago almost and is on /snaptest already. The system must be buffering the additional writes. Or something.

If All You Have is a Hammer ...

Let's try extending it again.

[root@spacewalk ~]# lvextend -L+100M /dev/mapper/centos-snaptest_fill
  Size of logical volume centos/snaptest_fill changed from 220.00 MiB (55 extents) to 320.00 MiB (80 extents).
  Logical volume snaptest_fill successfully resized.
[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-I-s--- 320.00m      snaptest 100.00
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g
[root@spacewalk ~]# tail /var/log/messages
...
Aug 18 16:50:24 spacewalk lvm[30082]: No longer monitoring snapshot centos-snaptest_fill
Aug 18 16:50:24 spacewalk lvm[30082]: Monitoring snapshot centos-snaptest_fill
Aug 18 16:50:24 spacewalk kernel: Buffer I/O error on device dm-6, logical block 1310704
Aug 18 16:50:24 spacewalk kernel: sdb: unknown partition table

That's not encouraging. Even though I only wrote 50MB in that overfiling dd command earlier. Or did I?

scrollscrollscrollscroll ... ohhhh. I mistyped it and wrote WAY more than 50MB: 476053504 bytes (476 MB) copied. Well, let's try enlarging it past that and see what happens. FOR SCIENCE!

[root@spacewalk ~]# lvextend -L+400M /dev/mapper/centos-snaptest_fill
  Size of logical volume centos/snaptest_fill changed from 320.00 MiB (80 extents) to 720.00 MiB (180 extents).
  Logical volume snaptest_fill successfully resized.
[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-I-s--- 720.00m      snaptest 100.00
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g

Not enough? Again!

[root@spacewalk ~]# lvextend -L+400M /dev/mapper/centos-snaptest_fill
  Size of logical volume centos/snaptest_fill changed from 720.00 MiB (180 extents) to 1.09 GiB (280 extents).
  Logical volume snaptest_fill successfully resized.
[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-I-s---   1.09g      snaptest 100.00
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g

Man, still not enough. That should have eclipsed the extra data we wrote. How big is this thing anyhow?

[root@spacewalk ~]# ddf -h |awk '{if (NR == 1) {print $0}} /snaptest/ {print $0}'
Filesystem                    Size  Used Avail Use% Mounted on
/dev/mapper/centos-snaptest   4.8G  2.1G  2.5G  46% /snaptest
[root@spacewalk ~]# ls -lh /snaptest/overfull1
-rw-r--r--. 1 root root 454M Aug 18 16:31 /snaptest/overfull1
[root@spacewalk ~]# pvs
  /dev/centos/snaptest_fill: read failed after 0 of 4096 at 0: Input/output error
  /dev/centos/snaptest_fill: read failed after 0 of 4096 at 5368643584: Input/output error
  /dev/centos/snaptest_fill: read failed after 0 of 4096 at 5368700928: Input/output error
  /dev/centos/snaptest_fill: read failed after 0 of 4096 at 4096: Input/output error
  PV         VG     Fmt  Attr PSize   PFree
  /dev/sda2  centos lvm2 a--   49.51g 40.00m
  /dev/sdb   centos lvm2 a--  221.00g 16.00g

... ooh. Ok. So, yeah, maybe we should call this a failure and just ditch the snapshot ... after I try ONE MORE TIME I SWEAR THIS IS THE LAST ONE DON'T JUDGE

[root@spacewalk ~]# lvextend -L+2.5G /dev/mapper/centos-snaptest_fill
  Size of logical volume centos/snaptest_fill changed from 1.09 GiB (280 extents) to 3.59 GiB (920 extents).
  Logical volume snaptest_fill successfully resized.
[root@spacewalk ~]# lvs
  LV            VG     Attr       LSize   Pool Origin   Data%  Meta%  Move Log Cpy%Sync Convert
  root          centos -wi-ao----  44.47g
  snaptest      centos owi-aos---   5.00g
  snaptest_fill centos swi-I-s---   3.59g      snaptest 100.00
  spacewalk     centos -wi-ao---- 198.90g
  swap          centos -wi-ao----   5.00g
[root@spacewalk ~]# mount /dev/mapper/centos-snaptest_fill /snaptest_fill
mount: /dev/mapper/centos-snaptest_fill: can't read superblock
[root@spacewalk ~]# tail /var/log/messages
...
Aug 18 17:02:50 spacewalk kernel: Buffer I/O error on device dm-6, logical block 1310704

All right, it's clear the snapshot is beyond recovery.

Throwing In the Towel

It's time to deep-6 our ill-fated snapshot and see if my system is still ok afterwards.

[root@spacewalk ~]# mount |grep snaptest
/dev/mapper/centos-snaptest on /snaptest type ext4 (rw,relatime,seclabel,data=ordered)
[root@spacewalk ~]# lvremove /dev/mapper/centos-snaptest_fill
Do you really want to remove active logical volume snaptest_fill? [y/n]: y
  Logical volume "snaptest_fill" successfully removed
[root@spacewalk ~]# tail /var/log/messages
...
Aug 18 17:04:37 spacewalk lvm[30082]: No longer monitoring snapshot centos-snaptest_fill
Aug 18 17:04:37 spacewalk kernel: sdb: unknown partition table
[root@spacewalk ~]# lvs
  LV        VG     Attr       LSize   Pool Origin Data%  Meta%  Move Log Cpy%Sync Convert
  root      centos -wi-ao----  44.47g
  snaptest  centos -wi-ao----   5.00g
  spacewalk centos -wi-ao---- 198.90g
  swap      centos -wi-ao----   5.00g
[root@spacewalk ~]# pvs
  PV         VG     Fmt  Attr PSize   PFree
  /dev/sda2  centos lvm2 a--   49.51g 40.00m
  /dev/sdb   centos lvm2 a--  221.00g 17.09g

And we're back to normal again. I don't see any ill effects from our little experiment here, except there's a persistent entry in /var/log/messages like this: kernel: sdb: unknown partition table. I think this is a benign error.

As near as I can tell, the kernel keeps rescanning /dev/sdb when we do bad things to the snapshot. Since the entire drive has been fed into lvm via pvcreate /dev/sdb, there's no partition table on it. The kernel finds this notable enough to report, but since lvm is already aware and doesn't care, it doesn't actually mean anything.

Conclusions

So, what have we learned? We learned that:

In addition, I am super impressed with the robustness of both LVM2 and the I/O systems of the Linux kernel. I really put the screws to the snapshot and the only thing that failed was the one piece I was testing. Everything else is completely untouched. Nice work Linus et al!

Thanks for tuning in to my experiments. Check back in later for more interesting explorations of all manner of Linux sysadminery.