Subject: kern/37172: VNODE_LOCKDEBUG kernel panics with vop_read: vp: locked 0, expected 1
To: None <kern-bug-people@netbsd.org, gnats-admin@netbsd.org,>
From: None <scotte@warped.com>
List: netbsd-bugs
Date: 10/22/2007 03:55:01
>Number:         37172
>Category:       kern
>Synopsis:       Booting a kernel with CNODE_LOCKDEBUG causes a panic at init access
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Oct 22 03:55:00 +0000 2007
>Originator:     Scott Ellis
>Release:        NetBSD 4.99.34
>Organization:
	
>Environment:
	
	
System: NetBSD intrepid 4.99.34 NetBSD 4.99.34 (INTREPID.NEWBOX) #2: Sun Oct 21 18:39:46 PDT 2007 scotte@intrepid:/nbu/source/netbsd/src/obj.amd64/nbu/source/netbsd/src/sys/arch/amd64/compile/INTREPID.NEWBOX amd64
Architecture: x86_64
Machine: amd64
>Description:
	
Building a debug version of my normal kernel (which works more-or-less fine)
halts on boot with:

[snip]
raid0: configured ok
boot device: raid0
root on raid0a dumps on raid0b
mountroot: trying ffs...
root file system type: ffs
init: copying out path `/sbin/init' 11
panic: vop_read: vp: locked 0, expected 1
Stopped in pid 1.1 (init) at    netbsd:breakpoint+0x1:  ret
db{0}> bt
breakpoint() at netbsd:breakpoint+0x1
panic() at netbsd:panic+0x1bd
VOP_READ() at netbsd:VOP_READ+0x78
vn_rdwr() at netbsd:vn_rdwr+0xc6
check_exec() at netbsd:check_exec+0x1db
execve1() at netbsd:execve1+0x183
sys_execve() at netbsd:sys_execve+0x43
start_init() at netbsd:start_init+0x3e3

>How-To-Repeat:
	
I can just boot a kernel with DIAGNOSTIC, DEBUG, LOCKDEBUG, and VNODE_DEBUG.
Full dmesg is as follows:

>> NetBSD/x86 BIOS Boot, Revision 3.3
>> (scotte@intrepid, Sun Oct  7 11:24:49 PDT 2007)
>> Memory: 639/2095744 k
Press return to boot now, any other key for boot menu
booting hd0a:netbsd - starting in 0
4263600+71680+472048 [328248+205731]=0x618750
kernel text is mapped with 3 large pages and 17 normal pages
Loaded initial symtab at 0xffffffff80695bf0, strtab at 0xffffffff806e63a8, # entries 13660
Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007
    The NetBSD Foundation, Inc.  All rights reserved.
Copyright (c) 1982, 1986, 1989, 1991, 1993
    The Regents of the University of California.  All rights reserved.

NetBSD 4.99.34 (INTREPID.NEWBOX.DEBUG) #2: Sun Oct 21 18:41:33 PDT 2007
        scotte@intrepid:/nbu/source/netbsd/src/obj.amd64/nbu/source/netbsd/src/sys/arch/amd64/compile/INTREPID.NEWBOX.DEBUG
total memory = 2047 MB
avail memory = 1967 MB
mainbus0 (root)
cpu0 at mainbus0 apid 0: (boot processor)
cpu0: Intel(R) Core(TM)2 CPU          6600  @ 2.40GHz, 2404.20 MHz
cpu1 at mainbus0 apid 1: (application processor)
cpu1: Intel(R) Core(TM)2 CPU          6600  @ 2.40GHz, 2404.11 MHz
ioapic0 at mainbus0 apid 2
acpi0 at mainbus0: Advanced Configuration and Power Interface
ACPI-Fast 24-bit timer
CPU1 (ACPI Object Type 'Processor' [0x0c]) at acpi0 not configured
CPU2 (ACPI Object Type 'Processor' [0x0c]) at acpi0 not configured
CPU3 (ACPI Object Type 'Processor' [0x0c]) at acpi0 not configured
CPU4 (ACPI Object Type 'Processor' [0x0c]) at acpi0 not configured
PCI0 (PNP0A08) at acpi0 not configured
MCH (PNP0C01) at acpi0 not configured
PIC (PNP0000) at acpi0 not configured
DMAD (PNP0200) at acpi0 not configured
attimer0 at acpi0 (TMR, PNP0100): AT Timer
attimer0: io 0x40-0x43 irq 0
RTC0 (PNP0B00) at acpi0 not configured
pcppi0 at acpi0 (SPKR, PNP0800)
pcppi0: io 0x61
sysbeep0 at pcppi0
COPR (PNP0C04) at acpi0 not configured
fdc0 at acpi0 (FDC, PNP0700)
fdc0: io 0x3f0-0x3f5,0x3f7 irq 6 drq 2
fdc0: expected BUFFER, got 4
SIOR (PNP0C02) at acpi0 not configured
RMSC (PNP0C02) at acpi0 not configured
hpet0 at acpi0 (HPET, PNP0103)
hpet0: mem 0xfed00000-0xfed003ff
hpet0: Found 64-bits HPET, will only use lowest 32-bits
aiboost0 at acpi0 (ASOC, ATK0110-16843024)
aiboost0: ASUS AI Boost Hardware monitor
OMSC (PNP0C02) at acpi0 not configured
com0 at acpi0 (UAR1, PNP0501-1)
com0: io 0x3f8-0x3ff irq 4
com: ns16550a, working fifo
com0: console
PCIE (PNP0C02) at acpi0 not configured
RMEM (PNP0C01) at acpi0 not configured
acpibut0 at acpi0 (PWRB, PNP0C0C-170): ACPI Power Button
LNKA (PNP0C0F) at acpi0 not configured
LNKB (PNP0C0F) at acpi0 not configured
LNKC (PNP0C0F) at acpi0 not configured
LNKD (PNP0C0F) at acpi0 not configured
LNKE (PNP0C0F) at acpi0 not configured
LNKF (PNP0C0F) at acpi0 not configured
LNKG (PNP0C0F) at acpi0 not configured
LNKH (PNP0C0F) at acpi0 not configured
pcppi0: attached to attimer0
pci0 at mainbus0 bus 0: configuration mode 1
pci0: i/o space, memory space enabled, rd/line, rd/mult, wr/inv ok
pchb0 at pci0 dev 0 function 0
pchb0: vendor 0x8086 product 0x277c (rev. 0xc0)
ppb0 at pci0 dev 1 function 0: vendor 0x8086 product 0x277d (rev. 0xc0)
pci1 at ppb0 bus 6
pci1: memory space enabled, rd/line, wr/inv ok
azalia0 at pci0 dev 27 function 0: Generic High Definition Audio Controller
azalia0: interrupting at ioapic0 pin 19 (irq 5)
azalia0: host: 0x8086/0x27d8 (rev. 1)
azalia0: host: High Definition Audio rev. 1.0
ppb1 at pci0 dev 28 function 0: vendor 0x8086 product 0x27d0 (rev. 0x01)
pci2 at ppb1 bus 5
pci2: memory space enabled, rd/line, wr/inv ok
ppb2 at pci0 dev 28 function 3: vendor 0x8086 product 0x27d6 (rev. 0x01)
pci3 at ppb2 bus 4
pci3: i/o space, memory space enabled, rd/line, wr/inv ok
mskc0 at pci3 dev 0 function 0, Yukon-2 EC rev. A3 (0x2): ioapic0 pin 19 (irq 5)
msk0 at mskc0 port A: Ethernet address 00:1b:fc:03:ee:42
makphy0 at msk0 phy 0: Marvell 88E1111 Gigabit PHY, rev. 2
makphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-FDX, auto
ppb3 at pci0 dev 28 function 4: vendor 0x8086 product 0x27e0 (rev. 0x01)
pci4 at ppb3 bus 3
pci4: i/o space, memory space enabled, rd/line, wr/inv ok
mskc1 at pci4 dev 0 function 0, Yukon-2 EC rev. A3 (0x2): ioapic0 pin 16 (irq 11)
msk1 at mskc1 port A: Ethernet address 00:1b:fc:03:e3:60
makphy1 at msk1 phy 0: Marvell 88E1111 Gigabit PHY, rev. 2
makphy1: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-FDX, auto
ppb4 at pci0 dev 28 function 5: vendor 0x8086 product 0x27e2 (rev. 0x01)
pci5 at ppb4 bus 2
pci5: i/o space, memory space enabled, rd/line, wr/inv ok
jmide0 at pci5 dev 0 function 0: vendor 0x197b product 0x2363
jmide0: 1 PATA port, 2 SATA ports
jmide0: interrupting at ioapic0 pin 17 (irq 10)
ahcisata0 at jmide0
ahcisata0: AHCI revision 1.0, 2 ports, 32 command slots, features 0xc722e000
atabus0 at ahcisata0 channel 0
atabus1 at ahcisata0 channel 1
jmide1 at pci5 dev 0 function 1: vendor 0x197b product 0x2363
jmide1: 1 PATA port, 2 SATA ports
jmide1: interrupting at ioapic0 pin 18 (irq 0)
jmide1: PCI IDE interface used
jmide1: device disabled (at device)
uhci0 at pci0 dev 29 function 0: vendor 0x8086 product 0x27c8 (rev. 0x01)
uhci0: interrupting at ioapic0 pin 20 (irq 7)
usb0 at uhci0: USB revision 1.0
usbd_get_string: getting lang failed, using 0
uhub0 at usb0
uhub0: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhci1 at pci0 dev 29 function 1: vendor 0x8086 product 0x27c9 (rev. 0x01)
uhci1: interrupting at ioapic0 pin 17 (irq 10)
usb1 at uhci1: USB revision 1.0
usbd_get_string: getting lang failed, using 0
uhub1 at usb1
uhub1: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhci2 at pci0 dev 29 function 2: vendor 0x8086 product 0x27ca (rev. 0x01)
uhci2: interrupting at ioapic0 pin 18 (irq 10)
usb2 at uhci2: USB revision 1.0
usbd_get_string: getting lang failed, using 0
uhub2 at usb2
uhub2: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhci3 at pci0 dev 29 function 3: vendor 0x8086 product 0x27cb (rev. 0x01)
uhci3: interrupting at ioapic0 pin 19 (irq 5)
usb3 at uhci3: USB revision 1.0
usbd_get_string: getting lang failed, using 0
uhub3 at usb3
uhub3: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub3: 2 ports with 2 removable, self powered
ehci0 at pci0 dev 29 function 7: vendor 0x8086 product 0x27cc (rev. 0x01)
ehci0: interrupting at ioapic0 pin 20 (irq 7)
ehci0: companion controllers, 2 ports each: uhci0 uhci1 uhci2 uhci3
usb4 at ehci0: USB revision 2.0
usbd_get_string: getting lang failed, using 0
uhub4 at usb4
uhub4: vendor 0x8086 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub4: 8 ports with 8 removable, self powered
ppb5 at pci0 dev 30 function 0: vendor 0x8086 product 0x244e (rev. 0xe1)
pci6 at ppb5 bus 1
pci6: i/o space, memory space enabled
ex0 at pci6 dev 0 function 0: 3Com 3c905B-TX 10/100 Ethernet (rev. 0x30)
ex0: interrupting at ioapic0 pin 21 (irq 5)
ex0: MAC address 00:50:04:78:77:9c
exphy0 at ex0 phy 24: 3Com internal media interface
exphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
vendor 0x102b product 0x051b (VGA display) at pci6 dev 1 function 0 not configured
ichlpcib0 at pci0 dev 31 function 0
ichlpcib0: vendor 0x8086 product 0x27b8 (rev. 0x01)
ichlpcib0: 24-bit timer
piixide0 at pci0 dev 31 function 1
piixide0: Intel 82801GB/GR IDE Controller (ICH7) (rev. 0x01)
piixide0: primary channel interrupting at ioapic0 pin 14 (irq 14)
atabus2 at piixide0 channel 0
piixide0: secondary channel interrupting at ioapic0 pin 15 (irq 15)
atabus3 at piixide0 channel 1
ahcisata1 at pci0 dev 31 function 2: vendor 0x8086 product 0x27c1
ahcisata1: interrupting at ioapic0 pin 23 (irq 11)
ahcisata1: AHCI revision 1.1, 4 ports, 32 command slots, features 0xc320e000
atabus4 at ahcisata1 channel 0
atabus5 at ahcisata1 channel 1
atabus6 at ahcisata1 channel 2
atabus7 at ahcisata1 channel 3
ichsmb0 at pci0 dev 31 function 3: vendor 0x8086 product 0x27da (rev. 0x01)
ichsmb0: interrupting at ioapic0 pin 23 (irq 0)
iic0 at ichsmb0: I2C bus
iic0: devices at 0x22 0x44 0x50 0x52 0x69 0x6e
spdmem0 at iic0 addr 0x50
spdmem0: DDR2 SDRAM memory, no parity or ECC, 1024MB, 800MHz, PC2-6400
spdmem1 at iic0 addr 0x52
spdmem1: DDR2 SDRAM memory, no parity or ECC, 1024MB, 800MHz, PC2-6400
isa0 at ichlpcib0
ahcisata0 port 1: device present, speed: 3.0Gb/s
ahcisata1 port 0: device present, speed: 3.0Gb/s
ahcisata1 port 1: device present, speed: 3.0Gb/s
ehci0: handing over full speed device on port 3 to uhci1
wd0 at atabus1 drive 0: <WDC WD5000YS-01MPB0>
wd0: 465 GB, 969021 cyl, 16 head, 63 sec, 512 bytes/sect x 976773168 sectors
wd1 at atabus4 drive 0: <WDC WD5000YS-01MPB1>
wd1: 465 GB, 969021 cyl, 16 head, 63 sec, 512 bytes/sect x 976773168 sectors
wd2 at atabus5 drive 0: <WDC WD5000YS-01MPB1>
wd2: 465 GB, 969021 cyl, 16 head, 63 sec, 512 bytes/sect x 976773168 sectors
uhub4: port 3, device disappeared after reset
ehci0: handing over full speed device on port 4 to uhci1
uhub4: port 4, device disappeared after reset
fd0 at fdc0 drive 0: 1.44MB, 80 cyl, 2 head, 18 sec
uplcom0 at uhub1 port 1
uplcom0: vendor 0x067b product 0x2303, rev 1.10/2.02, addr 2
ucom0 at uplcom0
ehci0: handing over full speed device on port 5 to uhci2
uhub4: port 5, device disappeared after reset
uhub5 at uhub4 port 7
uhub5: vendor 0x05e3 USB2.0 Hub, class 9/0, rev 2.00/7.02, addr 2
uhub5: single transaction translator
uhub5: 4 ports with 4 removable, self powered
uplcom1 at uhub2 port 1
uplcom1: vendor 0x067b product 0x2303, rev 1.10/2.02, addr 2
ucom1 at uplcom1
ulpt0 at uhub1 port 2 configuration 1 interface 0
ulpt0: Brother HL-1650_1670N series, rev 1.00/1.00, addr 3, iclass 7/1
ulpt0: using bi-directional mode
azalia0: codec[0]: Realtek ALC882 (rev. 1.1)
azalia0: codec[0]: High Definition Audio rev. 1.0
azalia0: playback: max channels=8, encodings=1<PCM>
azalia0: playback: PCM formats=e0560<24bit,20bit,16bit,192kHz,96kHz,48kHz,44.1kHz>
azalia0: recording: max channels=6, encodings=1<PCM>
azalia0: recording: PCM formats=60160<20bit,16bit,96kHz,48kHz,44.1kHz>
audio0 at azalia0: full duplex, independent
raidattach: Asked for 2 units
Kernelized RAIDframe activated
swwdog0: software watchdog initialized
usbd_get_string: getting lang failed, using 0
ugen0 at uhub5 port 3
ugen0: vendor 0x0bda RTL8187_Wireless, rev 2.00/1.00, addr 3
Searching for RAID components...
Component on: wd1a: 976773105
   Row: 0 Column: 0 Num Rows: 1 Num Columns: 2
   Version: 2 Serial Number: 2007101302 Mod Counter: 216
   Clean: Yes Status: 0
   sectPerSU: 64 SUsPerPU: 1 SUsPerRU: 1
   RAID Level: 1  blocksize: 512 numBlocks: 976772992
   Autoconfig: Yes
   Contains root partition: Yes
   Last configured as: raid0
Component on: wd2a: 976773105
   Row: 0 Column: 1 Num Rows: 1 Num Columns: 2
   Version: 2 Serial Number: 2007101302 Mod Counter: 216
   Clean: Yes Status: 0
   sectPerSU: 64 SUsPerPU: 1 SUsPerRU: 1
   RAID Level: 1  blocksize: 512 numBlocks: 976772992
   Autoconfig: Yes
   Contains root partition: Yes
   Last configured as: raid0
Found: wd1a at 0
Found: wd2a at 1
RAID autoconfigure
Configuring raid0:
Starting autoconfiguration of RAID set...
Looking for 0 in autoconfig
Found: wd1a at 0
Looking for 1 in autoconfig
Found: wd2a at 1
raid0: allocating 20 buffers of 32768 bytes.
raid0: RAID Level 1
raid0: Components: /dev/wd1a /dev/wd2a
raid0: Total Sectors: 976772992 (476939 MB)
raid0: configured ok
boot device: raid0
root on raid0a dumps on raid0b
mountroot: trying ffs...
root file system type: ffs
init: copying out path `/sbin/init' 11
panic: vop_read: vp: locked 0, expected 1
Stopped in pid 1.1 (init) at    netbsd:breakpoint+0x1:  ret
db{0}> bt
breakpoint() at netbsd:breakpoint+0x1
panic() at netbsd:panic+0x1bd
VOP_READ() at netbsd:VOP_READ+0x78
vn_rdwr() at netbsd:vn_rdwr+0xc6
check_exec() at netbsd:check_exec+0x1db
execve1() at netbsd:execve1+0x183
sys_execve() at netbsd:sys_execve+0x43
start_init() at netbsd:start_init+0x3e3
db{0}>

>Fix:
	
Unknown.  Booting w/o VNODE_DEBUG seems to work okay (but there could be
hidden issues).

>Unformatted: