kern/52944: Kernel panic when plugging in USB keyboard during boot (hung while probing for the graphics chip)

[dhgutteridge%sympatico.ca@localhost]

>Number:         52944
>Category:       kern
>Synopsis:       Kernel panic when plugging in USB keyboard during boot (hung while probing for the graphics chip)
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed Jan 24 06:40:00 +0000 2018
>Originator:     David H. Gutteridge
>Release:        8.0_BETA
>Organization:
>Environment:
NetBSD arcusxi.nonus-porta.net 8.0_BETA NetBSD 8.0_BETA (GENERIC.201801180820Z) amd64
>Description:
There is more than one issue I've been encountering with a particular
machine running 8.0_BETA on amd64. They may be interrelated, and they
may be unavoidable (I have no idea).

While the kernel is booting, it sometimes hangs at the point where it
reports:

drm: GMBUS [i915 gmbus dpb] timed out, falling back to bit banging on pin 5

At this point, it shows a spinning text cursor, and never progresses
beyond this point. (At least, never as long as I've left it like that,
which has been at least twenty minutes in one case.)

The first time I encountered this, I tried plugging in a USB keyboard,
which resulted in an immediate panic. I recently encountered this
again, and happened to plug in a keyboard once more, which caused a
panic with a somewhat different message. (I infer more diagnostic
code has been added recently, which captures things differently.)

The kernel from mid-December: 8.0_BETA (GENERIC.201712151410Z) amd64:

ehci0: handing over low speed device on port 1 to uhci0
uhidev0 at uhub0 port 1 configuration 1 interface 0
uhidev0: USB (0x1a2c) USB Keyboard (0x2d23), rev 1.10/1.10, addr 2, iclass 3/1
ukbd0 at uhidev0: 8 Variable keys, 6 Array codes

This port is broken, it does not call cnpollc() before calling cngetc().
This should be fixed, but it will work anyway (for now).
wskbd0 at pckbd0: console keyboard, using wsdisplay0
uhidev1 at uhub0 port 1 configuration 1 interface 1
uhidev1: USB (0x1a2c) USB Keyboard (0x2d23), rev 1.10/1.10, addr 2, iclass 3/0
panic: usbd_transfer: not done
fatal breakpoint trap in supervisor mode
trap type 1 code 0 rip 0xffffffff80224d95 cs 0x8 rflags 0x246 cr2 0 ilevel 0 rsp 0xfffffe80401b3940
curlwp 0xfffffe81071d0220 pid 0.54 lowest kstack 0xfffffe80401b02c0
Stopped in pid 0.54 (system) at netbsd:breakpoint+0x5:  leave
db{0}>

The kernel from last week: 8.0_BETA (GENERIC.201801180820Z) amd64:

ehci0: handing over low speed device on port 1 to uhci0
uhidev0 at uhub0 port 1 configuration 1 interface 0
uhidev0: USB (0x1a2c) USB Keyboard (0x2d23), rev 1.10/1.10, addr 2, iclass 3/1
ukbd0 at uhidev0: 8 Variable keys, 6 Array codes

This port is broken, it does not call cnpollc() before calling cngetc().
This should be fixed, but it will work anyway (for now).
Mutex error: mutex_vector_enter,544: locking against myself

lock address : 0xffff8000067094c0
current cpu  :                  0
current lwp  : 0xffffffff81481ba0
owner field  : 0xffffffff81481ba0 wait/spin:               0/0

panic: lock error: Mutex: mutex_vector_enter,544: locking against myself:
lock 0xffff8000067094c0 cpu 0 lwp 0xffffffff81481ba0
fatal breakpoint trap in supervisor mode
trap type 1 code 0 rip 0xffffffff80224d95 cs 0x8 rflags 0x246 cr2 0 ilevel 0x8 rsp 0xffffffff817f2900
curlwp 0xffffffff81481ba0 pid 0.1 lowest kstack 0xffffffff817ef2c0
Stopped in pid 0.1 (system) at  netbsd:breakpoint+0x5:   leave
db{0}>

Since the keyboard doesn't work, I can't call a full backtrace, I'm
stuck with just this output. (I haven't yet booted it with the keyboard
already plugged in and reproduced the "bit banging" hang, so I don't
know if I could get more details that way.)

I'm not sure if this is an unavoidable issue, and it's kind of obscure,
but I thought I'd file it.

The "bit banging on pin 5" part I think is symptomatic of a broader
hardware issue. But given the "this port is broken" message, I wondered
if that was of interest in isolation.

