Sorry, dm:1.02, lvm2:2.02 did not work for me

in linux-lvm Digest, Vol 21, Issue 7 msg 2..

I tried the above dm and lvm2, but now have problems creating a snapshot on an origin volume named "F" of VGf11 on a pv /dev/sdf11. I get (The origin F was built with prior lvm2:1.0.5 dm:1.01.05)
---
device-mapper ioctl cmd 3 failed: Device or resource busy
Failed to suspend origin F
Device '/dev/sdf11' has been left open.
---
This is on stock FC4 kernel
kernel-2.6.13-1.1532_FC4

I also tried on
kernel-2.6.14-1.1637_FC4
but on that kernel, I get
---
Attempt to close device '/dev/hda' which is not open. Attempt to close device '/dev/sda' which is not open.
(& similarly up thru sdi -- all my disks) ..followed by the
Failed to suspend.. stuff as above

I had to configure both dm and lvm2 with "--disable-selinux"), but I wouldn't expect that to have any impact, eh?

I've also been noticing that I've had to use "--ignorearch" to install FC4 precompiled kernels and --target=i686 on compiles from FC4 kernel srpms -- would that have any relation to these symptoms?

I didn't do any kernel patching -- the only patches relate to the 2.4 kernel, I believe.

In case there's something useful there, heres the tail of the spam when I set verbose=2 in lvm.coinf

/dev/sdf11: lvm2 label detected
Archiving volume group "VGf11" metadata (seqno 64797). Creating logical volume S
Creating volume group backup "/etc/lvm/backup/VGf11" (seqno 64798).
Finding volume group for uuid
cfAe87N2RoYKKc6Ef8yZn4fG0Foi98gBLI1TVwRB4p3bJEoRfK52PtAc0crW4ytk
/dev/sdf11: lvm2 label detected
/dev/sdf11: lvm2 label detected
Found volume group "VGf11"
Locking memory
Setting activation/missing_stripe_filler to /dev/ioerror Getting target version for linear
Getting target version for striped
Creating VGf11-S
Loading VGf11-S table
Resuming VGf11-S (253:10)
Unlocking memory
Linking /dev/VGf11/S -> /dev/mapper/VGf11-S
Zeroing start of logical volume "S"
Finding volume group for uuid
cfAe87N2RoYKKc6Ef8yZn4fG0Foi98gBLI1TVwRB4p3bJEoRfK52PtAc0crW4ytk
/dev/sdf11: lvm2 label detected
/dev/sdf11: lvm2 label detected
Found volume group "VGf11"
Locking memory
Removing VGf11-S (253:10)
Unlocking memory
Removing link /dev/VGf11/S
Finding volume group for uuid
cfAe87N2RoYKKc6Ef8yZn4fG0Foi98gBLI1TVwRB4p3bJEoRfK52PtAc0crW4ytk
/dev/sdf11: lvm2 label detected
/dev/sdf11: lvm2 label detected
Found volume group "VGf11"
Finding volume group for uuid
cfAe87N2RoYKKc6Ef8yZn4fG0Foi98gBI7Kovv1OPi1Z4L4st6YPuh2L66mZur1B
/dev/sdf11: lvm2 label detected
/dev/sdf11: lvm2 label detected
Found volume group "VGf11"
Loading VGf11-F-real table
Resuming VGf11-F-real (253:9)
Creating VGf11-F
device-mapper ioctl cmd 3 failed: Device or resource busy Failed to suspend origin F
Unlocking /var/lock/lvm/V_VGf11
Dumping persistent device cache to /etc/lvm/.cache
Wiping internal VG cache
Device '/dev/sdf11' has been left open.

---
Also, if I set logging "level = 6" in lvm.conf, here's the tail-end of /var/log/lvm.log:
- - -
label/label.c:167 /dev/sdf11: lvm2 label detected
config/config.c:757 Setting cow_store to S
config/config.c:757 Setting origin to F
metadata/metadata.c:1177 Found volume group "VGf11"
libdm-deptree.c:1103 Creating VGf11-F-real
libdm-deptree.c:1321 Loading VGf11-F-real table
libdm-deptree.c:864 Resuming (253:1)
libdm-deptree.c:1103 Creating VGf11-F
ioctl/libdm-iface.c:1392 device-mapper ioctl cmd 3 failed: Device or
resource busy
lvcreate.c:763 Failed to suspend origin F
locking/file_locking.c:59 Unlocking /var/lock/lvm/V_VGf11
filters/filter-persistent.c:180 Dumping persistent device cache
to /etc/lvm/.cache
cache/lvmcache.c:591 Wiping internal VG cache
device/dev-cache.c:479 Device '/dev/sdf11' has been left open.
- - -

