[NG Mode, IMX Host, SPI mode] Device Driver hang-up during exiting

[nguyenlkdn]

Procedure: 1) Insmod Kernel Module insmod esp32_spi.ko 2) Wait for ESP Device handshaked success! 3) Remove Kernel Module rmmode esp32_spi.ko

Device Driver hangup at step https://github.com/espressif/esp-hosted/blob/master/esp_hosted_ng/host/main.c#L381

Kernel Log:

root@gridania-pvt1-soc:~# insmod esp32_spi.ko [ 178.377244] esp32_spi: loading out-of-tree module taints kernel. [ 178.593444] esp32_spi: spi_dev_init: ESP32 peripheral is registered to SPI bus [0],chip select [0], SPI Clock [10] root@gridania-pvt1-soc:~# [ 179.201125] esp32_spi: process_rx_buf: offset_rcv[0] != exp[12], drop [ 179.381868] usb 1-1.1: USB disconnect, device number 3 [ 179.628861] usb 1-1.1: new full-speed USB device number 10 using xhci-hcd [ 179.740613] usb 1-1.1: New USB device found, idVendor=303a, idProduct=1001, bcdDevice= 1.01 [ 179.749233] usb 1-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [ 179.757942] usb 1-1.1: Product: USB JTAG/serial debug unit [ 179.764188] usb 1-1.1: Manufacturer: Espressif [ 179.769857] usb 1-1.1: SerialNumber: F4:12:FA:47:21:D8 [ 179.795503] cdc_acm 1-1.1:1.0: ttyACM0: USB ACM device [ 180.885881] esp32_spi: process_esp_bootup_event: Received ESP bootup event [ 180.893017] esp_mark_scan_done_and_disconnect [ 180.897566] esp32_spi: process_event_esp_bootup: Bootup Event tag: 3 [ 180.904160] esp32_spi: esp_validate_chipset: Chipset=ESP32-S3 ID=09 detected over SPI [ 180.912106] esp32_spi: process_event_esp_bootup: Bootup Event tag: 2 [ 180.918603] esp32_spi: adjust_spi_clock: ESP Reconfigure SPI CLK to 30 MHz [ 180.925684] esp32_spi: process_event_esp_bootup: Bootup Event tag: 0 [ 180.932211] esp32_spi: process_event_esp_bootup: Bootup Event tag: 1 [ 180.938790] esp32_spi: process_fw_data: ESP chipset's last reset cause: [ 180.945646] esp32_spi: print_reset_reason: POWERON_RESET [ 180.951108] esp32_spi: check_esp_version: ESP-Hosted Version: NG-1.0.3.0.0 [ 180.962280] esp32_spi: esp_reg_notifier: Driver init is ongoing [ 181.061931] esp32_spi: print_capabilities: Capabilities: 0xa0. Features supported are: [ 181.069929] esp32_spi: print_capabilities: * WLAN on SPI

root@gridania-pvt1-soc:~# rmmod esp32_spi.ko [ 194.152964] esp_mark_scan_done_and_disconnect [ 194.157413] esp_mark_disconnect [ 194.160555] wireless_dev_current_bss_exists [ 194.166035] Stoping wlan0 [ 194.168671] esp_mark_scan_done_and_disconnect

Note: I disabled BLE feature so print_capabilities just show WLAN on SPI

It can't going to finished one of 2 APIs

    ESP_MARK_SCAN_DONE(priv, true);
    ESP_CANCEL_SCHED_SCAN();

Because i didn't see esp_mark_disconnect() is called

[nguyenlkdn]

