Re: kernel BUG at mm/usercopy.c when using usbip

[Zenithal <i@zenithal.me>]

On Thu, Jan 12, 2023 at 09:40:59AM +0100, Sosthène Guédon wrote:
> Hi!
> 
> I have stumbled upon a bug that is triggered reliably by using usbip.
> 
> We are using usbip to test our firmware. usbip attach works, but once
> `opgpcard-tools` interacts with the firmware through pcscd, a kernel bug
> happens.
> Then usbip stops working, and `lsusb` as well as other tools interacting
> with usb devices hang.
> The symptoms are similar to
> https://bugzilla.kernel.org/show_bug.cgi?id=215487 but the kernel bug is not
> the same (see attached dmesg logs).
> 
> The bug can be reproduced on arch (Linux archlinux 6.1.4-arch1-1 #1 SMP
> PREEMPT_DYNAMIC Sat, 07 Jan 2023 15:10:07 +0000 x86_64 GNU/Linux
> ) and debian (Linux nitropc 5.10.0-19-amd64 #1 SMP Debian 5.10.149-2
> (2022-10-21) x86_64 GNU/Linux), though the reproduction is not minimal.
> 
> To reproduce the bug on Arch Linux, with the packages rust, pcsclite, and
> openpgp-card-tools installed:
> 
> - Compile and run the usbip runner from this
> PR: https://github.com/Nitrokey/nitrokey-3-firmware/pull/149 (`cd
> nitrokey-3-firmware/runners/usbip && cargo run --features alpha`)
> - Run `usbip attach -r localhost -b 1-1`
> - Run `pcscd`
> - Run `opgpcard status`
> 
> The bug should happen.

I can reproduce the bug and I have captured the buggy usbip request/response
by running `tcpdump -i lo "tcp port 3240"`

First the architecture is
pcscd --ioctl-> vhci-hcd --kernel usb stack-> usbip-host --usbip tcp-> usbip-runner

This is a CTRL IN request which expect a response of length 0x22,
which has indicated its expectation in the transfer_buffer_length
and USB SETUP wLength field

CMD_SUBMIT:

usbip_header_basic:
00 00 00 01 00 00 00 0d 00 01 00 02 00 00 00 01 00 00 00 00
trasfer_flags:
00 00 02 00
**transfer_buffer_length**:
00 00 00 22
other meta:
00 00 00 00 00 00 00 00 00 00 00 00
**setup**:
81 06 00 22 00 00 **22 00**

But usbip-runner did not behave according to the
SETUP request, instead it returned a buffer of length 0x32.
It seems that it accidently added a descriptor twice.

RET_SUBMIT:

usbip_header_basic:
00 00 00 03 00 00 00 0d 00 00 00 02 00 00 00 01 00 00 00 00
status:
00 00 00 00
**actual_length:**
00 00 00 32
other metas:
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 
payload of length 0x32:
06 d0 f1 09 01 a1 01 09 03 15 00 26 ff 00 75 08
06 d0 f1 09 01 a1 01 09 03 15 00 26 ff 00 75 08
95 40 81 08 09 04 15 00 26 ff 00 75 08 95 40 91
08 c0

Then this leads to consequent errors in kernel

> 
> -- 
> Sosthène Guédon,
> Software engineer
> 
> Nitrokey GmbH
> https://www.nitrokey.com
> 
> Email: sosthene@nitrokey.com
> Phone: +49 30 1205 3434
> 
> Rheinstr. 10 C, 14513 Teltow, Germany
> CEO / Geschäftsführer: Jan Suhr
> Register: AG Potsdam, HRB 32882 P
> VAT ID / USt-IdNr.: DE300136599

> [ 1464.886564] usb 5-1: new high-speed USB device number 2 using vhci_hcd
> [ 1465.019883] usb 5-1: SetAddress Request (2) to port 0
> [ 1465.036533] usb 5-1: Using ep0 maxpacket: 8
> [ 1465.153573] usb 5-1: config 1 interface 1 altsetting 0 bulk endpoint 0x82 has invalid maxpacket 64
> [ 1465.153591] usb 5-1: config 1 interface 1 altsetting 0 bulk endpoint 0x2 has invalid maxpacket 64
> [ 1465.189963] usb 5-1: New USB device found, idVendor=20a0, idProduct=42b2, bcdDevice= 0.10
> [ 1465.189979] usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
> [ 1465.189982] usb 5-1: Product: Nitrokey 3
> [ 1465.189986] usb 5-1: Manufacturer: Nitrokey
> [ 1465.231395] usb 5-1: recv xbuf, 0

usbip-host first detected such abnormality:

the returned urb->actualy_length is greater than
urb->transfer_buffer_length, the "recv xbuf, 0" path
is gone through.

https://github.com/torvalds/linux/blob/6015b1aca1a233379625385feb01dd014aca60b5/drivers/usb/usbip/usbip_common.c#L789-L791

> [ 1465.231548] vhci_hcd: stop threads
> [ 1465.231552] vhci_hcd: release socket
> [ 1465.231558] vhci_hcd: disconnect device
> [ 1466.209577] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(3)
> [ 1466.209586] vhci_hcd vhci_hcd.0: devid(65538) speed(3) speed_str(high-speed)
> [ 1466.209632] vhci_hcd vhci_hcd.0: Device attached
> [ 1466.234515] hid-generic 0003:20A0:42B2.0007: hiddev98,hidraw6: USB HID v1.11 Device [Nitrokey Nitrokey 3] on usb-vhci_hcd.0-1/input0
> [ 1480.014598] usb 5-1: recv xbuf, 0
> [ 1480.014620] usercopy: Kernel memory exposure attempt detected from SLUB object 'kmalloc-16' (offset 0, size 64)!

Then vhci-hcd is not happy.

I did not reproduce the kernel BUG though. I was using 5.15.47-1-lts
from Arch.

I guess if usbip-runner behaves normally then such error
wont be happen.

But other way around: the abnormal exit of usbip-host
should not lead to vhci_hcd bugs. There may be URB
not freed when usbip-host exits, but
I have not investigated into it yet.

> [ 1480.014631] ------------[ cut here ]------------
> [ 1480.014633] kernel BUG at mm/usercopy.c:101!
> [ 1480.014640] invalid opcode: 0000 [#1] PREEMPT SMP NOPTI
> [ 1480.014644] CPU: 2 PID: 3912 Comm: pcscd Not tainted 6.1.4-arch1-1 #1 b56a0be67d6a5f69f99015da4a908cae98ee5acc
> [ 1480.014649] Hardware name: LENOVO 82NW/LNVNB161216, BIOS G9CN23WW 09/01/2021
> [ 1480.014652] RIP: 0010:usercopy_abort+0x79/0x7b
> [ 1480.014665] Code: a5 a5 51 48 0f 45 d6 48 89 c1 49 c7 c3 b0 82 a5 a5 41 52 48 c7 c6 2a de a4 a5 48 c7 c7 b0 2e ae a5 49 0f 45 f3 e8 34 57 ff ff <0f> 0b 48 89 f1 49 89 e8 44 89 e2 31 f6 48 c7 c7 fa 82 a5 a5 e8 6e
> [ 1480.014667] vhci_hcd: stop threads
> [ 1480.014669] RSP: 0018:ffffbc854a5bbd28 EFLAGS: 00010246
> [ 1480.014674] RAX: 0000000000000064 RBX: 0000000000000000 RCX: 0000000000000000
> [ 1480.014678] RDX: 0000000000000000 RSI: ffff98e85fea1660 RDI: ffff98e85fea1660
> [ 1480.014680] RBP: 0000000000000040 R08: 0000000000000000 R09: ffffbc854a5bbbc0
> [ 1480.014682] vhci_hcd: release socket
> [ 1480.014682] R10: 0000000000000003 R11: ffffffffa62cb828 R12: ffff98e5c0042300
> [ 1480.014683] R13: 0000000000000001 R14: 0000000000000040 R15: ffff98e67a690e80
> [ 1480.014686] FS:  00007f7b4a3a66c0(0000) GS:ffff98e85fe80000(0000) knlGS:0000000000000000
> [ 1480.014687] vhci_hcd: disconnect device
> [ 1480.014688] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1480.014690] CR2: 00007f7b4a374ff8 CR3: 00000001ba794000 CR4: 0000000000750ee0
> [ 1480.014692] PKRU: 55555554
> [ 1480.014694] Call Trace:
> [ 1480.014697]  <TASK>
> [ 1480.014699]  __check_heap_object+0xd9/0x110
> [ 1480.014706]  __check_object_size+0x1ea/0x210
> [ 1480.014711]  copy_urb_data_to_user+0xfc/0x120
> [ 1480.014715]  ? __rseq_handle_notify_resume+0xad/0x4a0
> [ 1480.014720]  processcompl+0xc8/0x140
> [ 1480.014722]  usbdev_ioctl+0x120/0x1280
> [ 1480.014724] usb 5-1: USB disconnect, device number 2
> [ 1480.014726]  ? exit_to_user_mode_prepare+0x16f/0x1d0
> [ 1480.014731]  ? syscall_exit_to_user_mode+0x1b/0x40
> [ 1480.014735]  ? do_syscall_64+0x6b/0x90
> [ 1480.014739]  __x64_sys_ioctl+0x94/0xd0
> [ 1480.014744]  do_syscall_64+0x5f/0x90
> [ 1480.014746]  ? syscall_exit_to_user_mode+0x1b/0x40
> [ 1480.014749]  ? do_syscall_64+0x6b/0x90
> [ 1480.014751]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
> [ 1480.014756] RIP: 0033:0x7f7b4d79cc0f
> [ 1480.014778] Code: 00 48 89 44 24 18 31 c0 48 8d 44 24 60 c7 04 24 10 00 00 00 48 89 44 24 08 48 8d 44 24 20 48 89 44 24 10 b8 10 00 00 00 0f 05 <89> c2 3d 00 f0 ff ff 77 18 48 8b 44 24 18 64 48 2b 04 25 28 00 00
> [ 1480.014780] RSP: 002b:00007f7b4a385500 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [ 1480.014783] RAX: ffffffffffffffda RBX: 00007f7b440705a0 RCX: 00007f7b4d79cc0f
> [ 1480.014785] RDX: 00007f7b4a385580 RSI: 000000004008550d RDI: 000000000000000d
> [ 1480.014786] RBP: 000000000000001a R08: 000000000000000d R09: 0000000000000000
> [ 1480.014787] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
> [ 1480.014789] R13: 0000000000000003 R14: 0000000000000001 R15: 00007f7b440705a0
> [ 1480.014794]  </TASK>
> [ 1480.014795] Modules linked in: vhci_hcd rfcomm snd_seq_dummy snd_hrtimer snd_seq snd_seq_device ccm wireguard curve25519_x86_64 libchacha20poly1305 chacha_x86_64 poly1305_x86_64 libcurve25519_generic libchacha ip6_udp_tunnel udp_tunnel cmac algif_hash algif_skcipher af_alg snd_sof_amd_rembrandt bnep intel_rapl_msr snd_sof_amd_renoir snd_sof_amd_acp snd_sof_pci snd_sof snd_sof_utils rtw89_8852ae snd_hda_codec_realtek intel_rapl_common snd_soc_core rtw89_8852a snd_hda_codec_generic ledtrig_audio snd_compress rtw89_pci snd_hda_codec_hdmi ac97_bus rtw89_core snd_hda_intel snd_pcm_dmaengine snd_intel_dspcfg snd_intel_sdw_acpi hid_multitouch snd_pci_ps amdgpu wmi_bmof edac_mce_amd snd_hda_codec snd_rpl_pci_acp6x mac80211 btusb snd_hda_core snd_acp_pci snd_pci_acp6x snd_hwdep btrtl snd_pci_acp5x gpu_sched btbcm snd_pcm snd_rn_pci_acp3x r8169 drm_buddy kvm_amd btintel ideapad_laptop libarc4 snd_acp_config realtek drm_ttm_helper ucsi_acpi cfg80211 sp5100_tco typec_ucsi ttm btmtk snd_timer
> [ 1480.014861]  mdio_devres cm32181 snd_soc_acpi vfat sparse_keymap kvm irqbypass rapl wdat_wdt pcspkr typec fat bluetooth k10temp platform_profile ecdh_generic i2c_piix4 snd snd_pci_acp3x drm_display_helper soundcore libphy cec rfkill roles video wmi mousedev industrialio lzo_rle i2c_hid_acpi joydev i2c_hid acpi_cpufreq mac_hid usbip_host usbip_core pkcs8_key_parser dm_multipath crypto_user fuse zram bpf_preload ip_tables x_tables ext4 crc32c_generic crc16 mbcache jbd2 usbhid dm_crypt cbc encrypted_keys trusted asn1_encoder tee dm_mod serio_raw atkbd libps2 crct10dif_pclmul crc32_pclmul crc32c_intel polyval_clmulni polyval_generic gf128mul ghash_clmulni_intel vivaldi_fmap sha512_ssse3 aesni_intel nvme crypto_simd nvme_core xhci_pci cryptd ccp i8042 xhci_pci_renesas nvme_common serio
> [ 1480.014912] ---[ end trace 0000000000000000 ]---
> [ 1480.014914] RIP: 0010:usercopy_abort+0x79/0x7b
> [ 1480.014917] Code: a5 a5 51 48 0f 45 d6 48 89 c1 49 c7 c3 b0 82 a5 a5 41 52 48 c7 c6 2a de a4 a5 48 c7 c7 b0 2e ae a5 49 0f 45 f3 e8 34 57 ff ff <0f> 0b 48 89 f1 49 89 e8 44 89 e2 31 f6 48 c7 c7 fa 82 a5 a5 e8 6e
> [ 1480.014919] RSP: 0018:ffffbc854a5bbd28 EFLAGS: 00010246
> [ 1480.014921] RAX: 0000000000000064 RBX: 0000000000000000 RCX: 0000000000000000
> [ 1480.014923] RDX: 0000000000000000 RSI: ffff98e85fea1660 RDI: ffff98e85fea1660
> [ 1480.014924] RBP: 0000000000000040 R08: 0000000000000000 R09: ffffbc854a5bbbc0
> [ 1480.014925] R10: 0000000000000003 R11: ffffffffa62cb828 R12: ffff98e5c0042300
> [ 1480.014927] R13: 0000000000000001 R14: 0000000000000040 R15: ffff98e67a690e80
> [ 1480.014928] FS:  00007f7b4a3a66c0(0000) GS:ffff98e85fe80000(0000) knlGS:0000000000000000
> [ 1480.014930] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1480.014932] CR2: 00007f7b4a374ff8 CR3: 00000001ba794000 CR4: 0000000000750ee0
> [ 1480.014934] PKRU: 55555554
> [ 1480.030021] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(3)
> [ 1480.030025] vhci_hcd vhci_hcd.0: devid(65538) speed(3) speed_str(high-speed)
> [ 1480.030034] vhci_hcd vhci_hcd.0: Device attached
> [ 1480.030396] kauditd_printk_skb: 3 callbacks suppressed