[linux-lvm] oops on 2.4.2 with lvm-0.9beta5 and Reiserfs 3.6.25

[linux-lvm] oops on 2.4.2 with lvm-0.9beta5 and Reiserfs 3.6.25

[lvm]

I just built a new system based on Linux 2.4.2 with LVM 0.9 beta 5.
I applied the patches, turned on the #define LVM_VFS_ENHANCEMENT,
rebuilt/booted the kernel and the user level tools.

I found a reproducible "kernel oops" as shown in the trace attached below.

// note: I apologize for attaching a long trace, but the problem is often
//       found "in the details" so I felt the attachment was justified.

The oops always happens if I use 

  # lvcreate -L 10g ...
  # lvextend -L +2g ...

but I've never seen it happen if I use

  # lvcreate -L 12g ...

I'm happy to supply any additional details on request.

Larry

-----
# vgscan
vgscan -- reading all physical volumes (this may take a while...)
vgscan -- no volume groups found

# pvcreate /dev/hda3
pvcreate -- physical volume "/dev/hda3" successfully created

# vgcreate vg0 /dev/hda3
vgcreate -- INFO: using default physical extent size 4 MB
vgcreate -- INFO: maximum logical volume size is 255.99 Gigabyte
vgcreate -- doing automatic backup of volume group "vg0"
vgcreate -- volume group "vg0" successfully created and activated

# lvcreate -L 10g -n lv0 vg0
lvcreate -- doing automatic backup of "vg0"
lvcreate -- logical volume "/dev/vg0/lv0" successfully created

# lvextend -L +2g /dev/vg0/lv0
lvextend -- extending logical volume "/dev/vg0/lv0" to 12 GB
lvextend -- doing automatic backup of volume group "vg0"
lvextend -- logical volume "/dev/vg0/lv0" successfully extended

# mkreiserfs /dev/vg0/lv0

<-------------mkreiserfs, 2000------------->
reiserfsprogs 3.x.0d
Creating reiserfs of 3.6 format
Block size 4096 bytes
Block count 3145728
Used blocks 8307
Free blocks count 3137421
First 16 blocks skipped
Super block is in 16
Bitmap blocks (96) are : 
        17, 32768, 65536, 98304, 131072, 163840, 196608, 229376, 262144, 294912, 327680, 360448, 393216, 425984, 458752, 491520, 524288, 557056, 589824, 622592, 655360, 688128, 720896, 753664, 786432, 819200, 851968, 884736, 917504, 950272, 983040, 1015808, 1048576, 1081344, 1114112, 1146880, 1179648, 1212416, 1245184, 1277952, 1310720, 1343488, 1376256, 1409024, 1441792, 1474560, 1507328, 1540096, 1572864, 1605632, 1638400, 1671168, 1703936, 1736704, 1769472, 1802240, 1835008, 1867776, 1900544, 1933312, 1966080, 1998848, 2031616, 2064384, 2097152, 2129920, 2162688, 2195456, 2228224, 2260992, 2293760, 2326528, 2359296, 2392064, 2424832, 2457600, 2490368, 2523136, 2555904, 2588672, 2621440, 2654208, 2686976, 2719744, 2752512, 2785280, 2818048, 2850816, 2883584, 2916352, 2949120, 2981888, 3014656, 3047424, 3080192, 3112960
Journal size 8192 (blocks 18-8210 of file /dev/vg0/lv0)
Root block 8211
Hash function "r5"
ATTENTION: YOU SHOULD REBOOT AFTER FDISK!
            ALL DATA WILL BE LOST ON '/dev/vg0/lv0'! (y/n)y
Initializing journal - 0%                                                       ....20%....40%....60%....80%....100%                         left 0, 585 /sec
Syncing..

ReiserFS core development sponsored by SuSE Labs (suse.com)

Journaling sponsored by MP3.com.

To learn about the programmers and ReiserFS, please go to
http://www.devlinux.com/namesys

Have fun.

# vgdisplay
--- Volume group ---
VG Name               vg0
VG Access             read/write
VG Status             available/resizable
VG #                  0
MAX LV                256
Cur LV                1
Open LV               0
MAX LV Size           255.99 GB
Max PV                256
Cur PV                1
Act PV                1
VG Size               14.77 GB
PE Size               4 MB
Total PE              3780
Alloc PE / Size       3072 / 12 GB
Free  PE / Size       708 / 2.77 GB
VG UUID               4dsYpg-DTNA-v3n6-Ez2W-5Ht6-ZBOM-mK23YY