[ 56.693946] esp32_spi: process_esp_bootup_event: Received ESP bootup event [ 56.700980] esp_deinit_module [ 56.703952] esp_mark_scan_done_and_disconnect [ 56.708361] stop_network_iface [ 56.711433] esp_cfg_cleanup [ 56.715165] esp32_spi: process_event_esp_bootup: Bootup Event tag: 3 [ 56.721670] esp32_spi: esp_validate_chipset: Chipset=ESP32-S3 ID=09 detected over SPI [ 56.729807] esp32_spi: process_event_esp_bootup: Bootup Event tag: 2 [ 56.736360] esp32_spi: adjust_spi_clock: ESP Reconfigure SPI CLK to 30 MHz [ 56.743339] esp32_spi: process_event_esp_bootup: Bootup Event tag: 0 [ 56.749843] esp32_spi: process_event_esp_bootup: Bootup Event tag: 1 [ 56.756338] esp32_spi: process_fw_data: ESP chipset's last reset cause: [ 56.763067] esp32_spi: print_reset_reason: POWERON_RESET [ 56.768626] esp32_spi: check_esp_version: ESP-Hosted Version: NG-1.0.3.0.0 [ 56.779801] esp32_spi: esp_reg_notifier: Driver init is ongoing [ 56.879821] esp32_spi: print_capabilities: Capabilities: 0xa0. Features supported are: [ 56.888001] esp32_spi: print_capabilities: * WLAN on SPI [ 81.108270] stop_network_iface [ 81.111344] esp_mark_scan_done_and_disconnect [ 81.116754] esp_mark_scan_done_and_disconnect ESP_MARK_SCAN_DONE [ 81.124188] esp_mark_scan_done_and_disconnect ESP_CANCEL_SCHED_SCAN [ 81.130551] esp_mark_disconnect [ 81.133851] wireless_dev_current_bss_exists [ 81.138208] Stoping wlan0 [ 81.141727] esp_mark_scan_done_and_disconnect [ 81.146687] esp_mark_scan_done_and_disconnect ESP_MARK_SCAN_DONE

Add more log tracert, it looks like duplicated stopping sequence

[kapilkedawat]

@nguyenlkdn please share your kernel version. Also are you using latest master?

[mantriyogesh]

Hello @nguyenlkdn ,

1. as your offsets are not matching, can you please confirm this happens only on reload, but not on first loading of kernel module after system bootup up?

2. I see the spi transitions are out os sync for host and slave.

I suspect one of the issues:

3. Jumpers unequal length
4. Spi mode may be mismatched

Can you please:

5. Reduce spi clock to 5Mhz
6. Comment: https://github.com/espressif/esp-hosted/blob/70de43ac9cc30ef55960d8025274df7a0fe1dfc8/esp_hosted_ng/host/spi/esp_spi.c#L637 And rebuild the kernel module

[nguyenlkdn]

@nguyenlkdn please share your kernel version. Also are you using latest master?

Kernel Version 5.10(https://github.com/nxp-imx/linux-imx/tree/lf-5.10.y) and the latest master 2 weeks ago

[nguyenlkdn]

Hello @nguyenlkdn ,

1. as your offsets are not matching, can you please confirm this happens only on reload, but not on first loading of kernel module after system bootup up?
2. I see the spi transitions are out os sync for host and slave.

I suspect one of the issues: 3. Jumpers unequal length 4. Spi mode may be mismatched

Can you please: 5. Reduce spi clock to 5Mhz 6. Comment:

https://github.com/espressif/esp-hosted/blob/70de43ac9cc30ef55960d8025274df7a0fe1dfc8/esp_hosted_ng/host/spi/esp_spi.c#L637

And rebuild the kernel module

1. It occurs because during ESP32 Bootup it generated a rising on ready pin so the host fetched wrong package. but after ESP dev bootup done it able to read spi normally.

   2. Let me reduce baud-rate then see (5Mhz). I think don't need to rebuild kernel module. It able to setting on insmod esp32_spi clockspeed=5

[nguyenlkdn]

root@gridania-pvt1-soc:~# insmod esp32_spi.ko clockspeed=5 [ 1428.928493] esp32_spi: spi_dev_init: ESP32 peripheral is registered to SPI bus [0],chip select [0], SPI Clock [5] root@gridania-pvt1-soc:~# [ 1429.639974] esp32_spi: process_rx_buf: offset_rcv[0] != exp[12], drop [ 1429.693077] usb 1-1.1: USB disconnect, device number 7 [ 1429.971924] usb 1-1.1: new full-speed USB device number 8 using xhci-hcd [ 1430.077375] usb 1-1.1: New USB device found, idVendor=303a, idProduct=1001, bcdDevice= 1.01 [ 1430.085777] usb 1-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [ 1430.095186] usb 1-1.1: Product: USB JTAG/serial debug unit [ 1430.102004] usb 1-1.1: Manufacturer: Espressif [ 1430.108014] usb 1-1.1: SerialNumber: F4:12:FA:47:21:D8 [ 1430.129424] cdc_acm 1-1.1:1.0: ttyACM0: USB ACM device [ 1431.326473] esp32_spi: process_esp_bootup_event: Received ESP bootup event [ 1431.333422] esp_deinit_module [ 1431.336514] esp_mark_scan_done_and_disconnect [ 1431.341035] stop_network_iface [ 1431.344228] esp_cfg_cleanup [ 1431.347040] esp32_spi: process_event_esp_bootup: Bootup Event tag: 3 [ 1431.354562] esp32_spi: esp_validate_chipset: Chipset=ESP32-S3 ID=09 detected over SPI [ 1431.362606] esp32_spi: process_event_esp_bootup: Bootup Event tag: 2 [ 1431.369284] esp32_spi: process_event_esp_bootup: Bootup Event tag: 0 [ 1431.375787] esp32_spi: process_event_esp_bootup: Bootup Event tag: 1 [ 1431.382337] esp32_spi: process_fw_data: ESP chipset's last reset cause: [ 1431.389076] esp32_spi: print_reset_reason: POWERON_RESET [ 1431.394530] esp32_spi: check_esp_version: ESP-Hosted Version: NG-1.0.3.0.0 [ 1431.405805] esp32_spi: esp_reg_notifier: Driver init is ongoing [ 1431.518238] esp32_spi: print_capabilities: Capabilities: 0xa0. Features supported are: [ 1431.526310] esp32_spi: print_capabilities: * WLAN on SPI

root@gridania-pvt1-soc:~# rmmod esp32_spi.ko [ 1439.539977] stop_network_iface [ 1439.543441] esp_mark_scan_done_and_disconnect [ 1439.548814] priv->wdev.iftype: 2|2, scan_in_progress: 0 [ 1439.554279] esp_mark_scan_done_and_disconnect ESP_MARK_SCAN_DONE [ 1439.560357] esp_mark_scan_done_and_disconnect ESP_CANCEL_SCHED_SCAN [ 1439.566738] esp_mark_disconnect [ 1439.570087] wireless_dev_current_bss_exists [ 1439.574489] Stoping wlan0 [ 1439.577217] esp_mark_scan_done_and_disconnect [ 1439.581687] priv->wdev.iftype: 2|2, scan_in_progress: 0 [ 1439.587014] esp_mark_scan_done_and_disconnect ESP_MARK_SCAN_DONE

SPI Baurate 5Mhz result is the same it stuck at esp_stop()

[nguyenlkdn]

My Hardware Design:

• ESP32S3

[mantriyogesh]

Observattions: basically, spi offset might be having race while the slave rebooting (which i think the mostly the reason). however, the chip has already sent the boot up event after starting up, and capabilities are received at host, fine each time (in bootup event). Please confirm @nguyenlkdn on this.

Can you please re-test on latest master @nguyenlkdn ?

[nguyenlkdn]

Yes, i think SPI have no problem. Host and ESP slave work fine on every bootup time.

I am using this "70de43ac9cc30ef55960d8025274df7a0fe1dfc8" on master branch. it is latest.

[nguyenlkdn]

I have a question: https://github.com/espressif/esp-hosted/blob/master/esp_hosted_ng/host/esp_cfg80211.c#L1217

We always need to ESP_MARK_SCAN_DONE and ESP_CANCEL_SCHED_SCAN although "scan_in_progress" and "waiting_for_scan_done" is 0?

[mantriyogesh]

@kapilkedawat , please take a look

[kapilkedawat]

Hi @nguyenlkdn could you share the kernel version.. we will try to check on the same version.

[nguyenlkdn]

@kapilkedawat `[ 0.000000] Linux version 5.10.9+ga751ca3b96f5 (oe-user@oe-host) (aarch64-poky-linux-gcc (GCC) 10.2.0, GNU ld (GNU Binutils) 2.35.1)

[kapilkedawat]

@nguyenlkdn we are checking this and will provide a fix.

[kapilkedawat]

fixed in https://github.com/espressif/esp-hosted/commit/7a70cc36585531f628c794ba67579ae380ae9d6b