Hi Jakub, Oliver,
On 7/15/25 3:54 PM, Jakub Kicinski wrote:
On Tue, 15 Jul 2025 07:15:51 +0000 John Ernberg wrote:
I'm worried that this is still racy. Since usbnet_bh checks if carrier is ok and __handle_link_change() checks the opposite something must be out of sync if both run. Most likely something restored the carrier while we're still handling the previous carrier loss.
There could definitely be other factors, I'll try to dig some in cdc_ether and see if something there could be causing problems for the usbnet core. I honestly kinda stopped digging when I found unlink_urbs() being wrapped with a pause/unpause at another place tied to a commit seeing a similar issue.
Looking at cdc_ether:
static void usbnet_cdc_zte_status(struct usbnet *dev, struct urb *urb) [...] if (event->wValue && netif_carrier_ok(dev->net)) netif_carrier_off(dev->net);
This looks sus. Is the Gemalto Cinterion PLS83-W ZTE based?
The modem isn't ZTE-based, but I did spot that function as well when checking cdc_ether.
The modem is advertising USB High Speed with a bInterval of 5, which in usbnet gets bumped to 7 to avoid too aggressive polling, if I read that code right.
Through some rudimentary logging with the inlined patch on 6.12.20 (mail client mangled):
-----------------8<----------------------
diff --git a/drivers/net/usb/cdc_ether.c b/drivers/net/usb/cdc_ether.c index a6469235d904..7b4827d2c797 100644 --- a/drivers/net/usb/cdc_ether.c +++ b/drivers/net/usb/cdc_ether.c @@ -418,8 +418,10 @@ void usbnet_cdc_status(struct usbnet *dev, struct urb *urb) case USB_CDC_NOTIFY_NETWORK_CONNECTION: netif_dbg(dev, timer, dev->net, "CDC: carrier %s\n", event->wValue ? "on" : "off"); - if (netif_carrier_ok(dev->net) != !!event->wValue) + if (netif_carrier_ok(dev->net) != !!event->wValue) { + netdev_err(dev->net, "network connection %d\n", (int)event->wValue); usbnet_link_change(dev, !!event->wValue, 0); + } break; case USB_CDC_NOTIFY_SPEED_CHANGE: /* tx/rx rates */ netif_dbg(dev, timer, dev->net, "CDC: speed change (len %d)\n", diff --git a/drivers/net/usb/usbnet.c b/drivers/net/usb/usbnet.c index 1e99a6ef4945..dc3e3d87b4f7 100644 --- a/drivers/net/usb/usbnet.c +++ b/drivers/net/usb/usbnet.c @@ -721,6 +721,7 @@ static int unlink_urbs (struct usbnet *dev, struct sk_buff_head *q) struct sk_buff *skb; int count = 0;
+ netdev_err(dev->net, "unlink urb start: %d devflags=%lx\n", skb_queue_len_lockless(q), dev->flags); spin_lock_irqsave (&q->lock, flags); while (!skb_queue_empty(q)) { struct skb_data *entry; @@ -757,6 +758,7 @@ static int unlink_urbs (struct usbnet *dev, struct sk_buff_head *q) spin_lock_irqsave(&q->lock, flags); } spin_unlock_irqrestore (&q->lock, flags); + netdev_err(dev->net, "unlink urb counted %d\n", count); return count; }
-----------------8<----------------------
I ended up with the following log:
[ 23.823289] cdc_ether 1-1.1:1.8 wwan0: network connection 0 [ 23.830874] cdc_ether 1-1.1:1.8 wwan0: unlink urb start: 5 devflags=1880 [ 23.840148] cdc_ether 1-1.1:1.8 wwan0: unlink urb counted 5 [ 25.356741] cdc_ether 1-1.1:1.8 wwan0: network connection 1 [ 25.364745] cdc_ether 1-1.1:1.8 wwan0: network connection 0 [ 25.371106] cdc_ether 1-1.1:1.8 wwan0: unlink urb start: 5 devflags=880 [ 25.378710] cdc_ether 1-1.1:1.8 wwan0: network connection 1 [ 51.422757] rcu: INFO: rcu_sched self-detected stall on CPU [ 51.429081] rcu: 0-....: (6499 ticks this GP) idle=da7c/1/0x4000000000000000 softirq=2067/2067 fqs=2668 [ 51.439717] rcu: hardirqs softirqs csw/system [ 51.445897] rcu: number: 62096 59017 0 [ 51.452107] rcu: cputime: 0 11397 1470 ==> 12996(ms) [ 51.459852] rcu: (t=6500 jiffies g=2397 q=663 ncpus=2)
From a USB capture where the stall didn't happen I can see: * A bunch of CDC_NETWORK_CONNECTION events with Disconnected state (0). * Then a CDC_NETWORK_CONNECTION event with Connected state (1) once the WWAN interface is turned on by the modem. * Followed by a Disconnected in the next USB INTR poll. * Followed by a Connected in the next USB INTR poll. (I'm not sure if I can achieve a different timing with enough captures or a faster system)
Which makes the off and on LINK_CHANGE events race on our system (ARM64 based, iMX8QXP) as they cannot be handled fast enough. Nothing stops usbnet_link_change() from being called while the deferred work is running.
As Oliver points out usbnet_resume_rx() causes scheduling which seems unnecessary or maybe even inappropriate for all cases except when the carrier was turned on during the race.
I gave the ZTE modem quirk a go anyway, despite the comment explaining a different situation than what I am seeing, and it has no observable effect on this RCU stall.
Currently drawing a blank on what the correct fix would be.
Best regards // John Ernberg