Re: kern/48277: Booting under KVM yields panic: siop_intr: I shouldn't be there !

[Andreas Gustafsson <gson%gson.org@localhost>]

David Holland wrote:
>  It looks like building with SIOP_DEBUG_INTR might provide some further
>  information. FWIW. And if you're going to go to the trouble there also
>  appears to be SIOP_DEBUG.

I enabled SIOP_DEBUG_INTR and SIOP_DEBUG in esiop.c, and to simplify
the extraction of the kernel messages, I also changed the panic() into
a printf() followed by "return 1;".  The full dmesg output follows.
-- 
Andreas Gustafsson, gson%gson.org@localhost

Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007, 2008, 2009, 2010, 2011, 2012
    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 6.1.2 (GENERIC) #1: Sun Oct  6 12:28:46 EEST 2013
        
gson%guido.araneus.fi@localhost:/bracket/prod2/6.1.2-RELEASE/obj/sys/arch/amd64/compile/GENERIC
total memory = 1023 MB
avail memory = 978 MB
timecounter: Timecounters tick every 10.000 msec
timecounter: Timecounter "i8254" frequency 1193182 Hz quality 100
Bochs Bochs
mainbus0 (root)
forcing PCI mode 1 for QEMU
cpu0 at mainbus0 apid 0: QEMU Virtual CPU version 1.0, id 0x623
ioapic0 at mainbus0 apid 1: pa 0xfec00000, version 11, 24 pins
acpi0 at mainbus0: Intel ACPICA 20110623
acpi0: X/RSDT: OemId <BOCHS ,BXPCRSDT,00000001>, AslId <BXPC,00000001>
LNKS: ACPI: Found matching pin for 0.1.INTA at func 3: 9
LNKD: ACPI: Found matching pin for 0.1.INTD at func 2: 11
LNKC: ACPI: Found matching pin for 0.3.INTA at func 0: 11
LNKD: ACPI: Found matching pin for 0.4.INTA at func 0: 11
LNKB: ACPI: Found matching pin for 0.6.INTA at func 0: 10
acpi0: SCI interrupting at int 9
timecounter: Timecounter "ACPI-Safe" frequency 3579545 Hz quality 900
hpet0 at acpi0: high precision event timer (mem 0xfed00000-0xfed00400)
timecounter: Timecounter "hpet0" frequency 100000000 Hz quality 2000
pckbc1 at acpi0 (KBD, PNP0303) (kbd port): io 0x60,0x64 irq 1
pckbc2 at acpi0 (MOU, PNP0F13) (aux port): irq 12
FDC0 (PNP0700) at acpi0 not configured
pckbd0 at pckbc1 (kbd slot)
pckbc1: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard
pms0 at pckbc1 (aux slot)
pckbc1: using irq 12 for aux slot
wsmouse0 at pms0 mux 0
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: vendor 0x8086 product 0x1237 (rev. 0x02)
pcib0 at pci0 dev 1 function 0: vendor 0x8086 product 0x7000 (rev. 0x00)
piixide0 at pci0 dev 1 function 1: Intel 82371SB IDE Interface (PIIX3) (rev. 
0x00)
piixide0: bus-master DMA support present
piixide0: primary channel wired to compatibility mode
piixide0: primary channel interrupting at ioapic0 pin 14
atabus0 at piixide0 channel 0
piixide0: secondary channel wired to compatibility mode
piixide0: secondary channel interrupting at ioapic0 pin 15
atabus1 at piixide0 channel 1
uhci0 at pci0 dev 1 function 2: vendor 0x8086 product 0x7020 (rev. 0x01)
uhci0: interrupting at ioapic0 pin 11
usb0 at uhci0: USB revision 1.0
piixpm0 at pci0 dev 1 function 3: vendor 0x8086 product 0x7113 (rev. 0x03)
timecounter: Timecounter "piixpm0" frequency 3579545 Hz quality 1000
piixpm0: 24-bit timer
piixpm0: LNKS: _SRS failed: AE_NOT_FOUND
interrupting at ioapic0 pin 9
iic0 at piixpm0: I2C bus
vga0 at pci0 dev 2 function 0: vendor 0x1013 product 0x00b8 (rev. 0x00)
wsdisplay0 at vga0 kbdmux 1: console (80x25, vt100 emulation), using wskbd0
wsmux1: connecting to wsdisplay0
drm at vga0 not configured
virtio0 at pci0 dev 3 function 0
virtio0: Virtio Network Device (rev. 0x00)
vioif0 at virtio0: Ethernet address 52:54:00:f8:0c:5e
virtio0: allocated 20480 byte for virtqueue 0 for rx, size 256
virtio0: using 8192 byte (512 entries) indirect descriptors
virtio0: allocated 81920 byte for virtqueue 1 for tx, size 256
virtio0: using 69632 byte (4352 entries) indirect descriptors
virtio0: allocated 8192 byte for virtqueue 2 for control, size 64
virtio0: interrupting at ioapic0 pin 11
esiop0 at pci0 dev 4 function 0: Symbios Logic 53c895a (ultra2-wide scsi)
esiop0: using on-board RAM
esiop0: interrupting at ioapic0 pin 11
esiop0: alloc new tag DSA table at PHY addr 0x2f68000
esiop0: target table offset 724 free offset 740
scsibus0 at esiop0: 16 targets, 8 luns per target
virtio1 at pci0 dev 6 function 0
virtio1: Virtio Memory Balloon Device (rev. 0x00)
viomb0 at virtio1
virtio1: allocated 8192 byte for virtqueue 0 for inflate, size 128
virtio1: allocated 8192 byte for virtqueue 1 for deflate, size 128
virtio1: interrupting at ioapic0 pin 10
isa0 at pcib0
attimer0 at isa0 port 0x40-0x43
pcppi0 at isa0 port 0x61
midi0 at pcppi0: PC speaker
sysbeep0 at pcppi0
fdc0 at isa0 port 0x3f0-0x3f7 irq 6 drq 2
attimer0: attached to pcppi0
acpicpu0 at cpu0: ACPI CPU
acpicpu0: C1: HLT, lat   0 us, pow     0 mW
interrupt, istat=0x1 tflags=0x0 DSA=0x0 DSP=0x50
siop_intr: I shouldn't be there !
timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
scsibus0: waiting 2 seconds for devices to settle...
uhub0 at usb0: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
esiop0 grow resources (0)
tables[0]: in=0x31e9010 out=0x31e9000 status=0x31e9020
tables[1]: in=0x31e9100 out=0x31e90f0 status=0x31e9110
tables[2]: in=0x31e91f0 out=0x31e91e0 status=0x31e9200
tables[3]: in=0x31e92e0 out=0x31e92d0 status=0x31e92f0
tables[4]: in=0x31e93d0 out=0x31e93c0 status=0x31e93e0
tables[5]: in=0x31e94c0 out=0x31e94b0 status=0x31e94d0
tables[6]: in=0x31e95b0 out=0x31e95a0 status=0x31e95c0
tables[7]: in=0x31e96a0 out=0x31e9690 status=0x31e96b0
tables[8]: in=0x31e9790 out=0x31e9780 status=0x31e97a0
tables[9]: in=0x31e9880 out=0x31e9870 status=0x31e9890
tables[10]: in=0x31e9970 out=0x31e9960 status=0x31e9980
tables[11]: in=0x31e9a60 out=0x31e9a50 status=0x31e9a70
tables[12]: in=0x31e9b50 out=0x31e9b40 status=0x31e9b60
tables[13]: in=0x31e9c40 out=0x31e9c30 status=0x31e9c50
tables[14]: in=0x31e9d30 out=0x31e9d20 status=0x31e9d40
tables[15]: in=0x31e9e20 out=0x31e9e10 status=0x31e9e30
tables[16]: in=0x31e9f10 out=0x31e9f00 status=0x31e9f20
esiop0: alloc siop_target for target 0
esiop0: lun table for target 0 offset 740 free offset 758
interrupt, istat=0x2 tflags=0x3 DSA=0x31e9000 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9000 DSP=0x3d0
esiop_intr end: status 255
esiop0:0:0: free lun sw entry
esiop0: alloc siop_target for target 1
esiop0: lun table for target 1 offset 758 free offset 776
cd0 at scsibus0 target 1 lun 0: <QEMU, QEMU CD-ROM, 1.0> cdrom removable
interrupt, istat=0x1 tflags=0x103 DSA=0x31e92d0 DSP=0x270
script interrupt 0xff00
done, DSA=0x31e92d0 target id 0x7010000 last msg in=0x0 status=0x2
esiop_intr end: status 2
interrupt, istat=0x2 tflags=0x10b DSA=0x31e93c0 DSP=0x5b8
scsi interrupt, sist=0x80 sstat1=0x3 DSA=0x31e93c0 DSP=0x5b8
interrupt, istat=0x1 tflags=0x103 DSA=0x31e94b0 DSP=0x270
script interrupt 0xff00
done, DSA=0x31e94b0 target id 0x7010000 last msg in=0x0 status=0x2
esiop_intr end: status 2
interrupt, istat=0x2 tflags=0x10b DSA=0x31e95a0 DSP=0x5b8
scsi interrupt, sist=0x80 sstat1=0x3 DSA=0x31e95a0 DSP=0x5b8
esiop0: alloc siop_target for target 2
esiop0: lun table for target 2 offset 776 free offset 794
interrupt, istat=0x2 tflags=0x203 DSA=0x31e9690 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9690 DSP=0x3d0
esiop_intr end: status 255
esiop0:2:0: free lun sw entry
esiop0: alloc siop_target for target 3
esiop0: lun table for target 3 offset 794 free offset 812
interrupt, istat=0x2 tflags=0x303 DSA=0x31e9780 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9780 DSP=0x3d0
esiop_intr end: status 255
esiop0:3:0: free lun sw entry
esiop0: alloc siop_target for target 4
esiop0: lun table for target 4 offset 812 free offset 830
interrupt, istat=0x2 tflags=0x403 DSA=0x31e9870 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9870 DSP=0x3d0
esiop_intr end: status 255
esiop0:4:0: free lun sw entry
esiop0: alloc siop_target for target 5
esiop0: lun table for target 5 offset 830 free offset 848
interrupt, istat=0x2 tflags=0x503 DSA=0x31e9960 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9960 DSP=0x3d0
esiop_intr end: status 255
esiop0:5:0: free lun sw entry
esiop0: alloc siop_target for target 6
esiop0: lun table for target 6 offset 848 free offset 866
interrupt, istat=0x2 tflags=0x603 DSA=0x31e9a50 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9a50 DSP=0x3d0
esiop_intr end: status 255
esiop0:6:0: free lun sw entry
esiop0: alloc siop_target for target 8
esiop0: lun table for target 8 offset 866 free offset 884
interrupt, istat=0x2 tflags=0x803 DSA=0x31e9b40 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9b40 DSP=0x3d0
esiop_intr end: status 255
esiop0:8:0: free lun sw entry
esiop0: alloc siop_target for target 9
esiop0: lun table for target 9 offset 884 free offset 902
interrupt, istat=0x2 tflags=0x903 DSA=0x31e9c30 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9c30 DSP=0x3d0
esiop_intr end: status 255
esiop0:9:0: free lun sw entry
esiop0: alloc siop_target for target 10
esiop0: lun table for target 10 offset 902 free offset 920
interrupt, istat=0x2 tflags=0xa03 DSA=0x31e9d20 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9d20 DSP=0x3d0
esiop_intr end: status 255
esiop0:10:0: free lun sw entry
esiop0: alloc siop_target for target 11
esiop0: lun table for target 11 offset 920 free offset 938
interrupt, istat=0x2 tflags=0xb03 DSA=0x31e9e10 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9e10 DSP=0x3d0
esiop_intr end: status 255
esiop0:11:0: free lun sw entry
esiop0: alloc siop_target for target 12
esiop0: lun table for target 12 offset 938 free offset 956
interrupt, istat=0x2 tflags=0xc03 DSA=0x31e9f00 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9f00 DSP=0x3d0
esiop_intr end: status 255
esiop0:12:0: free lun sw entry
esiop0: alloc siop_target for target 13
esiop0: lun table for target 13 offset 956 free offset 974
interrupt, istat=0x2 tflags=0xd03 DSA=0x31e9000 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e9000 DSP=0x3d0
esiop_intr end: status 255
esiop0:13:0: free lun sw entry
esiop0: alloc siop_target for target 14
esiop0: lun table for target 14 offset 974 free offset 992
interrupt, istat=0x2 tflags=0xe03 DSA=0x31e90f0 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e90f0 DSP=0x3d0
esiop_intr end: status 255
esiop0:14:0: free lun sw entry
esiop0: alloc siop_target for target 15
esiop0: lun table for target 15 offset 992 free offset 1010
interrupt, istat=0x2 tflags=0xf03 DSA=0x31e91e0 DSP=0x3d0
scsi interrupt, sist=0x400 sstat1=0x0 DSA=0x31e91e0 DSP=0x3d0
esiop_intr end: status 255
esiop0:15:0: free lun sw entry
wd0 at atabus0 drive 0
wd0: <QEMU HARDDISK>
wd0: drive supports 16-sector PIO transfers, LBA48 addressing
wd0: 12288 MB, 24966 cyl, 16 head, 63 sec, 512 bytes/sect x 25165824 sectors
wd0: 32-bit data port
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd0(piixide0:0:0): using PIO mode 4, DMA mode 2 (using DMA)
Kernelized RAIDframe activated
pad0: outputs: 44100Hz, 16-bit, stereo
audio0 at pad0: half duplex, playback, capture
boot device: wd0
root on wd0a dumps on wd0b
root file system type: ffs
wsdisplay0: screen 1 added (80x25, vt100 emulation)
wsdisplay0: screen 2 added (80x25, vt100 emulation)
wsdisplay0: screen 3 added (80x25, vt100 emulation)
wsdisplay0: screen 4 added (80x25, vt100 emulation)