Date: Wed, 14 May 2003 12:49:17 +0100 (IST) From: Nick Hilliard <nick-list@netability.ie> To: FreeBSD-gnats-submit@FreeBSD.org Subject: kern/52221: Repeatable NFS related panic in 5.0-current (bremfree: removing a buffer not on a queue) Message-ID: <200305141149.h4EBnHve049499@muffin.acquirer.com> Resent-Message-ID: <200305141150.h4EBoMtu024855@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>Number: 52221
>Category: kern
>Synopsis: Repeatable NFS related panic in 5.0-current (bremfree: removing a buffer not on a queue)
>Confidential: no
>Severity: critical
>Priority: high
>Responsible: freebsd-bugs
>State: open
>Quarter:
>Keywords:
>Date-Required:
>Class: sw-bug
>Submitter-Id: current-users
>Arrival-Date: Wed May 14 04:50:21 PDT 2003
>Closed-Date:
>Last-Modified:
>Originator: Nick Hilliard
>Release: FreeBSD 5.0-CURRENT i386
>Organization:
Network Ability ltd.
>Environment:
System: FreeBSD pancake.netability.ie 5.0-CURRENT FreeBSD 5.0-CURRENT #0: Thu May 8 23:26:35 IST 200
Crashing NFS server: 5.0-CURRENT w/ smp kernel dated May 8 (but has been
crashing in the same place since January). nfsserver is loaded as a kernel
module on bootup.
kosher client: 4.7-release
>Description:
mount /usr/src and /usr/obj on nfs client from nfs server. make buildworld,
and bang, the kernel panics.
The problems means that any NFS service from the server causes it to crash
with 100% reliability. It will panic and dump core about 75% of the time.
This basically means that nfsserver is unusable on this machine.
dmesg, kernel backtrace and nfs tcpdump included. 192.168.100.1 is the
4.7-release client, and 192.168.100.44 is the 5.0-current server.
pancake# dmesg
Copyright (c) 1992-2003 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
The Regents of the University of California. All rights reserved.
FreeBSD 5.0-CURRENT #0: Thu May 8 23:26:35 IST 2003
<removed>@pancake.netability.ie:/usr/src/sys/i386/compile/PANCAKE
Preloaded elf kernel "/boot/kernel/kernel" at 0xc05df000.
Preloaded elf module "/boot/kernel/vesa.ko" at 0xc05df0b4.
Preloaded elf module "/boot/kernel/linux.ko" at 0xc05df160.
Preloaded elf module "/boot/kernel/sysvshm.ko" at 0xc05df20c.
Preloaded elf module "/boot/kernel/sysvsem.ko" at 0xc05df2b8.
Preloaded elf module "/boot/kernel/sysvmsg.ko" at 0xc05df364.
Preloaded elf module "/boot/kernel/if_xl.ko" at 0xc05df410.
Preloaded elf module "/boot/kernel/miibus.ko" at 0xc05df4bc.
Preloaded elf module "/boot/kernel/snd_pcm.ko" at 0xc05df568.
Preloaded elf module "/boot/kernel/snd_ich.ko" at 0xc05df614.
Preloaded elf module "/boot/kernel/random.ko" at 0xc05df6c0.
Preloaded elf module "/boot/kernel/nvidia.ko" at 0xc05df76c.
Preloaded elf module "/boot/kernel/ahc.ko" at 0xc05df818.
Preloaded elf module "/boot/kernel/fdc.ko" at 0xc05df8c0.
Preloaded elf module "/boot/kernel/acpi.ko" at 0xc05df968.
Timecounter "i8254" frequency 1193182 Hz
CPU: Intel Pentium III (728.44-MHz 686-class CPU)
Origin = "GenuineIntel" Id = 0x683 Stepping = 3
Features=0x383fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE>
real memory = 268034048 (255 MB)
avail memory = 253956096 (242 MB)
Changing APIC ID for IO APIC #0 from 0 to 2 on chip
Programming 24 pins in IOAPIC #0
IOAPIC #0 intpin 2 -> irq 0
FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
cpu0 (BSP): apic id: 0, version: 0x00040011, at 0xfee00000
cpu1 (AP): apic id: 1, version: 0x00040011, at 0xfee00000
io0 (APIC): apic id: 2, version: 0x00170020, at 0xfec00000
Allocating major#253 to "net"
VESA: v3.0, 4096k memory, flags:0x1, mode table:0xc03b5c62 (1000022)
VESA: NVidia
Allocating major#252 to "pci"
Pentium Pro MTRR support enabled
npx0: <math processor> on motherboard
npx0: INT 16 interface
acpi0: <DELL WS 220 > on motherboard
ACPI-0625: *** Info: GPE Block0 defined as GPE0 to GPE15
pcibios: BIOS version 2.10
Using $PIR table, 9 entries at 0xc00fbbc0
acpi0: power button is handled as a fixed feature programming model.
Timecounter "ACPI-fast" frequency 3579545 Hz
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x808-0x80b on acpi0
acpi_cpu0: <CPU> on acpi0
acpi_cpu1: <CPU> on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
IOAPIC #0 intpin 19 -> irq 2
IOAPIC #0 intpin 17 -> irq 13
agp0: <Intel 82820 host to AGP bridge> mem 0xf0000000-0xf3ffffff at device 0.0 on pci0
pcib1: <PCIBIOS PCI-PCI bridge> at device 1.0 on pci0
pci1: <PCI bus> on pcib1
nvidia0: <RIVA TNT2 Model 64> mem 0xf4000000-0xf5ffffff,0xfc000000-0xfcffffff irq 16 at device 0.0 on pci1
pcib2: <ACPI PCI-PCI bridge> at device 30.0 on pci0
pci2: <ACPI PCI bus> on pcib2
IOAPIC #0 intpin 18 -> irq 17
pci2: <mass storage, SCSI> at device 11.0 (no driver attached)
xl0: <3Com 3c905C-TX Fast Etherlink XL> port 0xe880-0xe8ff mem 0xfaffec00-0xfaffec7f irq 17 at device 12.0 on pci2
xl0: Ethernet address: 00:b0:d0:a1:12:07
miibus0: <MII bus> on xl0
xlphy0: <3c905C 10/100 internal PHY> on miibus0
xlphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <Intel ICH UDMA66 controller> port 0xffa0-0xffaf at device 31.1 on pci0
ata0: at 0x1f0 irq 14 on atapci0
ata1: at 0x170 irq 15 on atapci0
pci0: <serial bus, USB> at device 31.2 (no driver attached)
pci0: <serial bus, SMBus> at device 31.3 (no driver attached)
pcm0: <Intel 82801AA (ICH)> port 0xdc80-0xdcbf,0xd800-0xd8ff irq 13 at device 31.5 on pci0
pcm0: <Analog Devices AD1881 AC97 Codec>
fdc0: <Enhanced floppy controller (i82077, NE72065 or clone)> port 0x3f7,0x3f0-0x3f5 irq 6 drq 2 on acpi0
fdc0: FIFO enabled, 8 bytes threshold
fd0: <1440-KB 3.5" drive> on fdc0 drive 0
Allocating major#251 to "devstat"
atkbdc0: <Keyboard controller (i8042)> port 0x64,0x60 irq 1 on acpi0
atkbd0: <AT Keyboard> flags 0x1 irq 1 on atkbdc0
kbd0 at atkbd0
psm0: <PS/2 Mouse> irq 12 on atkbdc0
psm0: model IntelliMouse, device ID 3
sio0 port 0x3f8-0x3ff irq 4 on acpi0
sio0: type 16550A
sio1 port 0x2f8-0x2ff irq 3 on acpi0
sio1: type 16550A
ppc0 port 0x778-0x77f,0x378-0x37f irq 7 on acpi0
ppc0: SMC-like chipset (ECP/EPP/PS2/NIBBLE) in COMPATIBLE mode
ppc0: FIFO with 16/16/8 bytes threshold
pmtimer0 on isa0
orm0: <Option ROMs> at iomem 0xcb800-0xcbfff,0xc9000-0xcb7ff,0xc0000-0xc8fff on isa0
sc0: <System console> on isa0
sc0: VGA <16 virtual consoles, flags=0x200>
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
APIC_IO: Testing 8254 interrupt delivery
APIC_IO: routing 8254 via IOAPIC #0 intpin 2
Timecounters tick every 4.000 msec
ad0: 39082MB <Maxtor 54098H8> [79406/16/63] at ata0-master UDMA66
acd0: CD-RW <PLEXTOR CD-R PX-W4824A> at ata1-master UDMA33
pcm0: measured ac97 link rate at 682666666 Hz
SMP: AP CPU #1 Launched!
Mounting root from ufs:/dev/ad0s1a
WARNING: / was not properly dismounted
uhci0: <Intel 82801AA (ICH) USB controller> port 0xff80-0xff9f irq 2 at device 31.2 on pci0
usb0: <Intel 82801AA (ICH) USB controller> on uhci0
usb0: USB revision 1.0
uhub0: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
pancake# gdb -k kernel.debug.8 vmcore.8
GNU gdb 5.2.1 (FreeBSD)
Copyright 2002 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "i386-undermydesk-freebsd"...
panic: bremfree: removing a buffer not on a queue
panic messages:
---
panic: softdep_disk_io_initiation: read
cpuid = 0; lapic.id = 00000000
boot() called on cpu#0
syncing disks, buffers remaining... panic: bremfree: removing a buffer not on a queue
cpuid = 0; lapic.id = 00000000
boot() called on cpu#0
Uptime: 7m37s
Dumping 255 MB
ata0: resetting devices ..
done
16 32 48 64 80 96 112 128 144 160 176 192 208 224 240
---
Reading symbols from /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/vesa/vesa.ko.debug...done.
Loaded symbols for /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/vesa/vesa.ko.debug
Reading symbols from /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/linux/linux.ko.debug...done.
Loaded symbols for /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/linux/linux.ko.debug
Reading symbols from /boot/kernel/sysvshm.ko...done.
Loaded symbols for /boot/kernel/sysvshm.ko
Reading symbols from /boot/kernel/sysvsem.ko...done.
Loaded symbols for /boot/kernel/sysvsem.ko
Reading symbols from /boot/kernel/sysvmsg.ko...done.
Loaded symbols for /boot/kernel/sysvmsg.ko
Reading symbols from /boot/kernel/if_xl.ko...done.
Loaded symbols for /boot/kernel/if_xl.ko
Reading symbols from /boot/kernel/miibus.ko...done.
Loaded symbols for /boot/kernel/miibus.ko
Reading symbols from /boot/kernel/snd_pcm.ko...done.
Loaded symbols for /boot/kernel/snd_pcm.ko
Reading symbols from /boot/kernel/snd_ich.ko...done.
Loaded symbols for /boot/kernel/snd_ich.ko
Reading symbols from /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/random/random.ko.debug...done.
Loaded symbols for /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/random/random.ko.debug
Reading symbols from /boot/kernel/ahc.ko...done.
Loaded symbols for /boot/kernel/ahc.ko
Reading symbols from /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/fdc/fdc.ko.debug...done.
Loaded symbols for /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/fdc/fdc.ko.debug
Reading symbols from /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/acpi/acpi.ko.debug...done.
Loaded symbols for /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/acpi/acpi.ko.debug
Reading symbols from /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/nfsclient/nfsclient.ko.debug...done.
Loaded symbols for /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/nfsclient/nfsclient.ko.debug
Reading symbols from /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/nfsserver/nfsserver.ko.debug...done.
Loaded symbols for /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/nfsserver/nfsserver.ko.debug
Reading symbols from /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/usb/usb.ko.debug...done.
Loaded symbols for /usr/src/sys/i386/compile/PANCAKE/modules/usr/src/sys/modules/usb/usb.ko.debug
#0 doadump () at ../../../kern/kern_shutdown.c:239
239 dumping++;
(kgdb) bt full
#0 doadump () at ../../../kern/kern_shutdown.c:239
No locals.
#1 0xc0191b81 in boot (howto=260) at ../../../kern/kern_shutdown.c:371
No locals.
#2 0xc0191ed0 in poweroff_wait (junk=0xc02e351b, howto=1) at ../../../kern/kern_shutdown.c:542
td = (struct thread *) 0xc0eca0f0
bootopt = 260
buf = "bremfree: removing a buffer not on a queue", '\0' <repeats 213 times>
#3 0xc01d1600 in bremfreel (bp=0xc02e351b) at ../../../kern/vfs_bio.c:636
old_qindex = 260
#4 0xc01d1513 in bremfree (bp=0x0) at ../../../kern/vfs_bio.c:618
No locals.
#5 0xc01d35cd in vfs_bio_awrite (bp=0x104) at ../../../kern/vfs_bio.c:1687
i = 1
j = 0
lblkno = 26
vp = (struct vnode *) 0xc0eca0f0
ncl = -1070713573
nwritten = -1070713573
size = 8192
maxcl = 16
#6 0xc025b622 in ffs_fsync (ap=0xcd2999cc) at ../../../ufs/ffs/ffs_vnops.c:255
vp = (struct vnode *) 0xc2cbe36c
ip = (struct inode *) 0xc77c9400
bp = (struct buf *) 0xc77c9400
nbp = (struct buf *) 0xc779ad80
error = 0
wait = 0
passes = 4
skipmeta = 0
lbn = 38
#7 0xc025a709 in ffs_sync (mp=0xc269b600, waitfor=2, cred=0xc0eb5e80, td=0xc02fd5c0)
at vnode_if.h:612
nvp = (struct vnode *) 0xc2cbe248
vp = (struct vnode *) 0xc2cbe36c
devvp = (struct vnode *) 0xc2cbe36c
ip = (struct inode *) 0x0
ump = (struct ufsmount *) 0xc2667c00
fs = (struct fs *) 0xc2727800
error = 0
count = 0
wait = 0
lockreq = 18
allerror = 0
#8 0xc01e866b in sync (td=0xc02fd5c0, uap=0x0) at ../../../kern/vfs_syscalls.c:138
mp = (struct mount *) 0xc269b600
nmp = (struct mount *) 0x0
asyncflag = 0
#9 0xc0191697 in boot (howto=256) at ../../../kern/kern_shutdown.c:280
bp = (struct buf *) 0xc0ec7000
iter = 4
nbusy = 0
pbusy = 1
subiter = 0
#10 0xc0191ed0 in poweroff_wait (junk=0xc02ea540, howto=-1071835885)
at ../../../kern/kern_shutdown.c:542
td = (struct thread *) 0xc0eca0f0
bootopt = 256
buf = "bremfree: removing a buffer not on a queue", '\0' <repeats 213 times>
#11 0xc0253a2c in softdep_disk_io_initiation (bp=0xc0eca0f0) at ../../../ufs/ffs/ffs_softdep.c:3465
wk = (struct worklist *) 0xc02ea540
nextwk = (struct worklist *) 0xc773acf0
indirdep = (struct indirdep *) 0x100
inodedep = (struct inodedep *) 0x0
#12 0xc01da24d in cluster_wbuild (vp=0xc2cbe36c, size=8192, start_lbn=26, len=6) at buf.h:422
bp = (struct buf *) 0xc7720468
tbp = (struct buf *) 0xc77c9400
i = 5
j = 2
totalwritten = 0
dbsize = 16
---Type <return> to continue, or q <return> to quit---
#13 0xc01d35c3 in vfs_bio_awrite (bp=0xc77683f8) at ../../../kern/vfs_bio.c:1681
i = 6
j = 0
lblkno = 21
vp = (struct vnode *) 0xc2cbe36c
ncl = 6
nwritten = 6
size = 8192
maxcl = 16
#14 0xc025b622 in ffs_fsync (ap=0xcd299c18) at ../../../ufs/ffs/ffs_vnops.c:255
vp = (struct vnode *) 0xc2cbe36c
ip = (struct inode *) 0xc77683f8
bp = (struct buf *) 0xc77683f8
nbp = (struct buf *) 0xc77388d8
error = 0
wait = 0
passes = 4
skipmeta = 0
lbn = 38
#15 0xc025a709 in ffs_sync (mp=0xc269b600, waitfor=3, cred=0xc0eb5e80, td=0xc0eca0f0)
at vnode_if.h:612
nvp = (struct vnode *) 0xc2cbe248
vp = (struct vnode *) 0xc2cbe36c
devvp = (struct vnode *) 0xc2cbe36c
ip = (struct inode *) 0x0
ump = (struct ufsmount *) 0xc2667c00
fs = (struct fs *) 0xc2727800
error = 0
count = -1072152611
wait = 0
lockreq = 18
allerror = 0
#16 0xc01e7dea in sync_fsync (ap=0xcd299cc4) at ../../../kern/vfs_subr.c:3493
syncvp = (struct vnode *) 0x0
mp = (struct mount *) 0xc269b600
td = (struct thread *) 0xc0eca0f0
error = -852910908
asyncflag = 0
#17 0xc01e40ab in sched_sync () at vnode_if.h:612
slp = (struct synclist *) 0xcd299cc4
vp = (struct vnode *) 0x0
mp = (struct mount *) 0x0
starttime = 1052481081
td = (struct thread *) 0xc0eca0f0
#18 0xc017c793 in fork_exit (callout=0xc01e3ed0 <sched_sync>, arg=0x0, frame=0x0)
at ../../../kern/kern_fork.c:875
td = (struct thread *) 0x0
p = (struct proc *) 0xc25eb400
(kgdb)
22:25:47.890909 192.168.100.1.1128420554 > 192.168.100.44.2049: 136 lookup [|nfs]
4500 00a4 16d8 0000 4011 0000 c0a8 6401
c0a8 642c 03ea 0801 0090 d8cc 4342 54ca
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0003 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
22:25:47.891179 192.168.100.44.2049 > 192.168.100.1.1128420554: reply ok 116 lookup ERROR: No such file or directo
ry
4500 0090 9b2b 0000 4011 95b3 c0a8 642c
c0a8 6401 0801 03ea 007c 8f1b 4342 54ca
0000 0001 0000 0000 0000 0000 0000 0000
0000 0000 0000 0002 0000 0001 0000 0002
0000 01ed 0000 0002 0000 00cc 0000 0000
0000
22:25:47.891542 192.168.100.1.1128420555 > 192.168.100.44.2049: 124 access [|nfs]
4500 0098 16d9 0000 4011 0000 c0a8 6401
c0a8 642c 03ea 0801 0084 998f 4342 54cb
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0004 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
22:25:47.891806 192.168.100.44.2049 > 192.168.100.1.1128420555: reply ok 120 access c 4342536b
4500 0094 9b2c 0000 4011 95ae c0a8 642c
c0a8 6401 0801 03ea 0080 6759 4342 54cb
0000 0001 0000 0000 0000 0000 0000 0000
0000 0000 0000 0000 0000 0001 0000 0001
0000 01a4 0000 0001 0000 00cc 0000 0000
0000
22:25:54.212203 192.168.100.1.1128420556 > 192.168.100.44.2049: 132 commit [|nfs]
4500 00a0 1772 0000 4011 0000 c0a8 6401
c0a8 642c 03e5 0801 008c 755f 4342 54cc
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0015 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
22:25:54.625787 192.168.100.1.1128420557 > 192.168.100.44.2049: 124 access [|nfs]
4500 0098 1777 0000 4011 0000 c0a8 6401
c0a8 642c 03e5 0801 0084 5704 4342 54cd
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0004 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
22:25:54.671795 192.168.100.1.1128420557 > 192.168.100.44.2049: 124 access [|nfs]
4500 0098 1778 0000 4011 0000 c0a8 6401
c0a8 642c 03e5 0801 0084 5704 4342 54cd
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0004 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
22:25:54.761721 192.168.100.1.1128420557 > 192.168.100.44.2049: 124 access [|nfs]
4500 0098 1779 0000 4011 0000 c0a8 6401
c0a8 642c 03e5 0801 0084 5704 4342 54cd
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0004 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
22:25:54.931739 192.168.100.1.1128420557 > 192.168.100.44.2049: 124 access [|nfs]
4500 0098 177e 0000 4011 0000 c0a8 6401
c0a8 642c 03e5 0801 0084 5704 4342 54cd
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0004 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
22:25:55.261827 192.168.100.1.1128420557 > 192.168.100.44.2049: 124 access [|nfs]
4500 0098 1783 0000 4011 0000 c0a8 6401
c0a8 642c 03e5 0801 0084 5704 4342 54cd
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0004 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
22:25:55.911853 192.168.100.1.1128420557 > 192.168.100.44.2049: 124 access [|nfs]
4500 0098 17b9 0000 4011 0000 c0a8 6401
c0a8 642c 03e5 0801 0084 5704 4342 54cd
0000 0000 0000 0002 0001 86a3 0000 0003
0000 0004 0000 0001 0000 0030 0000 0000
0000 0000 0000 0000 0000 0000 0000 0007
0000
>How-To-Repeat:
>Fix:
>Release-Note:
>Audit-Trail:
>Unformatted:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200305141149.h4EBnHve049499>