So .. what next?

Regards
..jim

Please do (at the point of failure)
dmsetup info -c
dmsetup table

Also, I need to see more of the log to work out what's going on and a copy of the metadata (/etc/lvm/backup/VGf11).

Is the original LV activated with the old or new code?

Alasdair

I've reproduced this if the LV is activated with an old release but the snapshot is created with the new code. Should be easy to fix.

Meanwhile, try lvchange -an before using the new code to activate the LV again and create the snapshot.

Alasdair

[email protected]

Try the current CVS versions.
[A device-mapper fix to stop it issuing an incorrect 'dm create'; an LVM2 fix to avoid the 'device left open' messages.]

Alasdair

[email protected]

Ok, I've grabbed the cvs images, done the configure/make/make install on dm and then lvm, and I now see:

lvm version
LVM version: 2.02.01-cvs (2005-11-10)
Library version: 1.02.01-cvs (2005-11-10)
Driver version: 4.4.0

I rebooted and reran my test procedure which
1) loops on {lvcreate, sleep 10, lvremove, sleep 2} and simultaneously
2) loops on {cp abcd wxyz;cp wxyz abcd) operating on a 1GB file on the origin filesystem

The kcopyd.c BUG at line 145 is triggered by the first lvremove following start of the i/o (copy loop).

The dmesg dump is:
-----------------
Linux version 2.6.13-1.1532_FC4 ([email protected]) (gcc version 4.0.1 20050727 (Red Hat 4.0.1-5)) #1 Thu Oct 20 01:30:08 EDT 2005
..<snip>..