# mount /dev/vg0/lv0 /lv
# df
Filesystem           1k-blocks      Used Available Use% Mounted on
/dev/hda1              4200828   1032508   3168320  25% /
/dev/vg0/lv0          12582524     32840  12549684   0% /lv
# echo hello world > /lv/foo
# lvcreate -L1g -s -n s0 /dev/vg0/lv0
lvcreate -- WARNING: the snapshot must be disabled if it gets full
lvcreate -- INFO: using default snapshot chunk size of 64 KB for "/dev/vg0/s0"
Segmentation fault
# dmesg | tail 
ReiserFS version 3.6.25
journal-1777: buffer 16 bad state !PREPARED !LOCKED !DIRTY !JDIRTY_WAIT
Unable to handle kernel NULL pointer dereference at virtual address 00000000
 printing eip:
c011370b
*pde = 00000000
Oops: 0002
CPU:    0
EIP:    0010:[<c011370b>]
EFLAGS: 00010086
eax: c697b578   ebx: 00000000   ecx: 00000286   edx: c15bdd68
esi: c15bdd60   edi: c15bc000   ebp: c697bb90   esp: c15bdd48
ds: 0018   es: 0018   ss: 0018
Process lvcreate (pid: 134, stackpage=c15bd000)
Stack: c697b56c c15bdd60 c01079d9 c697ba00 c697b400 c6879000 00000001 c15bc000 
       c697b578 00000000 c0107b38 c697b56c c13b51a0 00000000 c023bf73 4004fe20 
       080989e0 c15bdf9c c6879000 c697ba00 00000001 c68794c4 00000004 c68794c4 
Call Trace: [<c01079d9>] [<c0107b38>] [<c023bf73>] [<c01f3724>] [<c013b967>] [<c0108e2f>] [<c010002b>] 

Code: 89 13 51 9d 5b 5e c3 89 f6 9c 58 fa 8b 4a 0c 8b 52 08 89 4a 
# vgdisplay
--- Volume group ---
VG Name               vg0
VG Access             read/write
VG Status             available/resizable
VG #                  0
MAX LV                256
Cur LV                2
Open LV               1
MAX LV Size           255.99 GB
Max PV                256
Cur PV                1
Act PV                1
VG Size               14.77 GB
PE Size               4 MB
Total PE              3780
Alloc PE / Size       3328 / 13 GB
Free  PE / Size       452 / 1.77 GB
VG UUID               4dsYpg-DTNA-v3n6-Ez2W-5Ht6-ZBOM-mK23YY


# lvdisplay /dev/vg0/lv0
--- Logical volume ---
LV Name                /dev/vg0/lv0
VG Name                vg0
LV Write Access        read/write
LV Status              available
LV #                   1
# open                 1
LV Size                12 GB
Current LE             3072
Allocated LE           3072
Allocation             next free
Read ahead sectors     120
Block device           58:0

Re: [linux-lvm] oops on 2.4.2 with lvm-0.9beta5 and Reiserfs 3.6.25

[Chris Mason]

On Friday, February 23, 2001 04:07:52 PM -0500 lvm@winux.com wrote:

> ReiserFS version 3.6.25
> journal-1777: buffer 16 bad state !PREPARED !LOCKED !DIRTY !JDIRTY_WAIT

This oops shows that somebody logged the super block without preparing it.
Could you please run this data through ksymoops so I can track down the
caller?

> Unable to handle kernel NULL pointer dereference at virtual address
> 00000000 printing eip:
> c011370b
> *pde = 00000000
> Oops: 0002
> CPU:    0
> EIP:    0010:[<c011370b>]
> EFLAGS: 00010086
> eax: c697b578   ebx: 00000000   ecx: 00000286   edx: c15bdd68
> esi: c15bdd60   edi: c15bc000   ebp: c697bb90   esp: c15bdd48
> ds: 0018   es: 0018   ss: 0018
> Process lvcreate (pid: 134, stackpage=c15bd000)
> Stack: c697b56c c15bdd60 c01079d9 c697ba00 c697b400 c6879000 00000001
> c15bc000  c697b578 00000000 c0107b38 c697b56c c13b51a0 00000000 c023bf73
>        4004fe20  080989e0 c15bdf9c c6879000 c697ba00 00000001 c68794c4
>        00000004 c68794c4  Call Trace: [<c01079d9>] [<c0107b38>]
> [<c023bf73>] [<c01f3724>] [<c013b967>] [<c0108e2f>] [<c010002b>] 
> 
> Code: 89 13 51 9d 5b 5e c3 89 f6 9c 58 fa 8b 4a 0c 8b 52 08 89 4a 

-chris

Re: [linux-lvm] oops on 2.4.2 with lvm-0.9beta5 and Reiserfs 3.6.25

[Andreas Dilger]

Larry writes:
> I just built a new system based on Linux 2.4.2 with LVM 0.9 beta 5.
> I applied the patches, turned on the #define LVM_VFS_ENHANCEMENT,
> rebuilt/booted the kernel and the user level tools.
> 
> I found a reproducible "kernel oops" as shown in the trace attached below.
> 
> The oops always happens if I use 
> 
>   # lvcreate -L 10g ...
>   # lvextend -L +2g ...
> 
> but I've never seen it happen if I use
> 
>   # lvcreate -L 12g ...
> 
> # mkreiserfs /dev/vg0/lv0
> # mount /dev/vg0/lv0 /lv
> # echo hello world > /lv/foo
> # lvcreate -L1g -s -n s0 /dev/vg0/lv0
> lvcreate -- WARNING: the snapshot must be disabled if it gets full
> lvcreate -- INFO: using default snapshot chunk size of 64 KB for "/dev/vg0/s0"
> Segmentation fault
> # dmesg | tail 
> ReiserFS version 3.6.25
> journal-1777: buffer 16 bad state !PREPARED !LOCKED !DIRTY !JDIRTY_WAIT
> Unable to handle kernel NULL pointer dereference at virtual address 00000000
>  printing eip:

You need to run the dmesg output through ksymoops for this to be useful.
The journal-1777 message is definitely a reiserfs error, but there is no
way to tell where the oops happened.  Also running "lvcreate -v -d" may
be useful, if overly verbose.

I wouldn't think that how you create an LV would affect reiserfs, but who
knows?  There could be something in how lvextend updates the in-kernel
information, the beta5 snapshot changes, or it may also be something in
the reiserfs snapshot code.

Cheers, Andreas
-- 
Andreas Dilger  \ "If a man ate a pound of pasta and a pound of antipasto,
                 \  would they cancel out, leaving him still hungry?"
http://www-mddsp.enel.ucalgary.ca/People/adilger/               -- Dogbert

Re: [linux-lvm] oops on 2.4.2 with lvm-0.9beta5 and Reiserfs 3.6.25

[lvm]

Chris Mason writes:
> This oops shows that somebody logged the super block without preparing it.
> Could you please run this data through ksymoops so I can track down the
> caller?

# dmesg | ksymoops -v /usr/src/linux/vmlinux -m /boot/System.map 
ksymoops 2.3.7 on i686 2.4.2.  Options used
     -v /usr/src/linux/vmlinux (specified)
     -k /proc/ksyms (default)
     -l /proc/modules (default)
     -o /lib/modules/2.4.2/ (default)
     -m /boot/System.map (specified)

No modules in ksyms, skipping objects
Warning (read_lsmod): no symbols in lsmod, is /proc/modules a valid lsmod file?
Warning (compare_maps): mismatch on symbol partition_name  , ksyms_base says c01ee150, vmlinux says c0149cc0.  Ignoring ksyms_base entry
Unable to handle kernel NULL pointer dereference at virtual address 00000000
c011370b
*pde = 00000000
Oops: 0002
CPU:    0
EIP:    0010:[<c011370b>]
Using defaults from ksymoops -t elf32-i386 -a i386
EFLAGS: 00010086
eax: c697b578   ebx: 00000000   ecx: 00000286   edx: c15bdd68
esi: c15bdd60   edi: c15bc000   ebp: c697bb90   esp: c15bdd48
ds: 0018   es: 0018   ss: 0018
Process lvcreate (pid: 134, stackpage=c15bd000)
Stack: c697b56c c15bdd60 c01079d9 c697ba00 c697b400 c6879000 00000001 c15bc000 
       c697b578 00000000 c0107b38 c697b56c c13b51a0 00000000 c023bf73 4004fe20 
       080989e0 c15bdf9c c6879000 c697ba00 00000001 c68794c4 00000004 c68794c4 
Call Trace: [<c01079d9>] [<c0107b38>] [<c023bf73>] [<c01f3724>] [<c013b967>] [<c0108e2f>] [<c010002b>] 
Code: 89 13 51 9d 5b 5e c3 89 f6 9c 58 fa 8b 4a 0c 8b 52 08 89 4a 

>>EIP; c011370b <add_wait_queue_exclusive+1f/28>   <=====
Trace; c01079d9 <__down+41/9c>
Trace; c0107b38 <__down_failed+8/c>
Trace; c023bf73 <stext_lock+f9b/1374>
Trace; c01f3724 <lvm_chr_ioctl+504/670>
Trace; c013b967 <sys_ioctl+16b/184>
Trace; c0108e2f <system_call+33/38>
Trace; c010002b <startup_32+2b/139>
Code;  c011370b <add_wait_queue_exclusive+1f/28>
0000000000000000 <_EIP>:
Code;  c011370b <add_wait_queue_exclusive+1f/28>   <=====
   0:   89 13                     mov    %edx,(%ebx)   <=====
