[linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[James G. Sack (jim)]

in linux-lvm Digest, Vol 21, Issue 7 msg 2..
> ------------------------------
> 
> Message: 2
> Date: Thu, 10 Nov 2005 15:52:47 +0000
> From: Alasdair G Kergon <agk@redhat.com>
> Subject: [linux-lvm] New LVM2/device-mapper development tarballs
> To: dm-devel@redhat.com, linux-lvm@redhat.com
> Message-ID: <20051110155247.GH26394@agk.surrey.redhat.com>
> Content-Type: text/plain; charset=us-ascii
> 
> I have just created new tarballs from CVS for testing
> purposes:
> 
>   ftp://sources.redhat.com/pub/dm/device-mapper.1.02.00.tgz
>   ftp://sources.redhat.com/pub/lvm2/LVM2.2.02.00.tgz
> 
> There are some significant extensions to libdevmapper and 
> the code that activates logical volumes has been rewritten
> to prepare for kernel patches to fix snapshot activation.
> The new code will also make it possible to support more
> complex device hierarchies in the future, such as snapshots 
> of mirrors.
> 
> So far I've done some basic testing, but I expect there
> are still plenty more bugs to be found: If you find any,
> please report them to one of these lists!
> 
> (Note that you'll need to install the new device-mapper package
> before the new LVM2 one.)
> 
> Alasdair

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

Re: [linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[Alasdair G Kergon]

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

Re: [linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[Alasdair G Kergon]

On Sat, Nov 12, 2005 at 02:07:10AM +0000, Alasdair G Kergon wrote:
> Is the original LV activated with the old or new code?
 
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
-- 
agk@redhat.com

Re: [linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[Alasdair G Kergon]

On Sat, Nov 12, 2005 at 10:03:21PM +0000, Alasdair G Kergon wrote:
> 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.
 
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
-- 
agk@redhat.com

Re: [linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[James G. Sack (jim)]

On Sat, 2005-11-12 at 22:49 +0000, Alasdair G Kergon wrote: 
> On Sat, Nov 12, 2005 at 10:03:21PM +0000, Alasdair G Kergon wrote:
> > 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.
>  
> 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

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 (bhcompile@tweety.build.redhat.com) (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

Re: [linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[James G. Sack (jim)]

On Tue, 2005-11-15 at 08:54 -0800, James G. Sack (jim) wrote: 
> On Sat, 2005-11-12 at 22:49 +0000, Alasdair G Kergon wrote: 
> > On Sat, Nov 12, 2005 at 10:03:21PM +0000, Alasdair G Kergon wrote:
> > > 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.
> >  
> > Try the current CVS versions.
... 
> 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).
.. 
> ==> I will go rerun my test scenario on a new origin volume, to see if
> there's any differences.

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

Re: [linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[Alasdair G Kergon]

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

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
-- 
agk@redhat.com

Re: [linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[Alasdair G Kergon]

On Tue, Nov 15, 2005 at 02:23:16PM -0800, James G. Sack (jim) wrote:
> 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?)
 
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
-- 
agk@redhat.com

Re: [linux-lvm] Sorry, dm:1.02, lvm2:2.02 did not work for me

[Alasdair G Kergon]

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
-- 
agk@redhat.com