kern/56334: LOCKDEBUG panic after unplugging USB device

[reinoud%13thmonkey.org@localhost]

>Number:         56334
>Category:       kern
>Synopsis:       LOCKDEBUG panic after unplugging USB device
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed Jul 28 19:15:00 +0000 2021
>Originator:     Reinoud Zandijk
>Release:        NetBSD 9.99.87
>Organization:
NetBSD
	
>Environment:
	
	
System: NetBSD gorilla.13thmonkey.org 9.99.87 NetBSD 9.99.87 (GENERIC) #0: Thu Jul 22 10:10:33 CEST 2021 reinoud%gorilla.13thmonkey.org@localhost:/tmp/obj/sys/arch/amd64/compile/GENERIC amd64
Architecture: x86_64
Machine: amd64
DEBUG+LOCKDEBUG kernel
>Description:
After switching away my keyboard and mouse using a KVM switch the machine
paniced.

The dmesg upto then is:
...
[ 228113.020146] uhub8 at uhub6 port 4: Terminus Technology (0x1a40) USB 2.0
Hub (0x0101), class 9/0, rev 2.00/1.11, addr 3
[ 228113.020146] uhub8: single transaction translator
[ 228113.020146] uhub8: 4 ports with 4 removable, self powered
[ 228114.430150] uhidev1 at uhub8 port 3 configuration 1 interface 0
[ 228114.430150] uhidev1: CHESEN (0x0a81) PS2 to USB Converter (0x0205), rev
1.10/0.10, addr 4, iclass 3/1
[ 228114.440150] ukbd0 at uhidev1
[ 228114.850151] wskbd0 at ukbd0 mux 1
[ 228114.870151] wskbd0: connecting to wsdisplay0
[ 228114.870151] uhidev2 at uhub8 port 3 configuration 1 interface 1
[ 228114.870151] uhidev2: CHESEN (0x0a81) PS2 to USB Converter (0x0205), rev
1.10/0.10, addr 4, iclass 3/1
[ 228114.880151] uhidev2: 3 report ids
[ 228114.880151] ums0 at uhidev2 reportid 1: 5 buttons and Z dir
[ 228114.880151] wsmouse0 at ums0 mux 0
[ 228114.880151] uhid2 at uhidev2 reportid 2: input=1, output=0, feature=0
[ 228114.880151] uhid3 at uhidev2 reportid 3: input=3, output=0, feature=0
hid1 at uhidev0 reportid 204: input=0, output=0, feature=63
[     2.884727] wd0: drive supports P131.8601978] ukbd0: detached
[ 228131.860198] uhidev1: detached
[ 228131.860198] uhidev1: at uhub8 port 3 (addr 4) disconnected
[ 228136.130210] Kernel lock error: _kernel_lock,240: spinout

[ 228136.130210] lock address : 0xffffffff818a3b40 type     : spin
[ 228136.130210] initialized  : 0xffffffff80edbe90
[ 228136.130210] shared holds :                  0 exclusive: 1
[ 228136.130210] shares wanted:                  0 exclusive: 12
[ 228136.130210] relevant cpu :                  9 last held: 0
[ 228136.130210] relevant lwp : 0xffffeebb579d1100 last held: 0xffffeebb562bebc0
[ 228136.130210] last locked* : 0xffffffff80d19dc7 unlocked : 0xffffffff8055417e
[ 228136.130210] curcpu holds :                  0 wanted by: 0xffffeebb579d1100

[ 228136.130210] panic: LOCKDEBUG: Kernel lock error: _kernel_lock,240: spinout
[ 228136.130210] cpu9: Begin traceback...
[ 228136.130210] vpanic() at netbsd:vpanic+0x156
[ 228136.130210] device_printf() at netbsd:device_printf
[ 228136.130210] lockdebug_more.part.0() at netbsd:lockdebug_more.part.0
[ 228136.130210] _kernel_lock() at netbsd:_kernel_lock+0x22a
[ 228136.130210] kevent1() at netbsd:kevent1+0x6e0
[ 228136.130210] sys___kevent50() at netbsd:sys___kevent50+0x33
[ 228136.130210] syscall() at netbsd:syscall+0x226
[ 228136.130210] --- syscall (number 435) ---
[ 228136.130210] netbsd:syscall+0x226:
[ 228136.130210] cpu9: End traceback...
[ 228136.130210] fatal breakpoint trap in supervisor mode
...

USB tree for whats it worth
addr 0: xHCI root hub, NetBSD
  uhub3
 addr 1: BD-Rewriter, HLDS Inc
   umass0
 addr 2: USB2.0 Hub, Genesys Logic
   uhub6
  addr 3: USB 2.0 Hub, Terminus Technology
    uhub8
   addr 5: USB Optical Mouse, PixArt
     uhidev3
   addr 4: PS2 to USB Converter, CHESEN
     uhidev1
     uhidev2

A gdb session on the dumped core gives:
#12 0xffffffff80d51857 in panic (fmt=fmt@entry=0xffffffff8147f570 "LOCKDEBUG: %s error: %s,%zu: %s") at
%/usr/sources/cvs.netbsd.org/src-clean/sys/kern/subr_prf.c:209

#13 0xffffffff80d45be8 in lockdebug_abort1 (dopanic=true,
msg=0xffffffff81475dbe "spinout", s=0, ld=0xffffffff8197cfb8 <ld_prime+1080>,
line=240, func=0xffffffff81343270 <__func__.1> "_kernel_lock")
    at /usr/sources/cvs.netbsd.org/src-clean/sys/kern/subr_lockdebug.c:794

