Re: Panic after USB deadlock followed by kldunload umass.ko

From: Fabian Keil <freebsd-listen_at_fabiankeil.de>
Date: Sun, 21 Dec 2014 14:54:31 +0100
Fabian Keil <freebsd-listen_at_fabiankeil.de> wrote:

> Hans Petter Selasky <hps_at_selasky.org> wrote:
> 
> > On 10/23/14 16:28, Fabian Keil wrote:
> 
> > > kldunload umass.ko lead to a panic, dumping didn't work.
> > >
> > > Screenshots are available at:
> > > http://www.fabiankeil.de/bilder/freebsd/kernel-panic-r273434-usb/
> > >
> > > I've seen locked-up usbconfig processes in the past,
> > > usually after executing a shell function that does:
> > >
> > > | usbconfig_output="$(sudo usbconfig -d ${device} add_quirk UQ_MSC_NO_INQUIRY)"
> > > | [... error handling snipped ]
> > > | usbconfig_output="$(sudo usbconfig -d ${device} reset)"
> > >
> > > Sometimes the second command seems to mess up the USB system.
> 
> > USB detach is synchronous. If for example umass fails to detach, due to 
> > reference counts not reaching zero, that might be the root cause. Try to 
> > get a backtrace from the "usb_process()" processes using kgdb, and 
> > you'll see right away what is going on.
> 
> Thanks for the quick response. So far I haven't been able to intentionally
> reproduce the issue, but I'll try the above the next time I unintentionally
> run into this again.

A couple of days ago usbconfig got stuck again:

fk_at_r500 ~ $sudo procstat -kk $(pgrep usbconfig)
  PID    TID COMM             TDNAME           KSTACK                       
 2444 100971 usbconfig        -                mi_switch+0xe1 sleepq_wait+0x3a _sx_xlock_hard+0x522 _sx_xlock+0x5d usbd_enum_lock+0x3a usb_ref_device+0x157 usb_open+0xbf devfs_open+0x122 VOP_OPEN_APV+0xa1 vn_open_vnode+0x234 vn_open_cred+0x310 kern_openat+0x26f amd64_syscall+0x3fd Xfast_syscall+0xfb 
 2425 100970 usbconfig        -                mi_switch+0xe1 sleepq_timedwait+0x3a _sleep+0x294 pause_sbt+0xd0 usb_pause_mtx+0x85 usb_ioctl+0x3e7 devfs_ioctl_f+0x13b kern_ioctl+0x3ce sys_ioctl+0x140 amd64_syscall+0x3fd Xfast_syscall+0xfb 

The USB-related threads:

(kgdb) thread 520
[Switching to thread 520 (Thread 100970)]#0  sched_switch (td=0xfffff8001d2044a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff8001d2044a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff80601a7a in sleepq_timedwait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:666
#3  0xffffffff805bb984 in _sleep (ident=<value optimized out>, lock=<value optimized out>, priority=<value optimized out>, wmesg=<value optimized out>, sbt=<value optimized out>, pr=<value optimized out>, 
    flags=<value optimized out>) at /usr/src/sys/kern/kern_synch.c:250
#4  0xffffffff805bbe10 in pause_sbt (wmesg=<value optimized out>, sbt=<value optimized out>, pr=0, flags=<value optimized out>) at /usr/src/sys/kern/kern_synch.c:379
#5  0xffffffff81e2f175 in usb_pause_mtx (mtx=<value optimized out>, timo=<value optimized out>) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_util.c:143
#6  0xffffffff81e16ed7 in usb_ioctl (dev=<value optimized out>, cmd=<value optimized out>, addr=<value optimized out>, fflag=0, td=<value optimized out>)
    at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_dev.c:1128
#7  0xffffffff8047cffb in devfs_ioctl_f (fp=0xfffff8001d3d1b40, com=2147767558, data=0xfffffe009453aa20, cred=<value optimized out>, td=0xfffff8001d2044a0) at /usr/src/sys/fs/devfs/devfs_vnops.c:775
#8  0xffffffff8061041e in kern_ioctl (td=0xfffff8001d2044a0, fd=<value optimized out>, com=0) at file.h:318
#9  0xffffffff8060ffa0 in sys_ioctl (td=0xfffff8001d2044a0, uap=0xfffffe009453ab80) at /usr/src/sys/kern/sys_generic.c:718
#10 0xffffffff80877d5d in amd64_syscall (td=0xfffff8001d2044a0, traced=0) at subr_syscall.c:133
#11 0xffffffff8085ac9b in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:390
#12 0x0000000800b7caea in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) thread 522
[Switching to thread 522 (Thread 100971)]#0  sched_switch (td=0xfffff8001d3a5940, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff8001d3a5940, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff805bae82 in _sx_xlock_hard (sx=0xfffff80015e82050, tid=18446735278106892608, opts=<value optimized out>, file=0x0, line=0) at /usr/src/sys/kern/kern_sx.c:688
#4  0xffffffff805ba6ad in _sx_xlock (sx=0x0, opts=0, file=<value optimized out>, line=0) at sx.h:154
#5  0xffffffff81e19baa in usbd_enum_lock (udev=0xfffff80015e82000) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_device.c:2755
#6  0xffffffff81e18967 in usb_ref_device (cpd=0xfffff80015b518c0, crd=0xfffffe009453f630, need_uref=<value optimized out>) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_dev.c:231
#7  0xffffffff81e15caf in usb_open (dev=<value optimized out>, fflags=3, devtype=<value optimized out>, td=0x0) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_dev.c:887
#8  0xffffffff8047ae52 in devfs_open (ap=<value optimized out>) at /usr/src/sys/fs/devfs/devfs_vnops.c:1108
#9  0xffffffff8091e3d1 in VOP_OPEN_APV (vop=<value optimized out>, a=<value optimized out>) at vnode_if.c:467
#10 0xffffffff8067d544 in vn_open_vnode (vp=0xfffff8004f4283b0, fmode=3, cred=0xfffff80028c83500, td=0xfffff8001d3a5940, fp=0xfffff800283b6be0) at vnode_if.h:196
#11 0xffffffff8067d090 in vn_open_cred (ndp=0xfffffe009453f9b0, flagp=0xfffffe009453fa8c, cmode=<value optimized out>, vn_open_flags=<value optimized out>, cred=0x0, fp=0xfffff800283b6be0)
    at /usr/src/sys/kern/vfs_vnops.c:258
#12 0xffffffff8067674f in kern_openat (td=0xfffff8001d3a5940, fd=-100, path=0x7fffffffe650 <Address 0x7fffffffe650 out of bounds>, pathseg=UIO_USERSPACE, flags=3, mode=<value optimized out>)
    at /usr/src/sys/kern/vfs_syscalls.c:1081
#13 0xffffffff80877d5d in amd64_syscall (td=0xfffff8001d3a5940, traced=0) at subr_syscall.c:133
#14 0xffffffff8085ac9b in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:390
#15 0x0000000800b748aa in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) thread 497
[Switching to thread 497 (Thread 100728)]#0  sched_switch (td=0xfffff80015d51940, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015d51940, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff80553340 in _cv_wait (cvp=0xfffffe0004590d10, lock=0xfffffe0004591090) at /usr/src/sys/kern/kern_condvar.c:139
#4  0xffffffff81e28544 in usb_process (arg=0xfffffe0004590d00) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:193
#5  0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe0004590d00, frame=0xfffffe00942e0c00) at /usr/src/sys/kern/kern_fork.c:978
#6  0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#7  0x0000000000000000 in ?? ()
(kgdb) thread 496
[Switching to thread 496 (Thread 100731)]#0  sched_switch (td=0xfffff80015d50940, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015d50940, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff80553340 in _cv_wait (cvp=0xfffffe0004590d68, lock=0xfffffe0004591090) at /usr/src/sys/kern/kern_condvar.c:139
#4  0xffffffff81e28544 in usb_process (arg=0xfffffe0004590d58) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:193
#5  0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe0004590d58, frame=0xfffffe00942efc00) at /usr/src/sys/kern/kern_fork.c:978
#6  0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#7  0x0000000000000000 in ?? ()
(kgdb) thread 495
[Switching to thread 495 (Thread 100732)]#0  sched_switch (td=0xfffff80015d504a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015d504a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff80553340 in _cv_wait (cvp=0xfffffe0004590dc0, lock=0xfffffe0004591090) at /usr/src/sys/kern/kern_condvar.c:139
#4  0xffffffff81e28544 in usb_process (arg=0xfffffe0004590db0) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:193
#5  0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe0004590db0, frame=0xfffffe00942f4c00) at /usr/src/sys/kern/kern_fork.c:978
#6  0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#7  0x0000000000000000 in ?? ()
(kgdb) thread 495
[Switching to thread 495 (Thread 100732)]#0  sched_switch (td=0xfffff80015d504a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015d504a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff80553340 in _cv_wait (cvp=0xfffffe0004590dc0, lock=0xfffffe0004591090) at /usr/src/sys/kern/kern_condvar.c:139
#4  0xffffffff81e28544 in usb_process (arg=0xfffffe0004590db0) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:193
#5  0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe0004590db0, frame=0xfffffe00942f4c00) at /usr/src/sys/kern/kern_fork.c:978
#6  0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#7  0x0000000000000000 in ?? ()
(kgdb) thread 494
[Switching to thread 494 (Thread 100733)]#0  sched_switch (td=0xfffff80015d50000, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015d50000, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff80553340 in _cv_wait (cvp=0xfffffe0004590e18, lock=0xfffffe0004591090) at /usr/src/sys/kern/kern_condvar.c:139
#4  0xffffffff81e28544 in usb_process (arg=0xfffffe0004590e08) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:193
#5  0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe0004590e08, frame=0xfffffe00942f9c00) at /usr/src/sys/kern/kern_fork.c:978
#6  0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#7  0x0000000000000000 in ?? ()
(kgdb) thread 493
[Switching to thread 493 (Thread 100735)]#0  sched_switch (td=0xfffff80015d7f4a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015d7f4a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff80553340 in _cv_wait (cvp=0xfffffe00064a7d10, lock=0xfffffe00064a8090) at /usr/src/sys/kern/kern_condvar.c:139
#4  0xffffffff81e28544 in usb_process (arg=0xfffffe00064a7d00) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:193
#5  0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe00064a7d00, frame=0xfffffe0094303c00) at /usr/src/sys/kern/kern_fork.c:978
#6  0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#7  0x0000000000000000 in ?? ()
(kgdb) thread 492
[Switching to thread 492 (Thread 100736)]#0  sched_switch (td=0xfffff80015d7f000, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015d7f000, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff80553340 in _cv_wait (cvp=0xfffffe00064a7d68, lock=0xfffffe00064a8090) at /usr/src/sys/kern/kern_condvar.c:139
#4  0xffffffff81e28544 in usb_process (arg=0xfffffe00064a7d58) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:193
#5  0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe00064a7d58, frame=0xfffffe0094308c00) at /usr/src/sys/kern/kern_fork.c:978
#6  0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#7  0x0000000000000000 in ?? ()
(kgdb) thread 491
[Switching to thread 491 (Thread 100737)]#0  sched_switch (td=0xfffff80015ea0940, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015ea0940, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff805bb99d in _sleep (ident=<value optimized out>, lock=<value optimized out>, priority=<value optimized out>, wmesg=<value optimized out>, sbt=<value optimized out>, pr=<value optimized out>, 
    flags=<value optimized out>) at /usr/src/sys/kern/kern_synch.c:254
#4  0xffffffff802a2548 in cam_sim_free (sim=0xfffff8004f9fa800, free_devq=1) at /usr/src/sys/cam/cam_sim.c:109
#5  0xffffffff81e4e78f in umass_detach (dev=<value optimized out>) at /usr/src/sys/modules/usb/umass/../../../dev/usb/storage/umass.c:2136
#6  0xffffffff805e8ce2 in device_detach (dev=0xfffff80028c69000) at device_if.h:214
#7  0xffffffff81e1aad1 in usb_detach_device (udev=0xfffff8004f5bd000, iface_index=<value optimized out>, flag=0 '\0') at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_device.c:1145
#8  0xffffffff81e19c76 in usb_unconfigure (udev=0xfffff8004f5bd000, flag=0 '\0') at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_device.c:534
#9  0xffffffff81e196d0 in usbd_set_config_index (udev=0xfffff8004f5bd000, index=255 'ΓΏ') at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_device.c:597
#10 0xffffffff81e22d77 in uhub_explore_handle_re_enumerate (child=0xfffff8004f5bd000) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_hub.c:456
#11 0xffffffff81e25eb5 in uhub_explore (udev=0xfffff80015e82000) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_hub.c:551
#12 0xffffffff81e12f75 in usb_bus_explore (pm=<value optimized out>) at /usr/src/sys/modules/usb/usb/../../../dev/usb/controller/usb_controller.c:404
#13 0xffffffff81e2857f in usb_process (arg=0xfffffe00064a7db0) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:176
#14 0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe00064a7db0, frame=0xfffffe009430dc00) at /usr/src/sys/kern/kern_fork.c:978
#15 0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#16 0x0000000000000000 in ?? ()
(kgdb) thread 490
[Switching to thread 490 (Thread 100738)]#0  sched_switch (td=0xfffff80015ea04a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
1940			cpuid = PCPU_GET(cpuid);
(kgdb) where
#0  sched_switch (td=0xfffff80015ea04a0, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1940
#1  0xffffffff805bbf91 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:492
#2  0xffffffff8060126a in sleepq_wait (wchan=0x0, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:631
#3  0xffffffff80553340 in _cv_wait (cvp=0xfffffe00064a7e18, lock=0xfffffe00064a8090) at /usr/src/sys/kern/kern_condvar.c:139
#4  0xffffffff81e28544 in usb_process (arg=0xfffffe00064a7e08) at /usr/src/sys/modules/usb/usb/../../../dev/usb/usb_process.c:193
#5  0xffffffff80577afa in fork_exit (callout=0xffffffff81e28470 <usb_process>, arg=0xfffffe00064a7e08, frame=0xfffffe0094312c00) at /usr/src/sys/kern/kern_fork.c:978
#6  0xffffffff8085aeee in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:605
#7  0x0000000000000000 in ?? ()

So it looks like thread 491 is blocking thread 522 by holding udev->enum_sx?

Fabian

Received on Sun Dec 21 2014 - 12:57:11 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:54 UTC