| Message ID | 155be9e56e650dd7f7baf1c7e193e1a3d85e7141.camel@gmail.com (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | [v3] usb: gadget: u_ether: Use __netif_rx() in rx_callback() | expand |
On 2024-09-17 15:56:33 [+0200], Hubert Wiśniewski wrote: > netif_rx() now disables bottom halves, which causes the USB gadget to be > unable to receive frames if the interface is not brought up quickly enough > after being created by the driver (a bug confirmed on AM3352 SoC). > > Replacing netif_rx() with __netif_rx() restores the old behavior and fixes > the bug. This can be done since rx_callback() is called from the interrupt > context. > > Fixes: baebdf48c360 ("net: dev: Makes sure netif_rx() can be invoked in any context.") > Cc: stable@vger.kernel.org > Signed-off-by: Hubert Wiśniewski <hubert.wisniewski.25632@gmail.com> Now that I see v3, my v2 question stands. This supposed only to disable BH if invoked from from non-interrupt. hardirq and softirq should be good. A backtrace would be nice and further explanation how this becomes a problem. Also lockdep should complain at some point. Sebastian
On Tue, 2024-09-17 at 16:36 +0200, Sebastian Andrzej Siewior wrote: > On 2024-09-17 15:56:33 [+0200], Hubert Wiśniewski wrote: > > netif_rx() now disables bottom halves, which causes the USB gadget to be > > unable to receive frames if the interface is not brought up quickly enough > > after being created by the driver (a bug confirmed on AM3352 SoC). > > > > Replacing netif_rx() with __netif_rx() restores the old behavior and fixes > > the bug. This can be done since rx_callback() is called from the interrupt > > context. > > > > Fixes: baebdf48c360 ("net: dev: Makes sure netif_rx() can be invoked in any context.") > > Cc: stable@vger.kernel.org > > Signed-off-by: Hubert Wiśniewski <hubert.wisniewski.25632@gmail.com> > > Now that I see v3, my v2 question stands. > This supposed only to disable BH if invoked from from non-interrupt. > hardirq and softirq should be good. A backtrace would be nice and further > explanation how this becomes a problem. Also lockdep should complain at > some point. > > Sebastian This lockup seems to occur only on AM335x SoCs. If the interface is brought up immediately after it is created: # modprobe g_ether; ip link set usb0 up it works fine. But if there is some delay: # modprobe g_ether; sleep 5; ip link set usb0 up the interface is unable to receive any frames from the USB host (but the outgoing frames are sent correctly). This becomes a problem when the g_ether module is loaded early in the boot process or it is built in, and the interface is configured later (e.g. by ifupdown). The same thing happens when using configfs to create and configure an Ethernet gadget. I have built the kernel with CONFIG_PROVE_LOCKING=y and got the following messages upon bringing the interface up: Backtrace (timestamps stripped): WARNING: CPU: 0 PID: 86 at kernel/softirq.c:362 __local_bh_enable_ip+0x118/0x198 CPU: 0 UID: 0 PID: 86 Comm: ip Not tainted 6.11.0 #3 Hardware name: Generic AM33XX (Flattened Device Tree) Call trace: unwind_backtrace from show_stack+0x10/0x14 show_stack from dump_stack_lvl+0x68/0x88 dump_stack_lvl from __warn+0x70/0x1ac __warn from warn_slowpath_fmt+0x12c/0x1c4 warn_slowpath_fmt from __local_bh_enable_ip+0x118/0x198 __local_bh_enable_ip from netif_rx+0x118/0x208 netif_rx from rx_complete+0x140/0x27c rx_complete from musb_g_giveback+0xf0/0x1d8 musb_g_giveback from musb_ep_restart_resume_work+0x8/0x10 musb_ep_restart_resume_work from musb_gadget_queue+0x1c8/0x498 musb_gadget_queue from usb_ep_queue+0x38/0x134 usb_ep_queue from rx_submit+0xdc/0x1cc rx_submit from rx_fill+0x7c/0xa0 rx_fill from eth_start+0x30/0x54 eth_start from eth_open+0x40/0x80 eth_open from __dev_open+0xe0/0x174 __dev_open from __dev_change_flags+0x160/0x1d0 __dev_change_flags from dev_change_flags+0x1c/0x58 dev_change_flags from devinet_ioctl+0x6d0/0x884 devinet_ioctl from inet_ioctl+0x1ac/0x2bc inet_ioctl from sock_ioctl+0x2c0/0x3b8 sock_ioctl from sys_ioctl+0x194/0xf88 sys_ioctl from ret_fast_syscall+0x0/0x1c Exception stack(0xe1485fa8 to 0xe1485ff0) 5fa0: 000b3630 00000001 00000003 00008914 be802cd8 be802c90 5fc0: 000b3630 00000001 00000003 00000036 ffffffff ffffffff ffffffff be802ed4 5fe0: 000c74cc be802c80 00028000 b6e7d14c irq event stamp: 2581 hardirqs last enabled at (2579): [<c13e10cc>] _raw_spin_unlock_irqrestore+0x44/0x48 hardirqs last disabled at (2580): [<c13e0e94>] _raw_spin_lock_irqsave+0x64/0x68 softirqs last enabled at (2558): [<c0e727b0>] __dev_change_flags+0x7c/0x1d0 softirqs last disabled at (2581): [<c0e68dd8>] netif_rx+0xa4/0x208 Lockdep: ================================ WARNING: inconsistent lock state 6.11.0 #3 Tainted: G W -------------------------------- inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage. ip/86 [HC0[0]:SC0[0]:HE1:SE1] takes: c3e54050 (&musb->lock){?.-.}-{2:2}, at: musb_g_giveback+0xf8/0x1d8 {IN-HARDIRQ-W} state was registered at: lock_acquire+0x108/0x358 _raw_spin_lock_irqsave+0x4c/0x68 dsps_interrupt+0x28/0x278 __handle_irq_event_percpu+0xa0/0x2f4 handle_irq_event_percpu+0xc/0x40 handle_irq_event+0x38/0xcc handle_level_irq+0xb4/0x13c handle_irq_desc+0x1c/0x2c generic_handle_arch_irq+0x2c/0x64 call_with_stack+0x18/0x20 __irq_svc+0x9c/0xbc console_flush_all+0x25c/0x5c0 console_unlock+0x80/0x114 vprintk_emit+0x248/0x354 dev_vprintk_emit+0x110/0x144 dev_printk_emit+0x28/0x50 __dev_printk+0x74/0x90 _dev_warn+0x3c/0x68 _regulator_get+0x1f8/0x31c sdhci_omap_regulator_get_caps+0x8/0x84 sdhci_omap_probe+0x208/0x788 platform_probe+0x58/0xb8 really_probe+0xc4/0x28c __driver_probe_device+0x84/0x194 driver_probe_device+0x30/0xc8 __device_attach_driver+0xa4/0xe0 bus_for_each_drv+0x80/0xd0 __device_attach_async_helper+0xa8/0xdc async_run_entry_fn+0x20/0xb4 process_scheduled_works+0x254/0x6e8 worker_thread+0x13c/0x340 kthread+0xf4/0x114 ret_from_fork+0x14/0x24 irq event stamp: 2649 hardirqs last enabled at (2649): [<c13e10cc>] _raw_spin_unlock_irqrestore+0x44/0x48 hardirqs last disabled at (2648): [<c13e0e94>] _raw_spin_lock_irqsave+0x64/0x68 softirqs last enabled at (2644): [<c014b410>] handle_softirqs+0x260/0x45c softirqs last disabled at (2613): [<c1385f28>] call_with_stack+0x18/0x20 other info that might help us debug this: Possible unsafe locking scenario: CPU0 ---- lock(&musb->lock); <Interrupt> lock(&musb->lock); *** DEADLOCK *** 1 lock held by ip/86: #0: c1d60ca4 (rtnl_mutex){+.+.}-{3:3}, at: devinet_ioctl+0xc4/0x884 stack backtrace: CPU: 0 UID: 0 PID: 86 Comm: ip Tainted: G W 6.11.0 #3 Tainted: [W]=WARN Hardware name: Generic AM33XX (Flattened Device Tree) Call trace: unwind_backtrace from show_stack+0x10/0x14 show_stack from dump_stack_lvl+0x68/0x88 dump_stack_lvl from mark_lock.part.17+0x3cc/0x440 mark_lock.part.17 from __lock_acquire+0x44c/0x22b0 __lock_acquire from lock_acquire+0x108/0x358 lock_acquire from _raw_spin_lock+0x38/0x48 _raw_spin_lock from musb_g_giveback+0xf8/0x1d8 musb_g_giveback from musb_ep_restart_resume_work+0x8/0x10 musb_ep_restart_resume_work from musb_gadget_queue+0x1c8/0x498 musb_gadget_queue from usb_ep_queue+0x38/0x134 usb_ep_queue from rx_submit+0xdc/0x1cc rx_submit from rx_fill+0x7c/0xa0 rx_fill from eth_start+0x30/0x54 eth_start from eth_open+0x40/0x80 eth_open from __dev_open+0xe0/0x174 __dev_open from __dev_change_flags+0x160/0x1d0 __dev_change_flags from dev_change_flags+0x1c/0x58 dev_change_flags from devinet_ioctl+0x6d0/0x884 devinet_ioctl from inet_ioctl+0x1ac/0x2bc inet_ioctl from sock_ioctl+0x2c0/0x3b8 sock_ioctl from sys_ioctl+0x194/0xf88 sys_ioctl from ret_fast_syscall+0x0/0x1c Exception stack(0xe1485fa8 to 0xe1485ff0) 5fa0: 000b3630 00000001 00000003 00008914 be802cd8 be802c90 5fc0: 000b3630 00000001 00000003 00000036 ffffffff ffffffff ffffffff be802ed4 5fe0: 000c74cc be802c80 00028000 b6e7d14c Surprisingly, with the patch I suggested, there is still a backtrace generated, but without lockdep warning: WARNING: CPU: 0 PID: 87 at net/core/dev.c:5207 __netif_rx+0xd4/0x210 CPU: 0 UID: 0 PID: 87 Comm: ip Not tainted 6.11.0-dirty #4 Hardware name: Generic AM33XX (Flattened Device Tree) Call trace: unwind_backtrace from show_stack+0x10/0x14 show_stack from dump_stack_lvl+0x68/0x88 dump_stack_lvl from __warn+0x70/0x1ac __warn from warn_slowpath_fmt+0x12c/0x1c4 warn_slowpath_fmt from __netif_rx+0xd4/0x210 __netif_rx from rx_complete+0x140/0x27c rx_complete from musb_g_giveback+0xf0/0x1d8 musb_g_giveback from musb_ep_restart_resume_work+0x8/0x10 musb_ep_restart_resume_work from musb_gadget_queue+0x1c8/0x498 musb_gadget_queue from usb_ep_queue+0x38/0x134 usb_ep_queue from rx_submit+0xdc/0x1cc rx_submit from rx_fill+0x7c/0xa0 rx_fill from eth_start+0x30/0x54 eth_start from eth_open+0x40/0x80 eth_open from __dev_open+0xe0/0x174 __dev_open from __dev_change_flags+0x160/0x1d0 __dev_change_flags from dev_change_flags+0x1c/0x58 dev_change_flags from devinet_ioctl+0x6d0/0x884 devinet_ioctl from inet_ioctl+0x1ac/0x2bc inet_ioctl from sock_ioctl+0x2c0/0x3b8 sock_ioctl from sys_ioctl+0x194/0xf88 sys_ioctl from ret_fast_syscall+0x0/0x1c Exception stack(0xe148dfa8 to 0xe148dff0) dfa0: 000b3630 00000001 00000003 00008914 be8c8cd8 be8c8c90 dfc0: 000b3630 00000001 00000003 00000036 ffffffff ffffffff ffffffff be8c8ed4 dfe0: 000c74cc be8c8c80 00028000 b6ed614c irq event stamp: 2542 hardirqs last enabled at (2541): [<c13e10cc>] _raw_spin_unlock_irqrestore+0x44/0x48 hardirqs last disabled at (2542): [<c13e0e94>] _raw_spin_lock_irqsave+0x64/0x68 softirqs last enabled at (2520): [<c0e727b0>] __dev_change_flags+0x7c/0x1d0 softirqs last disabled at (2518): [<c0e7236c>] dev_set_rx_mode+0x0/0x40 I'm a bit at loss here. The deadlock seems to be unrelated to netif_rx() (which is not being called in the interrupt context after all), yet replacing it with __netif_rx() fixes the lockup (though a warning is still generated, which suggests that the patch does not completely fix the issue).
On Thu, 2024-09-26 at 21:39 +0200, Hubert Wiśniewski wrote: > I'm a bit at loss here. The deadlock seems to be unrelated to netif_rx() > (which is not being called in the interrupt context after all), yet > replacing it with __netif_rx() fixes the lockup (though a warning is still > generated, which suggests that the patch does not completely fix the > issue). Well, never mind. After some investigation, I think the problem is as follows: 1. musb_g_giveback() releases the musb lock using spin_unlock(). The lock is now released, but hardirqs are still disabled. 2. Then, usb_gadget_giveback_request() is called, which in turn calls rx_complete(). This does not happen in the interrupt context, so netif_rx() disables bottom havles, then enables them using local_bh_enable(). 3. This leads to calling __local_bh_enable_ip(), which gives off a warning (the first backtrace) that hardirqs are disabled. Then, hardirqs are disabled (again?), and then enabled (as they should have been in the first place). 4. After usb_gadget_giveback_request() returns, musb_g_giveback() acquires the musb lock using spin_lock(). This does not disable hardirqs, so they are still enabled. 5. While the musb lock is acquired, an interrupt occurs. It is handled by dsps_interrupt(), which acquires the musb lock. A deadlock occurs. Replacing netif_rx() with __netif_rx() apparently fixes this part, as it does not lead to any change of hardirq state. There is still one problem though: rx_complete() is usually called from the interrupt context, except when the network interface is brought up. I think one solution would be to make musb_g_giveback() use spin_unlock_irqrestore() and spin_lock_irqsave(), but I would need to pass the flags to it somehow. Also, I am not sure how that would influence other drivers using musb.
On 2024-09-27 15:33:35 [+0200], Hubert Wiśniewski wrote: > On Thu, 2024-09-26 at 21:39 +0200, Hubert Wiśniewski wrote: > > I'm a bit at loss here. The deadlock seems to be unrelated to netif_rx() > > (which is not being called in the interrupt context after all), yet > > replacing it with __netif_rx() fixes the lockup (though a warning is still > > generated, which suggests that the patch does not completely fix the > > issue). > > Well, never mind. After some investigation, I think the problem is as > follows: > > 1. musb_g_giveback() releases the musb lock using spin_unlock(). The lock > is now released, but hardirqs are still disabled. > > 2. Then, usb_gadget_giveback_request() is called, which in turn calls > rx_complete(). This does not happen in the interrupt context, so netif_rx() > disables bottom havles, then enables them using local_bh_enable(). > > 3. This leads to calling __local_bh_enable_ip(), which gives off a warning > (the first backtrace) that hardirqs are disabled. Then, hardirqs are > disabled (again?), and then enabled (as they should have been in the first > place). > > 4. After usb_gadget_giveback_request() returns, musb_g_giveback() acquires > the musb lock using spin_lock(). This does not disable hardirqs, so they > are still enabled. > > 5. While the musb lock is acquired, an interrupt occurs. It is handled by > dsps_interrupt(), which acquires the musb lock. A deadlock occurs. This all makes sense so far. > Replacing netif_rx() with __netif_rx() apparently fixes this part, as it > does not lead to any change of hardirq state. There is still one problem > though: rx_complete() is usually called from the interrupt context, except > when the network interface is brought up. __netif_rx() has an assert which should complain if you use __netif_rx(). Further in this case you pass the skb to backlog but never kick it for processing. Which means it is delayed until a random interrupt notices and processes it. > I think one solution would be to make musb_g_giveback() use > spin_unlock_irqrestore() and spin_lock_irqsave(), but I would need to pass > the flags to it somehow. Also, I am not sure how that would influence other > drivers using musb. I would also suggest to do this since the other solution is not safe/ correct. There is the ->busy assignment which should cover for the most cases. If you drop the lock without enabling interrupts then the interrupt can't do anything to the EP and other enqueue/ dequeue invocation is not possible if run on UP. On the other hand am335x was used on PREEMPT_RT and it runs a UP machine into SMP so that should be covered :) While looking at it, dequeue/ enqueue during complete callback looks safe due to the busy flag. Sebastian
On Fri, 2024-09-27 at 16:12 +0200, Sebastian Andrzej Siewior wrote: > On 2024-09-27 15:33:35 [+0200], Hubert Wiśniewski wrote: > > On Thu, 2024-09-26 at 21:39 +0200, Hubert Wiśniewski wrote: > > > I'm a bit at loss here. The deadlock seems to be unrelated to netif_rx() > > > (which is not being called in the interrupt context after all), yet > > > replacing it with __netif_rx() fixes the lockup (though a warning is still > > > generated, which suggests that the patch does not completely fix the > > > issue). > > > > Well, never mind. After some investigation, I think the problem is as > > follows: > > > > 1. musb_g_giveback() releases the musb lock using spin_unlock(). The lock > > is now released, but hardirqs are still disabled. > > > > 2. Then, usb_gadget_giveback_request() is called, which in turn calls > > rx_complete(). This does not happen in the interrupt context, so netif_rx() > > disables bottom havles, then enables them using local_bh_enable(). > > > > 3. This leads to calling __local_bh_enable_ip(), which gives off a warning > > (the first backtrace) that hardirqs are disabled. Then, hardirqs are > > disabled (again?), and then enabled (as they should have been in the first > > place). > > > > 4. After usb_gadget_giveback_request() returns, musb_g_giveback() acquires > > the musb lock using spin_lock(). This does not disable hardirqs, so they > > are still enabled. > > > > 5. While the musb lock is acquired, an interrupt occurs. It is handled by > > dsps_interrupt(), which acquires the musb lock. A deadlock occurs. > > This all makes sense so far. I have done more testing on this. It seems that this deadlock possibility reported by lockdep is not the cause, but just a symptom. For now, my conclusion is that the problem lies in the MUSB gadget driver itself. Interrupts (in peripheral mode) on Rx endpoints are handled by musb_g_rx(), which pulls requests from EP request queue. If there is no request queued, it just returns without clearing the RXPKTRDY flag in the RXCSR register (but the interrupt flag in the glue layer register has been already cleared by the glue layer IRQ handler). This makes the received packet wait for the next interrupt. If the Rx FIFO is full, no more packets are received and no more interrupts are generated. The EP stays locked up forever (or until the RXPKTRDY flag is cleared manually :)). From what I have learned, the request queue being empty just happens sometimes and it is not en error. This bug became exposed by the new behaviour of netif_rx(). When BHs are enabled, hardirqs are enabled too (for a moment) which causes the Rx interrupt to be handled before a request is enqueued. If there are enough such unhandled packets, the EP gets locked up. > > Replacing netif_rx() with __netif_rx() apparently fixes this part, as it > > does not lead to any change of hardirq state. There is still one problem > > though: rx_complete() is usually called from the interrupt context, except > > when the network interface is brought up. > > __netif_rx() has an assert which should complain if you use > __netif_rx(). Further in this case you pass the skb to backlog but never > kick it for processing. Which means it is delayed until a random > interrupt notices and processes it. Now I see that it was a bad idea. I just found this using git bisect. > > I think one solution would be to make musb_g_giveback() use > > spin_unlock_irqrestore() and spin_lock_irqsave(), but I would need to pass > > the flags to it somehow. Also, I am not sure how that would influence other > > drivers using musb. > > I would also suggest to do this since the other solution is not safe/ > correct. There is the ->busy assignment which should cover for the most > cases. If you drop the lock without enabling interrupts then the > interrupt can't do anything to the EP and other enqueue/ dequeue > invocation is not possible if run on UP. On the other hand am335x was > used on PREEMPT_RT and it runs a UP machine into SMP so that should be > covered :) > > While looking at it, dequeue/ enqueue during complete callback looks > safe due to the busy flag. I think it is not needed now. After I have modified the interrupt handling code to clear the RXPKTRDY flag if there is no request queued and the FIFO is full, neither __local_bh_enable_ip() nor lockdep complain (tested on SMP and UP, with and without PREEMPT, on AM3358 and A64). It would probably by nicer to ensure that no MUSB interrupts are handled when a MUSB request callback is invoked from musb_g_giveback() (e.g. by disabling MUSB interrupts before releasing the lock and enabling them after acquiring it), but that could cause some side effects if the callback relied on MUSB interrupts being enabled. And since there are no warnings and everything works... I guess it is time to submit another patch then and to forget about this one. Thank you for your time!
diff --git a/drivers/usb/gadget/function/u_ether.c b/drivers/usb/gadget/function/u_ether.c index 4bb0553da658..fd7e483b4a48 100644 --- a/drivers/usb/gadget/function/u_ether.c +++ b/drivers/usb/gadget/function/u_ether.c @@ -266,7 +266,7 @@ static void rx_complete(struct usb_ep *ep, struct usb_request *req) /* no buffer copies needed, unless hardware can't * use skb buffers. */ - status = netif_rx(skb2); + status = __netif_rx(skb2); next_frame: skb2 = skb_dequeue(&dev->rx_frames); }
netif_rx() now disables bottom halves, which causes the USB gadget to be unable to receive frames if the interface is not brought up quickly enough after being created by the driver (a bug confirmed on AM3352 SoC). Replacing netif_rx() with __netif_rx() restores the old behavior and fixes the bug. This can be done since rx_callback() is called from the interrupt context. Fixes: baebdf48c360 ("net: dev: Makes sure netif_rx() can be invoked in any context.") Cc: stable@vger.kernel.org Signed-off-by: Hubert Wiśniewski <hubert.wisniewski.25632@gmail.com> --- v2 -> v3: Added cc stable tag v1 -> v2: Added Fixes tag and corrected Signed-off-by tag drivers/usb/gadget/function/u_ether.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)