Oops / NULL pointer dereference when using libcomposite/HID OTG device

[mdevaev]

Describe the bug
When emulating an OTG HID Keyboard on a Raspberry Pi 4 or ZeroW, there is a chance of getting kernel oops when the USB is hot-disconnected/plugged in. This requires that the device /dev/hidg0 constantly performs a write operation while switching the connector. This happens when the /dev/hidg0 is constantly being written (spammed).

Apparently, the problem lies in f_hidg_write() which uses hidg->write_spinlock. When the device is disconnected (presumably), this variable becomes NULL, which causes oops. There's probably a race going on somewhere.

To reproduce

1. Install fresh Raspbian and configure OTG:
   • /etc/modules:

     libcomposite
     dwc2
     

   • /boot/config.txt:

     enable_uart=1
     dtoverlay=disable-bt
     dtoverlay=dwc2
     

   • reboot
2. Run attached bash script otg.txt to configure OTG.
3. Run attached python script spam.txt to perform write spam.
4. Follow the test pattern. You need to do this many times at different intervals. When the error configfs-gadget gadget: usb_ep_queue error on int endpoint -11 appears in dmesg of the Pi. the probability of oops will be high. Sometimes it can be 1:5, sometimes 1:20.
5. It will fail at some point with oops (see attached log). Redproduced not only 5.4 kernel, but on 4.x too.

Expected behaviour
No oops. Linux must correctly initialize the device each time after reconnecting, so that the user space can continue working with it.

Actual behaviour
Oops. Sometimes Linux is not able to correctly handle the fact of reconnection/disconnection.

System

• Raspberry Pi 4 Model B Rev 1.1
• /etc/rpi-issue:

  Raspberry Pi reference 2020-08-20
  Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 9a3a10bf1019ebb2d59053564dc6b90068bad27d, stage2
  

• vcgencmd version:

  Aug 19 2020 17:38:16
  Copyright (c) 2012 Broadcom
  version e90cba19a98a0d1f2ef086b9cafcbca00778f094 (clean) (release) (start)
  

• Linux raspberrypi 5.4.51-v7l+ #1333 SMP Mon Aug 10 16:51:40 BST 2020 armv7l GNU/Linux

Logs
Full dmesg with crashes: biglog.txt

When testing on Arch Linux ARM I got a slightly more detailed error location (f_hidg_write, _raw_spin_unlock_irqrestore). This applies to mouse emulation, but it was exactly the same for the keyboard:

[72347.088714] 8<--- cut here ---
[72347.094638] Unable to handle kernel NULL pointer dereference at virtual address 00000000
[72347.109127] pgd = 05f6ffed
[72347.115183] [00000000] *pgd=1e6c1003, *pmd=00000000
[72347.122794] Internal error: Oops: 206 [#1] PREEMPT SMP ARM
Entering kdb (current=0xde418f00, pid 389) on processor 1 Oops: (null)
due to oops @ 0xbf29bac4
CPU: 1 PID: 389 Comm: kvmd/hid-mouse: Tainted: G        WC        5.4.61-2-ARCH #1
Hardware name: BCM2711
PC is at f_hidg_write+0xa0/0x300 [usb_f_hid]
LR is at _raw_spin_unlock_irqrestore+0x38/0x64
pc : [<bf29bac4>]    lr : [<c0d23388>]    psr: 600f0013
sp : ddeb5f18  ip : bf29ba24  fp : de5fdcc0
r10: 00000000  r9 : b4a0b480  r8 : def96f2c
r7 : 00000000  r6 : 00000007  r5 : 600f0013  r4 : def96f00
r3 : 00000000  r2 : 00000000  r1 : 600f0013  r0 : 00000000
Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 30c5383d  Table: 1e6a1b80  DAC: 55555555
CPU: 1 PID: 389 Comm: kvmd/hid-mouse: Tainted: G        WC        5.4.61-2-ARCH #1
Hardware name: BCM2711
[<c0210ca8>] (unwind_backtrace) from [<c020c57c>] (show_stack+0x10/0x14)
[<c020c57c>] (show_stack) from [<c0d040cc>] (dump_stack+0x90/0xb0)
[<c0d040cc>] (dump_stack) from [<c02fa4a0>] (kdb_main_loop+0x4b8/0x98c)
[<c02fa4a0>] (kdb_main_loop) from [<c02fd40c>] (kdb_stub+0x258/0x460)
[<c02fd40c>] (kdb_stub) from [<c02f2908>] (kgdb_cpu_enter+0x3dc/0x6c0)

Additional context
The problem was detected when using an OTG keyboard to control a computer that was rebooted. To get into the BIOS, the user sent an event to /dev/hidg0 that was responsible for the F12 key. During boot, the USB is reinitialized several times so that the Pi is perceived as enabling and disabling the OTG host. The same thing happens if you just pull out and insert the USB cable.

[Testato]

+1

[mdevaev]

Could it be related with #3151?

[pelwell]

Have you tried applying the patch in #3151 to see if it solves the problem?

[mdevaev]

I'm just about to do it. The fact is that I found the patch and the problem after I created this Issue.

[mdevaev]

@pelwell I just tested it.
That patch #3151 really fixes the problem of the usb state, that is, I see that when the cable is hot disconnected, the state has changed:

pi@raspberrypi:~ $ cat /sys/class/udc/fe980000.usb/state
configured
pi@raspberrypi:~ $ cat /sys/class/udc/fe980000.usb/state
not attached

But this does NOT fix the problem described in this issue. The kernel still does oops :(

It seems to be an independent issue.

[mdevaev]

@pelwell I spent a few hours and found a synthetic pattern that completely reproduces the problem on the Raspberry Pi 4. The problem persists regardless of whether the patch #3151 is present. I tried default kernel 5.4.51 and patched 5.4.68 from git.

To reproduce the problem, you need to configure the system as I described in the first post and have the attached scripts otg.sh and spam.py. Since the test requires reconnecting the USB OTG cable, I used this circuit to power the RPi. No underpower detected btw. I think the powering via GPIO pins will work fine either. Also I used my linux laptop as USB host.

So, the steps:

• Power on the RPi.
• Run sudo ./otg.sh.

I found two patterns. Sometimes the first one is triggered immediately, if it didn't work, you need to continue the first one with the second one, and repeat this until the crash occurs. This is usually 1-2 times.

The first pattern:

• Connect USB OTG cable to external host.
• Disconnect USB OTG cable.
• Start sudo ./spam.py.
• Connect USB OTG
• The first possibility of the crash is here

If not, continue with this:

• Ctrl+C on spam.py.
• Disconnect cable.
• Start spam.py.
• Connect cable.
• The second possibility of the crash is here, repeat from ctrl+c if not

Each time, it's the same NULL dereference failure inside f_hidg_write().

This problem exists on Zero with the same stacktrace, although locally I could not reproduce it on this Board with this pattern. Maybe it's just a single processor core or something. However, I received several stacktraces from my users who used Zero. The content is exactly the same as attached to issue: NULL and f_hidg_write(). The stacktrace on Arch Linux ARM was more accurate and showed, as I said, on _raw_spin_unlock_irqrestore().

I'm sorry if I'm too intrusive. How can I help to resolve this bug? It's just really urgent for me and my users who use Raspberry to manage their servers.

[pelwell]

From your log, the driver is in f_hidg_write, and is crashing when it evaluates req->buf in:

        status = copy_from_user(req->buf, buffer, count);

because hidg->req a few lines earlier was zero.

Adding a simple if (req) before that line would fix most if not all of the problems, but I want to see it crash first to give me confidence that the patch is making a difference.

[pelwell]

Note that I've been trying on the Zero - I'll have to locate a different power supply to try the 4B.

[mdevaev]

Okay, here what I did (the patch that fixes the states is also applied):

--- a/drivers/usb/gadget/function/f_hid.c
+++ b/drivers/usb/gadget/function/f_hid.c
@@ -364,6 +364,14 @@ static ssize_t f_hidg_write(struct file *file, const char __user *buffer,
    count  = min_t(unsigned, count, hidg->report_length);

    spin_unlock_irqrestore(&hidg->write_spinlock, flags);
+
+   if (!req) {
+       ERROR(hidg->func.config->cdev,
+           "+++++++++++++++++++++++++ copy_from_user error: req->buf is NULL\n");
+       status = -EINVAL;
+       goto release_write_pending;
+   }
+
    status = copy_from_user(req->buf, buffer, count);

    if (status != 0) {

I am confused by the fact that such a check is ALREADY in the kernel, but it seems that it is implemented incorrectly: here. That is, req = hidg->req at the line 363. Next it tries to refer to req->buf at 367, that is, BEFORE checking for NULL at 378. In line 380, an attempt will be made to release NULL using free_ep_req(). It doesn't make any sense at all. I think we can throw out the lines 379-386 and apply something like my patch above.

I tried testing this patch and it seems it helped. Oops disappeared, but a couple of times I was able to catch another error:

[  127.047314] ------------[ cut here ]------------
[  127.047329] WARNING: CPU: 1 PID: 561 at drivers/usb/gadget/udc/core.c:276 usb_ep_queue+0x10c/0x110
[  127.047334] Modules linked in: usb_f_hid 8021q garp stp llc brcmfmac brcmutil sha256_generic libsha256 cfg80211 rfkill raspberrypi_hwmon bcm2835_v4l2(C) bcm2835_codec(C) bcm2835_isp(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common vc_sm_cma(C) videodev mc rpivid_mem uio_pdrv_genirq uio dwc2 libcomposite ip_tables x_tables ipv6
[  127.047402] CPU: 1 PID: 561 Comm: python Tainted: G         C        5.4.68-v7l-hidbug+ #2
[  127.047406] Hardware name: BCM2711
[  127.047409] Backtrace:
[  127.047421] [<c020d4e0>] (dump_backtrace) from [<c020d7dc>] (show_stack+0x20/0x24)
[  127.047426]  r6:e4940000 r5:00000000 r4:c129f4fc r3:a44b0142
[  127.047434] [<c020d7bc>] (show_stack) from [<c0a7aba4>] (dump_stack+0xe0/0x124)
[  127.047441] [<c0a7aac4>] (dump_stack) from [<c0221d58>] (__warn+0xec/0x104)
[  127.047447]  r8:00000114 r7:00000009 r6:c0e2e954 r5:00000000 r4:00000000 r3:a44b0142
[  127.047453] [<c0221c6c>] (__warn) from [<c0221e28>] (warn_slowpath_fmt+0xb8/0xc0)
[  127.047458]  r9:c0e2e954 r8:00000114 r7:c0881e08 r6:00000009 r5:00000000 r4:c1204fc8
[  127.047464] [<c0221d74>] (warn_slowpath_fmt) from [<c0881e08>] (usb_ep_queue+0x10c/0x110)
[  127.047469]  r9:60000013 r8:e4d74f2c r7:e4dead80 r6:e4dead80 r5:e5bdf540 r4:e4d74f00
[  127.047484] [<c0881cfc>] (usb_ep_queue) from [<bf14bf9c>] (f_hidg_write+0x2c0/0x328 [usb_f_hid])
[  127.047488]  r7:e4d9b6c0 r6:e4dead80 r5:00000008 r4:e4d74f00
[  127.047498] [<bf14bcdc>] (f_hidg_write [usb_f_hid]) from [<c040874c>] (__vfs_write+0x48/0x1e0)
[  127.047503]  r10:00000004 r9:00000008 r8:e4941f60 r7:e4941f60 r6:a44b0142 r5:e5339900
[  127.047506]  r4:c1204fc8
[  127.047513] [<c0408704>] (__vfs_write) from [<c040b61c>] (vfs_write+0xb4/0x1c8)
[  127.047518]  r9:e4940000 r8:b67b55b4 r7:e4941f60 r6:b67b55b4 r5:e5339900 r4:00000008
[  127.047524] [<c040b568>] (vfs_write) from [<c040b8fc>] (ksys_write+0x70/0xec)
[  127.047529]  r8:b67b55b4 r7:00000008 r6:e5339900 r5:c1204fc8 r4:e5339900
[  127.047535] [<c040b88c>] (ksys_write) from [<c040b990>] (sys_write+0x18/0x1c)
[  127.047540]  r8:c02011c4 r7:00000004 r6:00000002 r5:007c1198 r4:00000008
[  127.047546] [<c040b978>] (sys_write) from [<c0201000>] (ret_fast_syscall+0x0/0x28)
[  127.047550] Exception stack(0xe4941fa8 to 0xe4941ff0)
[  127.047555] 1fa0:                   00000008 007c1198 00000003 b67b55b4 00000008 00000000
[  127.047560] 1fc0: 00000008 007c1198 00000002 00000004 b67b62c8 b67b6190 00000001 007c1198
[  127.047564] 1fe0: 0029f1ac bea6c3d0 001169d0 b6f54180
[  127.047568] ---[ end trace 3f75db016494a6b8 ]---
[  127.047574] configfs-gadget gadget: usb_ep_queue error on int endpoint -108
[  127.047598] configfs-gadget gadget: +++++++++++++++++++++++++ copy_from_user error: req->buf is NULL
[  127.058303] dwc2 fe980000.usb: new device is high-speed
[  127.131726] dwc2 fe980000.usb: new device is high-speed
[  127.193712] dwc2 fe980000.usb: new address 109

UPD: req->buf is NULL should be read as req is NULL, just a typo in my patch.

[pelwell]

With a suitably-powered 4B I was able to reproduce the bug just before the end of the day, so expect progress tomorrow.

[mdevaev]

With a suitably-powered 4B I was able to reproduce the bug just before the end of the day, so expect progress tomorrow.

Oh, that's great news! Thank you. I hope there's something I can do to help.

By the way, line 398 leads to spam in dmesg:

[  284.199807] configfs-gadget gadget: usb_ep_queue error on int endpoint -11
[  284.199839] configfs-gadget gadget: usb_ep_queue error on int endpoint -11
[  284.199870] configfs-gadget gadget: usb_ep_queue error on int endpoint -11

In fact, the kernel reports every EAGAIN from the user software. I think it must be ignored for the -11 code. The same applies to my patch, logging is not necessary here at all, I think. Or at least it should be at the debug level.

[mdevaev]

Another similar catch:

[  172.321400] configfs-gadget gadget: usb_ep_queue error on int endpoint -11
[  172.321450] configfs-gadget gadget: usb_ep_queue error on int endpoint -11
[  172.321482] configfs-gadget gadget: usb_ep_queue error on int endpoint -11
[  172.321547] WARNING: CPU: 1 PID: 582 at drivers/usb/gadget/udc/core.c:276 usb_ep_queue+0x10c/0x110
[  172.321625] CPU: 1 PID: 582 Comm: python Tainted: G         C        5.4.68-v7l-hidbug+ #2
[  172.321628] Hardware name: BCM2711
[  172.321632] Backtrace: 
[  172.321651]  r6:e517a000 r5:00000000 r4:c129f4fc r3:a44b0142
[  172.321672]  r8:00000114 r7:00000009 r6:c0e2e954 r5:00000000 r4:00000000 r3:a44b0142
[  172.321683]  r9:c0e2e954 r8:00000114 r7:c0881e08 r6:00000009 r5:00000000 r4:c1204fc8
[  172.321694]  r9:e517a000 r8:60000013 r7:e5185100 r6:e5185100 r5:e543f040 r4:e4ee0000
[  172.321730] [<bf19dcdc>] (f_hidg_write [usb_f_hid]) from [<c040874c>] (__vfs_write+0x48/0x1e0)
[  172.321750]  r9:e517a000 r8:b67a7594 r7:e517bf60 r6:b67a7594 r5:e5b30240 r4:00000008
[  172.321760]  r8:b67a7594 r7:00000008 r6:e5b30240 r5:c1204fc8 r4:e5b30240
[  172.321778] [<c040b978>] (sys_write) from [<c0201000>] (ret_fast_syscall+0x0/0x28)
[  172.321792] bfc0: 00000008 01959198 00000002 00000004 b67a82c8 b67a8190 00000001 01959198
[  172.321801] ---[ end trace 709129941f368f48 ]---
[  172.321838] configfs-gadget gadget: +++++++++++++++++++++++++ copy_from_user error: req->buf is NULL
[  172.321853] configfs-gadget gadget: +++++++++++++++++++++++++ copy_from_user error: req->buf is NULL
[  172.321867] configfs-gadget gadget: +++++++++++++++++++++++++ copy_from_user error: req->buf is NULL

UPD: req->buf is NULL should be read as req is NULL, just a typo in my patch.

[pelwell]

Can you try with these patches?

diff --git a/drivers/usb/gadget/function/f_hid.c b/drivers/usb/gadget/function/f_hid.c
index f3816a5c861e..7c0341a139e7 100644
--- a/drivers/usb/gadget/function/f_hid.c
+++ b/drivers/usb/gadget/function/f_hid.c
@@ -344,6 +344,11 @@ static ssize_t f_hidg_write(struct file *file, const char __user *buffer,
 
        spin_lock_irqsave(&hidg->write_spinlock, flags);
 
+       if (!hidg->req) {
+               spin_unlock_irqrestore(&hidg->write_spinlock, flags);
+               return -ESHUTDOWN;
+       }
+
 #define WRITE_COND (!hidg->write_pending)
 try_again:
        /* write queue */
@@ -364,7 +369,13 @@ static ssize_t f_hidg_write(struct file *file, const char __user *buffer,
        count  = min_t(unsigned, count, hidg->report_length);
 
        spin_unlock_irqrestore(&hidg->write_spinlock, flags);
-       status = copy_from_user(req->buf, buffer, count);
+       if (req)
+               status = copy_from_user(req->buf, buffer, count);
+       else {
+               pr_err("hidg->req is NULL\n");
+               status = -ESHUTDOWN;
+               goto release_write_pending;
+       }
 
        if (status != 0) {
                ERROR(hidg->func.config->cdev,
@@ -393,10 +404,14 @@ static ssize_t f_hidg_write(struct file *file, const char __user *buffer,
 
        spin_unlock_irqrestore(&hidg->write_spinlock, flags);
 
+       if (!hidg->in_ep->enabled) {
+               pr_err("enabled %d, req %px, hidg->req %px\n",
+                      hidg->in_ep->enabled, req, hidg->req);
+               status = -ESHUTDOWN;
+               goto release_write_pending;
+       }
        status = usb_ep_queue(hidg->in_ep, req, GFP_ATOMIC);
        if (status < 0) {
-               ERROR(hidg->func.config->cdev,
-                       "usb_ep_queue error on int endpoint %zd\n", status);
                goto release_write_pending;
        } else {
                status = count;

I usually see messages like these:

[  186.286417] enabled 0, req d6efd100, hidg->req d6efd100
[  186.296394] dwc2 fe980000.usb: new device is high-speed
[  186.397396] dwc2 fe980000.usb: new device is high-speed
[  186.486039] dwc2 fe980000.usb: new address 5
[  186.520984] configfs-gadget gadget: high-speed config #1: c

[mdevaev]

@pelwell It looks like it will work (but I had to fix the indetion in the patch :). Now I see this:

[  255.127483] configfs-gadget gadget: high-speed config #1: c
[  260.087081] dwc2 fe980000.usb: new device is high-speed
[  260.160259] dwc2 fe980000.usb: new device is high-speed
[  260.222182] dwc2 fe980000.usb: new address 40
[  260.247620] configfs-gadget gadget: high-speed config #1: c
[  265.973767] dwc2 fe980000.usb: new device is high-speed
[  266.047045] dwc2 fe980000.usb: new device is high-speed
[  266.108972] dwc2 fe980000.usb: new address 41
[  266.134700] configfs-gadget gadget: high-speed config #1: c

And sometimes If I disconnect the cable while the script is running, I get an endpoint error. But I didn't see any stacktraces:

[  289.260240] configfs-gadget gadget: End Point Request ERROR: -108
[  289.270749] dwc2 fe980000.usb: new device is high-speed
[  289.344233] dwc2 fe980000.usb: new device is high-speed
[  289.406211] dwc2 fe980000.usb: new address 42
[  289.431669] configfs-gadget gadget: high-speed config #1: c
[  417.519325] configfs-gadget gadget: End Point Request ERROR: -108
[  417.519352] enabled 0, req e4e0e700, hidg->req e4e0e700
[  417.530335] dwc2 fe980000.usb: new device is high-speed
[  417.603863] dwc2 fe980000.usb: new device is high-speed
[  417.665746] dwc2 fe980000.usb: new address 43
[  417.691698] configfs-gadget gadget: high-speed config #1: c
[  423.882868] configfs-gadget gadget: End Point Request ERROR: -108
[  423.882892] enabled 0, req e4e0ea80, hidg->req e4e0ea80
[  423.893874] dwc2 fe980000.usb: new device is high-speed
[  423.967197] dwc2 fe980000.usb: new device is high-speed
[  424.029276] dwc2 fe980000.usb: new address 44
[  424.055045] configfs-gadget gadget: high-speed config #1: c
[  425.039593] configfs-gadget gadget: End Point Request ERROR: -108
[  425.050598] dwc2 fe980000.usb: new device is high-speed
[  425.124158] dwc2 fe980000.usb: new device is high-speed
[  425.185964] dwc2 fe980000.usb: new address 45
[  425.211593] configfs-gadget gadget: high-speed config #1: c

[pelwell]

Thanks - I've tidied up that patch and pushed it, along with #3151.

[mdevaev]

@pelwell I also tried with arch linux and it seems everything is ok.

BTW is this still needed after your patch?

[pelwell]

I think it might be - the timing relationship between the write call and the disable call is unclear and possibly unsynchronized, in which case being outside the spin lock means anything is possible.

[mdevaev]

But if this is the case, there is another potential NULL dereference here: free_ep_req(hidg->in_ep, req). Since req == hidg->req, this call will fail on req->buf:

linux/drivers/usb/gadget/u_f.h

Line 78 in 65caf60

static inline void free_ep_req(struct usb_ep *ep, struct usb_request *req)

static inline void free_ep_req(struct usb_ep *ep, struct usb_request *req)
{
	WARN_ON(req->buf == NULL);
	kfree(req->buf);
	req->buf = NULL;
	usb_ep_free_request(ep, req);
}

If I'm right, then call free_ep_req(hidg->in_ep, req) must be removed, only goto should remain in the check.

[pelwell]

It's no longer crashing, and I don't want to spend any longer on what appears to be a generic problem in the HID gadget - there's nothing Pi-specific about this issue.

[mdevaev]

Okay, anyway thank you.

[mdevaev]

I read this code carefully again and it looks like I'm really wrong. I'm sorry to bother you with this. I really appreciate you fixing this bug, even though it's not directly related to Pi.

[popcornmix]

This fix is in latest rpi-update kernel.

[mdevaev]

Thanks. Just tested on Raspbian and Arch. No crash anymore, but the spam with usb_ep_queue error on int endpoint -11 is keeping. It seems that the corresponding log line was not removed in the final patch.

[pelwell]

You're right - in dropping some of the unwanted changes for this commit I also dropped this wanted one. It's there now as 6e776e6.