Code;  c011370d <add_wait_queue_exclusive+21/28>
   2:   51                        push   %ecx
Code;  c011370e <add_wait_queue_exclusive+22/28>
   3:   9d                        popf   
Code;  c011370f <add_wait_queue_exclusive+23/28>
   4:   5b                        pop    %ebx
Code;  c0113710 <add_wait_queue_exclusive+24/28>
   5:   5e                        pop    %esi
Code;  c0113711 <add_wait_queue_exclusive+25/28>
   6:   c3                        ret    
Code;  c0113712 <add_wait_queue_exclusive+26/28>
   7:   89 f6                     mov    %esi,%esi
Code;  c0113714 <remove_wait_queue+0/14>
   9:   9c                        pushf  
Code;  c0113715 <remove_wait_queue+1/14>
   a:   58                        pop    %eax
Code;  c0113716 <remove_wait_queue+2/14>
   b:   fa                        cli    
Code;  c0113717 <remove_wait_queue+3/14>
   c:   8b 4a 0c                  mov    0xc(%edx),%ecx
Code;  c011371a <remove_wait_queue+6/14>
   f:   8b 52 08                  mov    0x8(%edx),%edx
Code;  c011371d <remove_wait_queue+9/14>
  12:   89 4a 00                  mov    %ecx,0x0(%edx)


2 warnings issued.  Results may not be reliable.

Re: [linux-lvm] oops on 2.4.2 with lvm-0.9beta5 and Reiserfs 3.6.25

[Chris Mason]

On Friday, February 23, 2001 04:46:02 PM -0500 lvm@winux.com wrote:

> Chris Mason writes:
>> This oops shows that somebody logged the super block without preparing
>> it. Could you please run this data through ksymoops so I can track down
>> the caller?
> 
> # dmesg | ksymoops -v /usr/src/linux/vmlinux -m /boot/System.map 

Hmmm, probably not the right system.map.  I think I see the bug though,
please try this patch:

--- linux/fs/reiserfs/super.c.1	Fri Feb 23 16:30:55 2001
+++ linux/fs/reiserfs/super.c	Fri Feb 23 16:31:39 2001
@@ -68,6 +68,7 @@
   lock_kernel() ;
   if (!(s->s_flags & MS_RDONLY)) {
     journal_begin(&th, s, 1) ;
+    reiserfs_prepare_for_journal(s, SB_BUFFER_WITH_SB(s), 1) ;
     journal_mark_dirty(&th, s, SB_BUFFER_WITH_SB (s));
     reiserfs_block_writes(&th) ;
     journal_end(&th, s, 1) ;

Re: [linux-lvm] oops on 2.4.2 with lvm-0.9beta5 and Reiserfs 3.6.25

[lvm]

Chris Mason writes:
>> This oops shows that somebody logged the super block without preparing
>> it. Could you please run this data through ksymoops so I can track down
>> the caller?
>> 
>> # dmesg | ksymoops -v /usr/src/linux/vmlinux -m /boot/System.map 
> 
> Hmmm, probably not the right system.map.
> I think I see the bug though, please try this patch:
> 
> --- linux/fs/reiserfs/super.c.1	Fri Feb 23 16:30:55 2001
> +++ linux/fs/reiserfs/super.c	Fri Feb 23 16:31:39 2001
> @@ -68,6 +68,7 @@
>    lock_kernel() ;
>    if (!(s->s_flags & MS_RDONLY)) {
>      journal_begin(&th, s, 1) ;
> +    reiserfs_prepare_for_journal(s, SB_BUFFER_WITH_SB(s), 1) ;
>      journal_mark_dirty(&th, s, SB_BUFFER_WITH_SB (s));
>      reiserfs_block_writes(&th) ;
>      journal_end(&th, s, 1) ;

This message doesn't show up any more:

journal-1777: buffer 16 bad state !PREPARED !LOCKED !DIRTY !JDIRTY_WAIT

but that definitely didn't fix it.   I get exactly the same oops behavior.

I'm working on a different machine now but it's acting the same way.
Here's the script I use to stimulate the problem.  I use /dev/sda4
as the target here.

[ WARNING! There should be NO live LVM volumes on this machine.
  This starts from scratch by blowing away LVM info and zapping the partition.
]


dd if=/dev/zero of=/dev/sda4 count=2k bs=4k
rm -rf /etc/lvm* /dev/lvm* /dev/vg*
vgscan
pvcreate /dev/sda4
vgcreate vg0 /dev/sda4
lvcreate -L 10g -n lv0 vg0
lvextend -L +2g /dev/vg0/lv0
mkreiserfs -q /dev/vg0/lv0
mount /dev/vg0/lv0 /mnt
echo hello world > /mnt/foo
lvcreate -L 1g -s -n s0 /dev/vg0/lv0

-----------------------------------------------------------------------

Because you questioned the validity of the System.map, I switched back
to the kernel version without the above patch, recompiled to generate
a bona fide System.map and ran the test again.  Here's the result.
Hope it helps.

# dmesg | ksymoops -v /usr/src/linux/vmlinux -m /boot/System.map 
ksymoops 2.3.7 on i686 2.4.2.  Options used
     -v /usr/src/linux/vmlinux (specified)
     -k /proc/ksyms (default)
     -l /proc/modules (default)
     -o /lib/modules/2.4.2/ (default)
     -m /boot/System.map (specified)

Warning (compare_maps): mismatch on symbol partition_name  , ksyms_base says c01e7c70, vmlinux says c01474b0.  Ignoring ksyms_base entry
Unable to handle kernel NULL pointer dereference at virtual address 00000000
c0110efb
*pde = 00000000
Oops: 0002
CPU:    0
EIP:    0010:[<c0110efb>]
Using defaults from ksymoops -t elf32-i386 -a i386
EFLAGS: 00010086
eax: cf84af78   ebx: 00000000   ecx: 00000286   edx: ce7b3d68
esi: ce7b3d60   edi: ce7b2000   ebp: cddcd590   esp: ce7b3d48
ds: 0018   es: 0018   ss: 0018
Process lvcreate (pid: 129, stackpage=ce7b3000)
Stack: cf84af6c ce7b3d60 c0107a29 cddcd400 cf84ae00 cfb1e000 00000001 ce7b2000 
       cf84af78 00000000 c0107b88 cf84af6c cfe6bce0 00000000 c022b685 4004fe20 
       0809bd60 ce7b3f9c cfb1e000 cddcd400 00000001 cfb1e4c4 00000004 cfb1e4c4 
Call Trace: [<c0107a29>] [<c0107b88>] [<c022b685>] [<c01ed244>] [<c0139157>] [<c0108e7f>] 
Code: 89 13 51 9d 5b 5e c3 89 f6 9c 58 fa 8b 4a 0c 8b 52 08 89 4a 

>>EIP; c0110efb <add_wait_queue_exclusive+1f/28>   <=====
Trace; c0107a29 <__down+41/9c>
Trace; c0107b88 <__down_failed+8/c>
Trace; c022b685 <stext_lock+f19/1176>
Trace; c01ed244 <lvm_chr_ioctl+504/670>
Trace; c0139157 <sys_ioctl+16b/184>
Trace; c0108e7f <system_call+33/38>
Code;  c0110efb <add_wait_queue_exclusive+1f/28>
0000000000000000 <_EIP>:
Code;  c0110efb <add_wait_queue_exclusive+1f/28>   <=====
   0:   89 13                     mov    %edx,(%ebx)   <=====
Code;  c0110efd <add_wait_queue_exclusive+21/28>
   2:   51                        push   %ecx
Code;  c0110efe <add_wait_queue_exclusive+22/28>
   3:   9d                        popf   
Code;  c0110eff <add_wait_queue_exclusive+23/28>
   4:   5b                        pop    %ebx
Code;  c0110f00 <add_wait_queue_exclusive+24/28>
   5:   5e                        pop    %esi
Code;  c0110f01 <add_wait_queue_exclusive+25/28>
   6:   c3                        ret    
Code;  c0110f02 <add_wait_queue_exclusive+26/28>
   7:   89 f6                     mov    %esi,%esi
Code;  c0110f04 <remove_wait_queue+0/14>
   9:   9c                        pushf  
Code;  c0110f05 <remove_wait_queue+1/14>
   a:   58                        pop    %eax
Code;  c0110f06 <remove_wait_queue+2/14>
   b:   fa                        cli    
Code;  c0110f07 <remove_wait_queue+3/14>
   c:   8b 4a 0c                  mov    0xc(%edx),%ecx
Code;  c0110f0a <remove_wait_queue+6/14>
   f:   8b 52 08                  mov    0x8(%edx),%edx
Code;  c0110f0d <remove_wait_queue+9/14>
  12:   89 4a 00                  mov    %ecx,0x0(%edx)


1 warning issued.  Results may not be reliable.