------------[ cut here ]------------
kernel BUG at drivers/md/kcopyd.c:145!
invalid operand: 0000 [#1]
Modules linked in: xfs exportfs dm_snapshot ipv6 parport_pc lp parport
autofs4 rfcomm l2cap bluetooth sunrpc ohci_hcd i2c_piix4 i2c_core tulip
e100 mii floppy ext3 jbd raid1 dm_mod aic7xxx scsi_transport_spi sd_mod
scsi_mod
CPU:    0
EIP:    0060:[<f8870635>]    Not tainted VLI
EFLAGS: 00010287   (2.6.13-1.1532_FC4) 

EIP is at client_free_pages+0x2a/0x34 [dm_mod]
eax: 00000100 ebx: c1b73a60 ecx: f7fff060 edx: 00000000
esi: f8aaa080 edi: 00000000 ebp: 00000000 esp: f560ef0c
ds: 007b es: 007b ss: 0068
Process lvremove (pid: 4004, threadinfo=f560e000 task=f772d550)

Stack: c1b73a60 f8871e00 c1b97140 f89f9935 f8aaa080 f5667180 f886bb86
f5667180 
       f4a60140 f8a9f000 00000004 f886e09f f886d97e f88786a0 f886e0f1
f560e000 
       f560e000 00000000 f886f4df 00000002 c0164c71 f8a9f000 f886f411
f63e7600 
Call Trace:
 [<f8871e00>] kcopyd_client_destroy+0x12/0x26 [dm_mod]
 [<f89f9935>] snapshot_dtr+0x4f/0x58 [dm_snapshot]
 [<f886bb86>] table_destroy+0x3e/0x8e [dm_mod]
 [<f886e09f>] dev_remove+0x0/0xc6 [dm_mod]
 [<f886d97e>] __hash_remove+0x5a/0x99 [dm_mod]
 [<f886e0f1>] dev_remove+0x52/0xc6 [dm_mod]
 [<f886f4df>] ctl_ioctl+0xce/0x10a [dm_mod]
 [<c0164c71>] audit_syscall_entry+0x130/0x15e
 [<f886f411>] ctl_ioctl+0x0/0x10a [dm_mod]
 [<c01bf121>] do_ioctl+0x51/0x55
 [<c01bf217>] vfs_ioctl+0x50/0x1aa
 [<c01bf3ce>] sys_ioctl+0x5d/0x6b
 [<c0104465>] syscall_call+0x7/0xb
Code: c3 53 89 c3 8b 40 24 39 43 28 75 1f 8b 43 20 e8 86 ff ff ff c7 43

20 00 00 00 00 c7 43 24 00 00 00 00 c7 43 28 00 00 00 00 5b c3 <0f> 0b 91 00 ff 21 87 f8 eb d7 83 ec 0c c7 44 24 08 00 00 00 00
<1>Unable to handle kernel paging request at virtual address f8aacd84 printing eip:
f89fb038
*pde = 019c0067

Oops: 0000 [#2]
Modules linked in: xfs exportfs dm_snapshot ipv6 parport_pc lp parport
autofs4 rfcomm l2cap bluetooth sunrpc ohci_hcd i2c_piix4 i2c_core tulip
e100 mii floppy ext3 jbd raid1 dm_mod aic7xxx scsi_transport_spi sd_mod
scsi_mod
CPU:    0
EIP:    0060:[<f89fb038>]    Not tainted VLI
EFLAGS: 00010246   (2.6.13-1.1532_FC4) 

EIP is at persistent_commit+0xdb/0x100 [dm_snapshot]
eax: 00000000 ebx: 000001b0 ecx: f8aacd80 edx: 00000001
esi: 00000d80 edi: f5083120 ebp: 00000000 esp: f6a92edc
ds: 007b es: 007b ss: 0068
Process kcopyd (pid: 2944, threadinfo=f6a92000 task=f6294aa0)

Stack: 0088d972 00000000 00001808 00000000 cf39f964 c1b97140 cf39f964
f89f9c9b 
       f89f9cd1 cf39f964 cf3a1274 00000000 f8870760 00000000 cf3a1274
00000202 
       f8878878 f887071f f8870ece 00000092 00000000 00000282 f6294aa0
fadf8496 
Call Trace:
 [<f89f9c9b>] copy_callback+0x0/0x3c [dm_snapshot]
 [<f89f9cd1>] copy_callback+0x36/0x3c [dm_snapshot]
 [<f8870760>] run_complete_job+0x41/0x4b [dm_mod]
 [<f887071f>] run_complete_job+0x0/0x4b [dm_mod]
 [<f8870ece>] process_jobs+0x19/0x6a5 [dm_mod]
 [<f887155a>] do_work+0x0/0x2d [dm_mod]
 [<f8871569>] do_work+0xf/0x2d [dm_mod]
 [<c0147bf7>] worker_thread+0x2aa/0x621
 [<c012186b>] __wake_up_common+0x39/0x59
 [<c0121826>] default_wake_function+0x0/0xc
 [<c014794d>] worker_thread+0x0/0x621
 [<c01508ab>] kthread+0x87/0x8b
 [<c0150824>] kthread+0x0/0x8b
 [<c01012ed>] kernel_thread_helper+0x5/0xb
Code: 08 00 00 00 00 83 c4 10 5b 5e 5f 5d c3 c7 47 08 00 00 00 00 8b 47

28 85 c0 74 bc 31 db 31 f6 89 f1 03 4f 2c 31 d2 85 ed 0f 94 c2 <8b> 41 04 ff 11 83 c3 01 83 c6 08 39 5f 28 77 e4 c7 47 28 00 00
-----------------------------------------------------------------------

At this point any call to dmsetup seems to hang (and be in uninterruptible sleep state)

I have a big level-6 lvm2.log file if that's helpful. I could extract a somewhat smaller tail-end -- probably half-size or smaller would cover the results since last boot.

I think the origin volume was made on 2.6 lvm2 but I'm not 100% sure.

==> I will go rerun my test scenario on a new origin volume, to see if there's any differences.

Any suggestions on what else to do?

Regards,
..jim

...

..

Result with origin volume on new pv/vg/lv was same, namely: kcopyd.c BUG at line 145 & oops.

Is there something else I can provide to assist in diagnostics?

hmmm- I thought I might simplify my test environment by removing all older lvm devices, so I pulled disks containing 3 other pv's. Then I was getting another scsi read error so I pulled that disk (<heh> I have a 9- disk NAS I'm playing on, in case anyone's wondering)

Then after reboot, and rerun of my test procedure, I still get the same behavior --except that it now seems to lockup hard -- no ssh, no ping, no console scrollback, no keyboard (although sysrq works), no dmesg/syslog output. There *is* console screen output, ending with what looks like the trailing part of the oops calltrace. Is it worth configuring a serial console in order to capture this? (Or can someone tell me how to capture it otherwise?)

Regards.
..jim

Try some kernel patches.

http://www.kernel.org/pub/linux/kernel/people/agk/patches/2.6/editing/

in particular these four:

dm-snapshot-bio_list-fix.patch
dm-snapshot-metadata-reading-separation.patch
dm-snapshot-load-metadata-on-creation.patch
dm-ioctl-reduce-pf-memalloc-usage.patch

Alasdair

[email protected]

If you have a digital camera, posting images on the web sometimes works. [And see if you can scroll up to capture the earlier parts.]

Alasdair

[email protected]

Note also that a data corruption bug has been reported if you create *two* (or more) snapshots of the same devices. [I think this can be fixed in userspace but I may not get time to do this for a few days.]

Alasdair

[email protected]