The full dmesg (on a successful boot, seemingly at random):

Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007, 2008, 2009, 2010, 2011, 2012, 2013, 2014, 2015, 2016, 2017
    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 8.0_BETA (GENERIC.201801180820Z)
total memory = 3551 MB
avail memory = 3426 MB
timecounter: Timecounters tick every 10.000 msec
Kernelized RAIDframe activated
running cgd selftest aes-xts-256 aes-xts-512 done
Unknown argument
timecounter: Timecounter "i8254" frequency 1193182 Hz quality 100
LENOVO 7360C12 (ThinkCentre M58)
mainbus0 (root)
ACPI: RSDP 0x00000000000F68F0 000024 (v02 LENOVO)
ACPI: XSDT 0x00000000CFF9D2C9 0000B4 (v01 LENOVO TC-5C    00000145  LTP 00000000)
ACPI: TCPA 0x00000000CFFAABB9 000032 (v02 LENOVO TC-5C    00000145 PTL  00000000)
ACPI: FACP 0x00000000CFFAABEB 0000F4 (v03 LENOVO TC-5C    00000145 PTL  00000002)
ACPI: DSDT 0x00000000CFFA1423 009712 (v01 LENOVO TC-5C    00000145 MSFT 0100000E)
ACPI: FACS 0x00000000CFFCEFC0 000040
ACPI: FACS 0x00000000CFFCEFC0 000040
ACPI: _MAR 0x00000000CFFAACDF 000030 (v01 LENOVO TC-5C    00000145 LOHR 00000001)
ACPI: SLIC 0x00000000CFFAAD0F 000176 (v01 LENOVO TC-5C    00000145  LTP 00000000)
ACPI: MCFG 0x00000000CFFAAE85 00003C (v01 LENOVO TC-5C    00000145  LTP 00000000)
ACPI: HPET 0x00000000CFFAAEC1 000038 (v01 LENOVO TC-5C    00000145  LTP 00000001)
ACPI: APIC 0x00000000CFFAAEF9 000068 (v01 LENOVO TC-5C    00000145  LTP 00000000)
ACPI: BOOT 0x00000000CFFAAF61 000028 (v01 LENOVO TC-5C    00000145  LTP 00000001)
ACPI: ASF! 0x00000000CFFAAF89 000077 (v32 LENOVO TC-5C    00000145 PTL  00000001)
ACPI: SSDT 0x00000000CFF9EBC9 00025F (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: SSDT 0x00000000CFF9EB23 0000A6 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: SSDT 0x00000000CFF9EA7D 0000A6 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: SSDT 0x00000000CFF9E9D7 0000A6 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: SSDT 0x00000000CFF9E931 0000A6 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: SSDT 0x00000000CFF9E88B 0000A6 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: SSDT 0x00000000CFF9E7E5 0000A6 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: SSDT 0x00000000CFF9E73F 0000A6 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: SSDT 0x00000000CFF9D37D 0013C2 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: 10 ACPI AML tables successfully acquired and loaded
ioapic0 at mainbus0 apid 2: pa 0xfec00000, version 0x20, 24 pins
cpu0 at mainbus0 apid 0
cpu0: Intel(R) Core(TM)2 Duo CPU     E7500  @ 2.93GHz, id 0x1067a
cpu0: package 0, core 0, smt 0
cpu1 at mainbus0 apid 1
cpu1: Intel(R) Core(TM)2 Duo CPU     E7500  @ 2.93GHz, id 0x1067a
cpu1: package 0, core 1, smt 0
acpi0 at mainbus0: Intel ACPICA 20170303
acpi0: X/RSDT: OemId <LENOVO,TC-5C   ,00000145>, AslId < LTP,00000000>
acpi0: MCFG: segment 0, bus 0-16, address 0x00000000f8000000
ACPI: Dynamic OEM Table Load:
ACPI: SSDT 0xFFFFFE81064C5690 00021F (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: Dynamic OEM Table Load:
ACPI: SSDT 0xFFFFFE810CF29010 00067D (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: Dynamic OEM Table Load:
ACPI: SSDT 0xFFFFFE81064CD010 0001B0 (v01 LENOVO TC-5C    00000145 INTL 20050228)
ACPI: Dynamic OEM Table Load:
ACPI: SSDT 0xFFFFFE81064BF848 000085 (v01 LENOVO TC-5C    00000145 INTL 20050228)
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 14318180 Hz quality 2000
acpivga0 at acpi0 (IGD0): ACPI Display Adapter
MBRD (PNP0C02) at acpi0 not configured
pcppi1 at acpi0 (SPKR, PNP0800): io 0x61
spkr0 at pcppi1: PC Speaker
midi0 at pcppi1: PC speaker
sysbeep0 at pcppi1
attimer1 at acpi0 (TIMR, PNP0100): io 0x40-0x43,0x50-0x53
FWH (INT0800) at acpi0 not configured
COM1 (PNP0501) at acpi0 not configured
FDC (PNP0700) at acpi0 not configured
NOKM (PNP0C02) at acpi0 not configured
TPM (WEC1000) at acpi0 not configured
acpibut0 at acpi0 (PWRB, PNP0C0C): ACPI Power Button
acpiwmi0 at acpi0 (WMI1, PNP0C14-1): ACPI WMI Interface
acpiwmibus at acpiwmi0 not configured
ACPI: Enabled 3 GPEs in block 00 to 3F
attimer1: attached to pcppi1
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 8086 product 2e10 (rev. 0x03)
agp0 at pchb0: G4X-family chipset
agp0: detected 130556k stolen memory
agp0: aperture at 0xe0000000, size 0x10000000
ppb0 at pci0 dev 1 function 0: vendor 8086 product 2e11 (rev. 0x03)
ppb0: PCI Express capability version 2 <Root Port of PCI-E Root Complex> x16 @ 5.0GT/s
pci1 at ppb0 bus 1
pci1: i/o space, memory space enabled, rd/line, wr/inv ok
wm0 at pci1 dev 0 function 0: Intel i82574L (rev. 0x00)
wm0: for TX and RX interrupting at msix0 vec 0 affinity to 0
wm0: for TX and RX interrupting at msix0 vec 1 affinity to 1
wm0: for LINK interrupting at msix0 vec 2
wm0: PCI-Express bus
wm0: ASPM L0s and L1 are disabled to workaround the errata.
wm0: 2048 words FLASH, version 1.8.0, Image Unique ID 0000ffff
wm0: Ethernet address 
wm0: 0x224480<FLASH,IOH_VALID,PCIE,ASF_FIRM,WOL>
makphy0 at wm0 phy 1: Marvell 88E1149 Gigabit PHY, rev. 1
makphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-FDX, auto
i915drmkms0 at pci0 dev 2 function 0: vendor 8086 product 2e12 (rev. 0x03)
drm: Memory usable by graphics device = 512M
drm: Supports vblank timestamp caching Rev 2 (21.10.2013).
drm: Driver supports precise vblank timestamp query.
i915drmkms0: interrupting at ioapic0 pin 16 (i915)
intelfb0 at i915drmkms0
i915drmkms0: info: registered panic notifier
intelfb0: framebuffer at 0xffff80003f3f4000, size 1024x768, depth 32, stride 4096
wsdisplay0 at intelfb0 kbdmux 1: console (default, vt100 emulation)
wsmux1: connecting to wsdisplay0
vendor 8086 product 2e13 (miscellaneous display, revision 0x03) at pci0 dev 2 function 1 not configured
vendor 8086 product 2e14 (miscellaneous communications, revision 0x03) at pci0 dev 3 function 0 not configured
pciide0 at pci0 dev 3 function 2: vendor 8086 product 2e16 (rev. 0x03)
pciide0: I/O access disabled at device
puc0 at pci0 dev 3 function 3: Intel Q45 KT (com)
com2 at puc0 port 0 (16550-compatible): ioaddr 0x1c90, interrupting at ioapic0 pin 17
com2: ns16550a, working fifo
wm1 at pci0 dev 25 function 0: 82567LM-3 LAN Controller (rev. 0x02)
wm1: interrupting at msi1 vec 0
wm1: PCI-Express bus
wm1: 2048 words FLASH
wm1: Ethernet address 
wm1: 0xa4480<FLASH,IOH_VALID,PCIE,ASF_FIRM,AMT>
makphy1 at wm1 phy 2: Marvell 88E1149 Gigabit PHY, rev. 1
makphy1: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-FDX, auto
uhci0 at pci0 dev 26 function 0: vendor 8086 product 3a67 (rev. 0x02)
uhci0: interrupting at ioapic0 pin 16
usb0 at uhci0: USB revision 1.0
uhci1 at pci0 dev 26 function 1: vendor 8086 product 3a68 (rev. 0x02)
uhci1: interrupting at ioapic0 pin 17
usb1 at uhci1: USB revision 1.0
uhci2 at pci0 dev 26 function 2: vendor 8086 product 3a69 (rev. 0x02)
uhci2: interrupting at ioapic0 pin 18
usb2 at uhci2: USB revision 1.0
ehci0 at pci0 dev 26 function 7: vendor 8086 product 3a6c (rev. 0x02)
ehci0: interrupting at ioapic0 pin 18
ehci0: EHCI version 1.0
ehci0: 3 companion controllers, 2 ports each: uhci0 uhci1 uhci2
usb3 at ehci0: USB revision 2.0
hdaudio0 at pci0 dev 27 function 0: HD Audio Controller
hdaudio0: interrupting at msi2 vec 0
hdafg0 at hdaudio0: vendor 11d4 product 1882
hdafg0: max connections reached
hdafg0: DAC00 2ch: Speaker [Jack]
hdafg0: ADC01 2ch: CD [Built-In], Line In [Jack], Mic In [Jack]
hdafg0: DAC02 2ch: HP Out [Jack]
hdafg0: 2ch/2ch 8000Hz 11025Hz 16000Hz 22050Hz 32000Hz 44100Hz 48000Hz 88200Hz 96000Hz PCM16 PCM20 PCM24 AC3
audio0 at hdafg0: full duplex, playback, capture, mmap, independent
hdafg0: Virtual format configured - Format SLINEAR, precision 16, channels 2, frequency 48000
hdafg0: Latency: 128 milliseconds
spkr1 at audio0: PC Speaker (synthesized)
uhci3 at pci0 dev 29 function 0: vendor 8086 product 3a64 (rev. 0x02)
uhci3: interrupting at ioapic0 pin 16
usb4 at uhci3: USB revision 1.0
uhci4 at pci0 dev 29 function 1: vendor 8086 product 3a65 (rev. 0x02)
uhci4: interrupting at ioapic0 pin 17
usb5 at uhci4: USB revision 1.0
uhci5 at pci0 dev 29 function 2: vendor 8086 product 3a66 (rev. 0x02)
uhci5: interrupting at ioapic0 pin 18
usb6 at uhci5: USB revision 1.0
ehci1 at pci0 dev 29 function 7: vendor 8086 product 3a6a (rev. 0x02)
ehci1: interrupting at ioapic0 pin 16
ehci1: EHCI version 1.0
ehci1: 3 companion controllers, 2 ports each: uhci3 uhci4 uhci5
usb7 at ehci1: USB revision 2.0
ppb1 at pci0 dev 30 function 0: vendor 8086 product 244e (rev. 0xa2)
pci2 at ppb1 bus 17
pci2: i/o space, memory space enabled
ichlpcib0 at pci0 dev 31 function 0: vendor 8086 product 3a14 (rev. 0x02)
timecounter: Timecounter "ichlpcib0" frequency 3579545 Hz quality 1000
ichlpcib0: 24-bit timer
tco0 at ichlpcib0: TCO (watchdog) timer configured.
tco0: Min/Max interval 1/367 seconds
ahcisata0 at pci0 dev 31 function 2: vendor 8086 product 3a02 (rev. 0x02)
ahcisata0: interrupting at ioapic0 pin 17
ahcisata0: 64-bit DMA
ahcisata0: AHCI revision 1.20, 6 ports, 32 slots, CAP 0xe322ff25<SXS,PSC,SSC,PMD,SPM,ISS=0x2=Gen2,SCLO,SAL,SSNTF,SNCQ,S64A>
atabus0 at ahcisata0 channel 0
atabus1 at ahcisata0 channel 1
atabus2 at ahcisata0 channel 3
ichsmb0 at pci0 dev 31 function 3: vendor 8086 product 3a60 (rev. 0x02)
ichsmb0: interrupting at ioapic0 pin 17
iic0 at ichsmb0: I2C bus
isa0 at ichlpcib0
com0 at isa0 port 0x3f8-0x3ff irq 4: ns16550a, working fifo
pckbc0 at isa0 port 0x60-0x64
pckbd0 at pckbc0 (kbd slot)
pckbc0: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard, using wsdisplay0
fdc0 at isa0 port 0x3f0-0x3f7 irq 6 drq 2
acpicpu0 at cpu0: ACPI CPU
acpicpu0: C1: FFH, lat   1 us, pow  1000 mW
acpicpu0: C2: FFH, lat   1 us, pow   500 mW
acpicpu0: P0: FFH, lat  10 us, pow 35000 mW, 2933 MHz
acpicpu0: P1: FFH, lat  10 us, pow 23000 mW, 2133 MHz
acpicpu0: P2: FFH, lat  10 us, pow 16000 mW, 1600 MHz
acpicpu0: T0: FFH, lat   1 us, pow 16000 mW, 100 %
acpicpu0: T1: FFH, lat   1 us, pow 14000 mW,  88 %
acpicpu0: T2: FFH, lat   1 us, pow 12000 mW,  75 %
acpicpu0: T3: FFH, lat   1 us, pow 10000 mW,  63 %
acpicpu0: T4: FFH, lat   1 us, pow  8000 mW,  50 %
acpicpu0: T5: FFH, lat   1 us, pow  6000 mW,  38 %
acpicpu0: T6: FFH, lat   1 us, pow  4000 mW,  25 %
acpicpu0: T7: FFH, lat   1 us, pow  2000 mW,  13 %
coretemp0 at cpu0: thermal sensor, 1 C resolution, Tjmax=100
acpicpu1 at cpu1: ACPI CPU
coretemp1 at cpu1: thermal sensor, 1 C resolution, Tjmax=100
timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
IPsec: Initialized Security Association Processing.
uhub0 at usb0: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhub1 at usb1: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhub2 at usb2: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhub3 at usb3: vendor 8086 (0x8086) EHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 1
uhub3: 6 ports with 6 removable, self powered
uhub4 at usb4: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub4: 2 ports with 2 removable, self powered
uhub5 at usb5: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub5: 2 ports with 2 removable, self powered
uhub6 at usb6: vendor 8086 (0x8086) UHCI root hub (0000), class 9/0, rev 1.00/1.00, addr 1
uhub6: 2 ports with 2 removable, self powered
uhub7 at usb7: vendor 8086 (0x8086) EHCI root hub (0000), class 9/0, rev 2.00/1.00, addr 1
uhub7: 6 ports with 6 removable, self powered
ahcisata0 port 0: device present, speed: 3.0Gb/s
ahcisata0 port 1: device present, speed: 1.5Gb/s
ehci0: handing over low speed device on port 1 to uhci0
wd0 at atabus0 drive 0
wd0: <ST250DM000-1BD141>
wd0: drive supports 16-sector PIO transfers, LBA48 addressing
wd0: 232 GB, 484521 cyl, 16 head, 63 sec, 512 bytes/sect x 488397168 sectors
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd0(ahcisata0:0:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100) (using DMA)
atapibus0 at atabus1: 1 targets
cd0 at atapibus0 drive 0: <TSSTcorpDVD-ROM TS-H353C, R52868AZC04468, LE01> cdrom removable
cd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
cd0(ahcisata0:1:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100) (using DMA)
pad0: outputs: 44100Hz, 16-bit, stereo
audio1 at pad0: half duplex, playback, capture, mmap
pad0: Virtual format configured - Format SLINEAR, precision 16, channels 2, frequency 44100
pad0: Latency: 139 milliseconds
spkr2 at audio1: PC Speaker (synthesized)
WARNING: 1 error while detecting hardware; check system log.
boot device: wd0
root on wd0a dumps on wd0b
root file system type: ffs
kern.module.path=/stand/amd64/8.0/modules
uhidev0 at uhub0 port 1 configuration 1 interface 0
uhidev0: USB (0x1a2c) USB Keyboard (0x2d23), rev 1.10/1.10, addr 2, iclass 3/1
ukbd0 at uhidev0: 8 Variable keys, 6 Array codes
wskbd1 at ukbd0 mux 1
wskbd1: connecting to wsdisplay0
uhidev1 at uhub0 port 1 configuration 1 interface 1
uhidev1: USB (0x1a2c) USB Keyboard (0x2d23), rev 1.10/1.10, addr 2, iclass 3/0
uhidev1: 2 report ids
uhid0 at uhidev1 reportid 1: input=2, output=0, feature=0
uhid1 at uhidev1 reportid 2: input=1, output=0, feature=0
wsdisplay0: screen 1 added (default, vt100 emulation)
wsdisplay0: screen 2 added (default, vt100 emulation)
wsdisplay0: screen 3 added (default, vt100 emulation)
wsdisplay0: screen 4 added (default, vt100 emulation)


>How-To-Repeat:
Boot an 8.0_BETA kernel on this hardware.
>Fix: