On Tue, 1 Mar 2016 11:05:42 +0100
Sedat Dilek <sedat.dilek@xxxxxxxxx> wrote:
> [ FACT #3: TEST-CASE #2 ]
>
> The most reliable test-case is to simply unplug my external Logitech
> USB mouse - saw this by accident.
> YES, it was so simple.
Just to clarify, this happens on gcc and clang?
>
> --- dmesg_4.5.0-rc6-2-llvmlinux-amd64.txt 2016-02-29
> 21:23:56.399691975 +0100
> +++ dmesg_4.5.0-rc6-2-llvmlinux-amd64_usbmouse-unplugged.txt
> 2016-02-29 21:28:14.401832240 +0100
> @@ -832,3 +832,75 @@
> [ 66.529779] PPP BSD Compression module registered
> [ 66.563013] PPP Deflate Compression module registered
> [ 66.978977] usb 2-1.5: USB disconnect, device number 4
> +[ 321.937369] usb 2-1.4: USB disconnect, device number 3
> +[ 321.950810] BUG: sleeping function called from invalid context at
> kernel/workqueue.c:2785
> +[ 321.950816] in_atomic(): 0, irqs_disabled(): 1, pid: 44, name: kworker/2:1
> +[ 321.950819] 9 locks held by kworker/2:1/44:
> +[ 321.950820] #0: ("usb_hub_wq"){.+.+.+}, at: [<ffffffff810a7c5f>]
> process_one_work+0x30f/0x8d0
> +[ 321.950830] #1: ((&hub->events)){+.+.+.}, at:
> [<ffffffff810a7c8c>] process_one_work+0x33c/0x8d0
> +[ 321.950836] #2: (&dev->mutex){......}, at: [<ffffffff816fb0e0>]
> hub_event+0x50/0x15b0
> +[ 321.950844] #3: (&dev->mutex){......}, at: [<ffffffff816f686f>]
> usb_disconnect+0x5f/0x2c0
> +[ 321.950849] #4: (&dev->mutex){......}, at: [<ffffffff816245a2>]
> device_release_driver+0x22/0x40
> +[ 321.950856] #5: (&dev->mutex){......}, at: [<ffffffff816245a2>]
> device_release_driver+0x22/0x40
> +[ 321.950862] #6: (input_mutex){+.+.+.}, at: [<ffffffff8175171a>]
> __input_unregister_device+0x9a/0x190
> +[ 321.950869] #7: (&dev->mutex#2){+.+...}, at:
> [<ffffffff8174fe27>] input_close_device+0x27/0x70
> +[ 321.950875] #8: (hid_open_mut){+.+...}, at: [<ffffffffa0057388>]
> usbhid_close+0x28/0xb0 [usbhid]
> +[ 321.950883] irq event stamp: 47770
> +[ 321.950885] hardirqs last enabled at (47769):
> [<ffffffff819426a2>] _raw_spin_unlock_irq+0x32/0x60
> +[ 321.950889] hardirqs last disabled at (47770):
> [<ffffffff81115bdc>] del_timer_sync+0x3c/0x110
According to lockdep, interrupts were last disabled in del_timer_sync,
and they were never enabled. The numbers in parenthesis show the order
of events. _raw_spin_unlock_irq() at 47769, then del_timer_sync at
47770.
But why did they not get enabled again? We have:
local_irq_save(flags);
lock_map_acquire(&timer->lockdep_map);
lock_map_release(&timer->lockdep_map);
local_irq_restore(flags);
If this caused an issue, then you would have a lockdep splat. But
perhaps something corrupted "flags", and interrupts were not re-enabled?
> +[ 321.950894] softirqs last enabled at (47112):
> [<ffffffff810871a2>] __do_softirq+0x5a2/0x610
> +[ 321.950898] softirqs last disabled at (47097):
> [<ffffffff8108747c>] irq_exit+0x9c/0x120
> +[ 321.950903] CPU: 2 PID: 44 Comm: kworker/2:1 Not tainted
> 4.5.0-rc6-2-llvmlinux-amd64 #1
> +[ 321.950905] Hardware name: SAMSUNG ELECTRONICS CO., LTD.
> 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH, BIOS 13XK 03/28/2013
> +[ 321.950908] Workqueue: usb_hub_wq hub_event
> +[ 321.950911] ffff8800d3326948 0000000000000092 0000000000000000
> ffff8800d4347568
> +[ 321.950915] ffffffff814ba7d4 ffff8800d43474f8 ffff8800d4340cc0
> ffff8800d4347568
> +[ 321.950919] ffffffff810e28fd 0000000000000092 0000000000000096
> ffff8800d43475a8
> +[ 321.950923] Call Trace:
> +[ 321.950927] [<ffffffff814ba7d4>] dump_stack+0xa4/0xf0
> +[ 321.950931] [<ffffffff810e28fd>] ? print_irqtrace_events+0xcd/0xe0
> +[ 321.950936] [<ffffffff810bf495>] ___might_sleep+0x295/0x2b0
> +[ 321.950939] [<ffffffff810bf18f>] __might_sleep+0x4f/0xc0
This triggered on the might_sleep() in start_flush_work() because
something left interrupts enable.
Just strange.
-- Steve
> +[ 321.950943] [<ffffffff810a12ef>] start_flush_work+0x2f/0x2a0
> +[ 321.950946] [<ffffffff810a129c>] flush_work+0x5c/0x80
> +[ 321.950949] [<ffffffff810a125a>] ? flush_work+0x1a/0x80
> +[ 321.950953] [<ffffffff810e247d>] ? trace_hardirqs_off+0xd/0x10
> +[ 321.950956] [<ffffffff810a032a>] ? try_to_grab_pending+0x4a/0x260
> +[ 321.950960] [<ffffffff810a1717>] __cancel_work_timer+0x197/0x290
> +[ 321.950963] [<ffffffff81115b8d>] ? try_to_del_timer_sync+0xad/0xc0
> +[ 321.950966] [<ffffffff810a1578>] cancel_work_sync+0x18/0x20
> +[ 321.950970] [<ffffffffa00573d5>] usbhid_close+0x75/0xb0 [usbhid]
> +[ 321.950977] [<ffffffffa003a481>] hidinput_close+0x31/0x40 [hid]
> +[ 321.950982] [<ffffffffa003a450>] ? hidinput_open+0x40/0x40 [hid]
> +[ 321.950985] [<ffffffff8174fe48>] input_close_device+0x48/0x70
> +[ 321.950988] [<ffffffff81757f85>] evdev_cleanup+0xd5/0xe0
> +[ 321.950990] [<ffffffff81757b0c>] evdev_disconnect+0x2c/0x60
> +[ 321.950993] [<ffffffff8175173e>] __input_unregister_device+0xbe/0x190
> +[ 321.950996] [<ffffffff8175164a>] input_unregister_device+0x4a/0x80
> +[ 321.951001] [<ffffffffa003a29f>] hidinput_disconnect+0x8f/0xc0 [hid]
> +[ 321.951007] [<ffffffffa0034a30>] hid_device_remove+0xb0/0x130 [hid]
> +[ 321.951010] [<ffffffff816246bd>] __device_release_driver+0xfd/0x190
> +[ 321.951014] [<ffffffff816245aa>] device_release_driver+0x2a/0x40
> +[ 321.951017] [<ffffffff816224a3>] bus_remove_device+0x153/0x190
> +[ 321.951020] [<ffffffff8161f5fb>] device_del+0x1db/0x2b0
> +[ 321.951025] [<ffffffffa0033c1c>] hid_destroy_device+0x2c/0x60 [hid]
> +[ 321.951029] [<ffffffffa0058537>] usbhid_disconnect+0x67/0x90 [usbhid]
> +[ 321.951033] [<ffffffff81706ebf>] usb_unbind_interface+0xbf/0x2b0
> +[ 321.951037] [<ffffffff816246bd>] __device_release_driver+0xfd/0x190
> +[ 321.951040] [<ffffffff816245aa>] device_release_driver+0x2a/0x40
> +[ 321.951043] [<ffffffff816224a3>] bus_remove_device+0x153/0x190
> +[ 321.951046] [<ffffffff8161f5fb>] device_del+0x1db/0x2b0
> +[ 321.951048] [<ffffffff8161f6fc>] ? device_unregister+0x2c/0x40
> +[ 321.951051] [<ffffffff81704f6b>] usb_disable_device+0x10b/0x3b0
> +[ 321.951054] [<ffffffff816f6904>] usb_disconnect+0xf4/0x2c0
> +[ 321.951057] [<ffffffff816fbc3d>] hub_event+0xbad/0x15b0
> +[ 321.951060] [<ffffffff819426a2>] ? _raw_spin_unlock_irq+0x32/0x60
> +[ 321.951063] [<ffffffff810a7e0e>] process_one_work+0x4be/0x8d0
> +[ 321.951065] [<ffffffff810a7c8c>] ? process_one_work+0x33c/0x8d0
> +[ 321.951068] [<ffffffff810a757b>] worker_thread+0x5cb/0x750
> +[ 321.951071] [<ffffffff810a6fb0>] ? destroy_worker+0x110/0x110
> +[ 321.951074] [<ffffffff810ae1c5>] kthread+0x115/0x120
> +[ 321.951077] [<ffffffff810e248d>] ? trace_hardirqs_on+0xd/0x10
> +[ 321.951080] [<ffffffff810ae0b0>] ? flush_kthread_worker+0x80/0x80
> +[ 321.951084] [<ffffffff819435ff>] ret_from_fork+0x3f/0x70
> +[ 321.951087] [<ffffffff810ae0b0>] ? flush_kthread_worker+0x80/0x80
>
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
