embassy-usb: stm32f4/usb_ethernet example shows no link in ubuntu 22.04

shuanglengyunji commented 10 months ago

I run the stm32f4/usb_ethernet example on a stm32f4discovery board with static ip. It works on an iPhone 15 runs IOS17, while doesn't work on ubuntu 22.04 running on DELL Precision 15. On the ubuntu 22.04, I manually configured IP address on the ubuntu, while it shows:

➜  ~ ifconfig enx888888888888                  
enx888888888888: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        inet 192.168.10.1  netmask 255.255.255.0  broadcast 192.168.10.255
        ether 88:88:88:88:88:88  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

➜  ~ ip addr show dev enx888888888888          
6: enx888888888888: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc fq_codel state DOWN group default qlen 1000
    link/ether 88:88:88:88:88:88 brd ff:ff:ff:ff:ff:ff
    inet 192.168.10.1/24 brd 192.168.10.255 scope global enx888888888888
       valid_lft forever preferred_lft forever

➜  ~ sudo ethtool enx888888888888         
Settings for enx888888888888:
    Supported ports: [  ]
    Supported link modes:   Not reported
    Supported pause frame use: No
    Supports auto-negotiation: No
    Supported FEC modes: Not reported
    Advertised link modes:  Not reported
    Advertised pause frame use: No
    Advertised auto-negotiation: No
    Advertised FEC modes: Not reported
    Speed: Unknown!
    Duplex: Half
    Auto-negotiation: off
    Port: Twisted Pair
    PHYAD: 0
    Transceiver: internal
    MDI-X: Unknown
        Current message level: 0x00000007 (7)
                               drv probe link
    Link detected: no

I have also tried:

Disable USB autosuspend from kernel bootargs
Disable VBUS detection

It works on the iPhone. I had also made it similar implementation work on this board with TinyUSB RNDIS driver. Could someone please give me some direction on debugging it?

On the device log, it shows USB goes into suspend mode on its own:

0.000000 INFO  Hello World!
└─ usb_ethernet::____embassy_main_task::{async_fn#0} @ src/bin/usb_ethernet.rs:49  
0.000000 TRACE BDCR ok: 00008200
└─ embassy_stm32::rcc::bd::{impl#2}::init @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000000 DEBUG flash: latency=5
└─ embassy_stm32::rcc::_version::init @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:130 
0.000000 DEBUG rcc: Clocks { sys: Hertz(168000000), pclk1: Hertz(42000000), pclk1_tim: Hertz(84000000), pclk2: Hertz(84000000), pclk2_tim: Hertz(168000000), hclk1: Hertz(168000000), hclk2: Hertz(168000000), hclk3: Hertz(168000000), plli2s1_q: None, plli2s1_r: None, pll1_q: Some(Hertz(48000000)), rtc: Some(Hertz(32000)) }
└─ embassy_stm32::rcc::set_freqs @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:130 
0.000061 TRACE allocating type=Interrupt mps=8 interval_ms=255, dir=In
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000091 TRACE   index=1
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000122 TRACE allocating type=Bulk mps=64 interval_ms=0, dir=Out
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000152 TRACE   index=1
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000183 TRACE allocating type=Bulk mps=64 interval_ms=0, dir=In
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000213 TRACE   index=2
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000244 INFO  USB: device_descriptor used: 18
└─ embassy_usb::builder::{impl#1}::build @ /home/han/Codes/embassy/embassy-usb/src/fmt.rs:143 
0.000274 INFO  USB: config_descriptor used: 94
└─ embassy_usb::builder::{impl#1}::build @ /home/han/Codes/embassy/embassy-usb/src/fmt.rs:143 
0.000305 INFO  USB: bos_descriptor used: 12
└─ embassy_usb::builder::{impl#1}::build @ /home/han/Codes/embassy/embassy-usb/src/fmt.rs:143 
0.000305 INFO  USB: msos_descriptor used: 0
└─ embassy_usb::builder::{impl#1}::build @ /home/han/Codes/embassy/embassy-usb/src/fmt.rs:143 
0.000335 INFO  USB: control_buf size: 128
└─ embassy_usb::builder::{impl#1}::build @ /home/han/Codes/embassy/embassy-usb/src/fmt.rs:143 
0.000366 TRACE allocating type=Control mps=64 interval_ms=0, dir=Out
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000396 TRACE   index=0
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000427 TRACE allocating type=Control mps=64 interval_ms=0, dir=In
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000457 TRACE   index=0
└─ embassy_stm32::usb_otg::usb::{impl#6}::alloc_endpoint @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000457 TRACE start
└─ embassy_stm32::usb_otg::usb::{impl#7}::start @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.000854 DEBUG IPv4: UP
└─ embassy_net::{impl#5}::apply_static_config @ /home/han/Codes/embassy/embassy-net/src/fmt.rs:130 
0.000854 DEBUG    IP address:      192.168.10.2/24
└─ embassy_net::{impl#5}::apply_static_config @ /home/han/Codes/embassy/embassy-net/src/fmt.rs:130 
0.000915 DEBUG    Default gateway: Some(192.168.10.1)
└─ embassy_net::{impl#5}::apply_static_config @ /home/han/Codes/embassy/embassy-net/src/fmt.rs:130 
0.001068 TRACE [0]: adding
└─ smoltcp::iface::socket_set::{impl#2}::add::put @ /home/han/.cargo/registry/src/index.crates.io-6f17d22bba15001f/smoltcp-0.11.0/src/macros.rs:17  
0.001098 INFO  Listening on TCP:1234...
└─ usb_ethernet::____embassy_main_task::{async_fn#0} @ src/bin/usb_ethernet.rs:162 
0.001098 TRACE state=Closed=>Listen
└─ smoltcp::socket::tcp::{impl#9}::set_state @ /home/han/.cargo/registry/src/index.crates.io-6f17d22bba15001f/smoltcp-0.11.0/src/macros.rs:17  
0.001129 INFO  net_task
└─ usb_ethernet::__net_task_task::{async_fn#0} @ src/bin/usb_ethernet.rs:38  
0.001159 INFO  usb_ncm_task
└─ usb_ethernet::__usb_ncm_task_task::{async_fn#0} @ src/bin/usb_ethernet.rs:32  
0.001220 TRACE WAITING for connection
└─ embassy_usb::class::cdc_ncm::embassy_net::{impl#1}::run::{async_fn#0}::{async_block#0} @ /home/han/Codes/embassy/embassy-usb/src/fmt.rs:117 
0.001251 INFO  usb_task
└─ usb_ethernet::__usb_task_task::{async_fn#0} @ src/bin/usb_ethernet.rs:26  
0.001281 TRACE Core id 00001200
└─ embassy_stm32::usb_otg::usb::{impl#9}::init @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.001281 TRACE usb: power detected
└─ embassy_usb::{impl#2}::handle_bus_event::{async_fn#0} @ /home/han/Codes/embassy/embassy-usb/src/fmt.rs:117 
0.001312 TRACE irq
└─ embassy_stm32::usb_otg::usb::{impl#0}::on_interrupt @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.001312 TRACE enable
└─ embassy_stm32::usb_otg::usb::{impl#10}::enable::{async_fn#0} @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.001342 TRACE vbus detected
└─ embassy_stm32::usb_otg::usb::{impl#10}::poll::{async_fn#0}::{closure#0} @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.001342 TRACE SETUP waiting
└─ embassy_stm32::usb_otg::usb::{impl#18}::setup::{async_fn#0}::{closure#0} @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.007293 TRACE irq
└─ embassy_stm32::usb_otg::usb::{impl#0}::on_interrupt @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.007324 TRACE suspend
└─ embassy_stm32::usb_otg::usb::{impl#10}::poll::{async_fn#0}::{closure#0} @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.007324 TRACE usb: suspend
└─ embassy_usb::{impl#2}::handle_bus_event::{async_fn#0} @ /home/han/Codes/embassy/embassy-usb/src/fmt.rs:117 
0.183746 TRACE irq
└─ embassy_stm32::usb_otg::usb::{impl#0}::on_interrupt @ /home/han/Codes/embassy/embassy-stm32/src/fmt.rs:117 
0.183746 TRACE reset

Thank you all

shuanglengyunji commented 10 months ago

Update: I found a walk-around: add sleep between spawner.spawn(usb_task(usb)) and spawner.spawn(usb_ncm_task(runner)) will make it work on ubuntu 22.04.

// Build the builder.
let usb = builder.build();

unwrap!(spawner.spawn(usb_task(usb)));
Timer::after_millis(1000).await;                     <====== ADD SLEEP HERE

static NET_STATE: StaticCell<NetState<MTU, 4, 4>> = StaticCell::new();
let (runner, device) = class.into_embassy_net_device::<MTU, 4, 4>(NET_STATE.init(NetState::new()), our_mac_addr);
unwrap!(spawner.spawn(usb_ncm_task(runner)));

In debugging it, I found the usb_ncm_task(runner) has been scheduled before usb_task(usb) on stm32f407 by the scheduler, although the usb_task is spawned before the usb_ncm_task. Adding a sleep before usb_ncm_task will ensure the usb_task to be executed first, and it seems to address the problem. However, I still don't understand the root cause of the problem.

makeshared commented 4 months ago

Thanks @shuanglengyunji - can confirm the workaround fixes usb_ethernet on stm32h753zi as well :+1:

tq-schifferm commented 1 month ago

I have run into the same issue on the STM32F429ZI, and for me a sleep of 1s was not sufficient, but 3s did the trick. I assume the difference might be that I'm running my Linux in a VMware VM, so what often happens is:

Windows host enumerates the USB device, endpoint becomes enabled
VMware removes USB device from Windows's control, endpoint is disabled
Linux VM enumerates the USB device, endpoint becomes enabled again

In the embassy_usb::class::cdc_ncm::embassy_net trace, this is visible as a quick succession of "WAITING for connection" - "Connected" - "WAITING for connection". The second time cdc_ncm::wait_connection() is run, self.read_ep.wait_enabled() and self.comm_ep.wait_enabled() finish successfully, but self.comm_ep.write(&buf) hangs forever.

The same issue also occurs when I disconnect and reconnect the USB interface physically, and there is no place where I could add a sleep to work around this.

Some other observations I've made:

The hanging comm_ep.write() outputs the following tracing messages:

TRACE write ep=EndpointAddress(129) data=[161, 0, 1, 0, 1, 0, 0, 0]
└─ embassy_usb_synopsys_otg::{impl#16}::write::{async_fn#0} @ /home/schifferm/Devel/rtos/embassy/embassy-usb-synopsys-otg/src/lib.rs:1129
TRACE write ep=EndpointAddress(129): diepctl 804c8008 ftxfsts 00000010
└─ embassy_usb_synopsys_otg::{impl#16}::write::{async_fn#0}::{closure#0} @ /home/schifferm/Devel/rtos/embassy/embassy-usb-synopsys-otg/src/lib.rs:1142

After returning Poll::Pending, the future is never woken again.

I'm seeing "ERROR received SETUP before previous finished processing" from embassy_usb_synopsys_otg::on_interrupt a few times before this happens

I assume something is going wrong with the setup sequence if the USB connection is reset while the setup is happening, but I don't know enough about the USB controller (or USB in general) to debug this much further.

tq-schifferm commented 1 month ago

Update: comm_ep.write() is hanging because the EPENA flag is never cleared (probably because the previous transfer got interrupted?).

embassy-rs / embassy

embassy-usb: stm32f4/usb_ethernet example shows no link in ubuntu 22.04 #2376