Skip to contentSkip to conversation

oops on 2.4.2 with lvm-0.9beta5 and Reiserfs 3.6.25

linux-lvm [email protected] 3 participants 6 messages Feb 23, 2001 – Feb 24, 2001

lore
Share & tools
lore

[email protected]

author
#0 lore raw

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
#1 lore raw
Quoted 2 lines · On Friday, February 23, 2001 04:07:52 PM -0500 [email protected] 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?

Quoted 16 lines
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>]
Quoted 3 lines

[<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

author
#2 lore raw
Quoted 3 lines · Chris Mason

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
Quoted 1 line
Quoted 1 line

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.

#3 lore raw
Quoted 6 lines · On Friday, February 23, 2001 04:46:02 PM -0500 [email protected] wrote:
Quoted 3 lines · Chris Mason

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:

fs/reiserfs/super.c renamed from fs/reiserfs/super.c.1 +1 -0
@@ -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) ;
author
#4 lore raw
Quoted 12 lines · Chris Mason
Quoted 5 lines

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:

fs/reiserfs/super.c line 74

Quoted 7 lines
fs/reiserfs/super.c renamed from fs/reiserfs/super.c.1 +1 -0
@@ -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
Quoted 1 line
Quoted 1 line

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.

#5 lore raw
In reply to [email protected]
Quoted 15 lines · Larry

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 ...
Quoted 12 lines
# 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

Signature · 3 lines
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