#14 lockdebug_abort1 (func=0xffffffff81343270 <__func__.1> "_kernel_lock",
line=240, ld=0xffffffff8197cfb8 <ld_prime+1080>, s=0, msg=0xffffffff81475dbe
"spinout", dopanic=<optimized out>)
    at /usr/sources/cvs.netbsd.org/src-clean/sys/kern/subr_lockdebug.c:772

#15 0xffffffff80cf6ba8 in _kernel_lock (nlocks=1) at
/usr/sources/cvs.netbsd.org/src-clean/sys/kern/kern_lock.c:240

#16 0xffffffff80ce8f32 in kqueue_scan (kevcnt=8, kevbuf=0xffffa804ada5be00,
keops=0xffffffff81342da0 <kevent_native_ops>, retval=0xffffa804ada5bfb0,
tsp=0xffffa804ada5bd48, ulistp=0x79bac65b3a00, maxevents=64, 
    fp=<optimized out>) at
/usr/sources/cvs.netbsd.org/src-clean/sys/kern/kern_event.c:1511
(gdb) list /usr/sources/cvs.netbsd.org/src-clean/sys/kern/kern_event.c:1511
1506                    }
1507                    if ((kn->kn_flags & EV_ONESHOT) == 0) {
1508                            mutex_spin_exit(&kq->kq_lock);
1509                            KASSERT(kn->kn_fop != NULL);
1510                            KASSERT(kn->kn_fop->f_event != NULL);
1511                            KERNEL_LOCK(1, NULL);           /* XXXSMP */
1512                            KASSERT(mutex_owned(&fdp->fd_lock));
1513                            rv = (*kn->kn_fop->f_event)(kn, 0);
1514                            KERNEL_UNLOCK_ONE(NULL);        /* XXXSMP */
1515                            mutex_spin_enter(&kq->kq_lock);

#17 kevent1 (retval=0xffffa804ada5bfb0, fd=7, changelist=<optimized out>,
nchanges=<optimized out>, eventlist=0x79bac65b3a00, nevents=64,
timeout=0xffffa804ada5bd48, keops=<optimized out>)
    at /usr/sources/cvs.netbsd.org/src-clean/sys/kern/kern_event.c:1109
(gdb) list /usr/sources/cvs.netbsd.org/src-clean/sys/kern/kern_event.c:1109
1104                    error = 0;
1105                    goto done;
1106            }
1107    
1108            /* actually scan through the events */
1109            error = kqueue_scan(fp, nevents, eventlist, timeout, retval, keops,
1110                kevbuf, __arraycount(kevbuf));
1111     done:
1112            fd_putfile(fd);
1113            return (error);


#18 0xffffffff80ce94a4 in sys___kevent50 (l=<optimized out>, uap=<optimized
out>, retval=<optimized out>) at
/usr/sources/cvs.netbsd.org/src-clean/sys/kern/kern_event.c:1032

#19 0xffffffff80568535 in sy_call (rval=0xffffa804ada5bfb0,
uap=0xffffa804ada5c000, l=0xffffeebb579d1100, sy=0xffffffff81885388
<sysent+10440>) at
/usr/sources/cvs.netbsd.org/src-clean/sys/sys/syscallvar.h:65

#20 sy_invoke (code=435, rval=0xffffa804ada5bfb0, uap=0xffffa804ada5c000,
l=0xffffeebb579d1100, sy=0xffffffff81885388 <sysent+10440>) at
/usr/sources/cvs.netbsd.org/src-clean/sys/sys/syscallvar.h:94

#21 syscall (frame=0xffffa804ada5c000) at
/usr/sources/cvs.netbsd.org/src-clean/sys/arch/x86/x86/syscall.c:138

#22 0xffffffff8020b25d in handle_syscall ()

Last locked at sleepq_block
(/usr/sources/cvs.netbsd.org/src-clean/sys/kern/kern_sleepq.c:404).
(gdb) list *(0xffffffff80d19dc7)
0xffffffff80d19dc7 is in sleepq_block
(/usr/sources/cvs.netbsd.org/src-clean/sys/kern/kern_sleepq.c:404).
399     
400             ktrcsw(0, 0);
401             if (__predict_false(biglocks != 0)) {
402                     KERNEL_LOCK(biglocks, NULL);
403             }
404             return error;
405     }
406     
407     /*
408      * sleepq_wake:

Unlocked in intr_biglock_wrapper
(/usr/sources/cvs.netbsd.org/src-clean/sys/arch/x86/x86/intr.c:663).
gdb) list *(0xffffffff8055417e)
0xffffffff8055417e is in intr_biglock_wrapper
(/usr/sources/cvs.netbsd.org/src-clean/sys/arch/x86/x86/intr.c:663).
658     
659             ret = (*ih->ih_realfun)(ih->ih_realarg);
660     
661             KERNEL_UNLOCK_ONE(NULL);
662     
663             return ret;
664     }
665     #endif /* MULTIPROCESSOR */


	
>How-To-Repeat:
Run a LOCKDEBUG kernel and switch back and forth with an USB KVM switching
keyboard and mouse. I works most of the time but it can trigger the lock. I've
had it a few times so its not a one-off.

	
>Fix:
Unknown
	

>Unformatted: