Re: "usbip: Implement SG support to vhci-hcd and stub driver" causes a deadlock

[Suwan Kim <suwan.kim027@gmail.com>]

On Fri, Dec 06, 2019 at 04:24:06AM +0100, Marek Marczykowski-Górecki wrote:
> Hello,
> 
> I've hit an issue with recent 4.19 and 5.4 kernels. In short: if I
> connect Yubikey 4 and use its CCID interface (for example `ykman oath
> list` command), the client side hangs (100% reliably). After 60s I get a
> message that a CPU hangs waiting for a spinlock (see below).
> 
> I've bisected it to a ea44d190764b4422af ("usbip: Implement SG support
> to vhci-hcd and stub driver") commit. Which indeed is also backported to
> 4.19.
> 
> Any idea what is going on here? I can easily provide more information,
> if you tell me how to get it.
> 

Hi,

Thanks for reporting. Could you turn on lockdep and USBIP_DEBUG
in kernel config and send dmesg log? It will be helpful to figure
out lock dependency in vhci_hcd.

Regards,
Suwan Kim

> The kernel log:
> [ 6452.701016] usb 1-1: New USB device found, idVendor=1050, idProduct=0407, bcdDevice= 4.27
> [ 6452.701049] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
> [ 6452.701075] usb 1-1: Product: Yubikey 4 OTP+U2F+CCID
> [ 6452.701092] usb 1-1: Manufacturer: Yubico
> [ 6452.711566] input: Yubico Yubikey 4 OTP+U2F+CCID as /devices/platform/vhci_hcd.0/usb1/1-1/1-1:1.0/0003:1050:0407.0001/input/input1
> [ 6452.762251] hid-generic 0003:1050:0407.0001: input,hidraw0: USB HID v1.10 Keyboard [Yubico Yubikey 4 OTP+U2F+CCID] on usb-vhci_hcd.0-1/input0
> [ 6452.770270] hid-generic 0003:1050:0407.0002: hiddev96,hidraw1: USB HID v1.10 Device [Yubico Yubikey 4 OTP+U2F+CCID] on usb-vhci_hcd.0-1/input1
> [ 6530.805002] vhci_hcd: unlink->seqnum 111
> [ 6530.805024] vhci_hcd: urb->status -104
> [ 6531.386607] usb 1-1: recv xbuf, 42
> [ 6531.386701] vhci_hcd: stop threads
> [ 6531.386718] vhci_hcd: release socket
> [ 6531.386734] vhci_hcd: disconnect device
> [ 6531.386800] usb 1-1: USB disconnect, device number 2
> [ 6591.409099] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 6591.409130] rcu:     1-...!: (0 ticks this GP) idle=53a/1/0x4000000000000000 softirq=18978/18978 fqs=0 
> [ 6591.409158] rcu:     (detected by 0, t=60002 jiffies, g=17933, q=893)
> [ 6591.409181] Sending NMI from CPU 0 to CPUs 1:
> [ 6591.410415] NMI backtrace for cpu 1
> [ 6591.410416] CPU: 1 PID: 338 Comm: kworker/1:2 Tainted: G           O      4.19.84-1.pvops.qubes.x86_64 #1
> [ 6591.410417] Workqueue: usb_hub_wq hub_event
> [ 6591.410417] RIP: 0010:_raw_spin_lock_irqsave+0x22/0x40
> [ 6591.410418] Code: 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 53 9c 58 0f 1f 44 00 00 48 89 c3 fa 66 0f 1f 44 00 00 31 c0 ba 01 00 00 00 f0 0f b1 17 <85> c0 75 05 48 89 d8 5b c3 89 c6 e8 3e 1c 7e ff 66 90 48 89 d8 5b
> [ 6591.410419] RSP: 0000:ffffc900009dfaf8 EFLAGS: 00000046
> [ 6591.410419] RAX: 0000000000000000 RBX: 0000000000000082 RCX: 0000000000000000
> [ 6591.410420] RDX: 0000000000000001 RSI: ffff88801e633e40 RDI: ffff888006740be0
> [ 6591.410420] RBP: ffff888006740be0 R08: 0000000000000000 R09: ffffffff81346f00
> [ 6591.410420] R10: ffff888014f5b5d8 R11: 0000000000000000 R12: 00000000ffffff94
> [ 6591.410421] R13: ffff88803ff06000 R14: ffff88803ff06000 R15: ffff88801e633e40
> [ 6591.410421] FS:  0000000000000000(0000) GS:ffff8880f5b00000(0000) knlGS:0000000000000000
> [ 6591.410421] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 6591.410422] CR2: 00005eede8b122a8 CR3: 000000000220a002 CR4: 00000000003606e0
> [ 6591.410422] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 6591.410423] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 6591.410423] Call Trace:
> [ 6591.410423]  vhci_urb_dequeue+0x2b/0x280 [vhci_hcd]
> [ 6591.410423]  usb_hcd_flush_endpoint+0x119/0x190
> [ 6591.410424]  usb_disable_endpoint+0x7b/0xa0
> [ 6591.410424]  usb_disable_interface+0x3e/0x50
> [ 6591.410424]  usb_unbind_interface+0x117/0x250
> [ 6591.410425]  device_release_driver_internal+0x17d/0x240
> [ 6591.410425]  bus_remove_device+0xe5/0x150
> [ 6591.410425]  device_del+0x161/0x360
> [ 6591.410426]  ? usb_remove_ep_devs+0x1b/0x30
> [ 6591.410426]  usb_disable_device+0x93/0x240
> [ 6591.410426]  usb_disconnect+0x90/0x270
> [ 6591.410427]  hub_port_connect+0x83/0xab0
> [ 6591.410427]  hub_event+0x8d1/0xab0
> [ 6591.410427]  process_one_work+0x191/0x370
> [ 6591.410428]  worker_thread+0x4f/0x3b0
> [ 6591.410428]  kthread+0xf8/0x130
> [ 6591.410428]  ? rescuer_thread+0x340/0x340
> [ 6591.410428]  ? kthread_create_worker_on_cpu+0x70/0x70
> [ 6591.410429]  ret_from_fork+0x35/0x40
> [ 6591.410432] rcu: rcu_sched kthread starved for 60002 jiffies! g17933 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=1
> [ 6591.411962] rcu: RCU grace-period kthread stack dump:
> [ 6591.411980] rcu_sched       I    0    10      2 0x80000000
> [ 6591.411998] Call Trace:
> [ 6591.412015]  ? __schedule+0x3f5/0x870
> [ 6591.412030]  schedule+0x32/0x80
> [ 6591.412044]  schedule_timeout+0x16f/0x350
> [ 6591.412059]  ? __next_timer_interrupt+0xc0/0xc0
> [ 6591.412077]  rcu_gp_kthread+0x569/0x950
> [ 6591.412092]  kthread+0xf8/0x130
> [ 6591.412106]  ? rcu_nocb_kthread+0x560/0x560
> [ 6591.412119]  ? kthread_create_worker_on_cpu+0x70/0x70
> [ 6591.412136]  ret_from_fork+0x35/0x40
> 
> Some more details are available here:
> https://github.com/QubesOS/qubes-issues/issues/5498
> 
> -- 
> Best Regards,
> Marek Marczykowski-Górecki
> Invisible Things Lab
> A: Because it messes up the order in which people normally read text.
> Q: Why is top-posting such a bad thing?